Exception saving preferences in p2 tasks about equinox HOT 23 CLOSED

@HannesWell can you take a look?

It is not obvious why it is complaining about the destination file preferenceFile not existing when the code just checked that it existed before the move call:

			if (Files.exists(preferenceFile)) {
				// Write new file content to a temporary file first to not loose the old content
				// in case of a failure. If everything goes OK, it is moved to the right place.
				Path tmp = preferenceFile.resolveSibling(preferenceFile.getFileName() + BACKUP_FILE_EXTENSION);
				Files.writeString(tmp, fileContent, StandardCharsets.UTF_8);
				Files.move(tmp, preferenceFile, StandardCopyOption.REPLACE_EXISTING);
			} else {
				Files.writeString(preferenceFile, fileContent, StandardCharsets.UTF_8);
			}

from equinox.

@iloveeclipse can you confirm reverting eclipse-equinox/equinox.bundles#8 fixes the issue for you? When this error happens does it also result in a failed state for the p2 task you were running?

@vogella @akurtakov If reverting eclipse-equinox/equinox.bundles#8 fixes the issue I suggest we consider reverting for RC2.

from equinox.

The error is really weird. It complains about the target file not existing, but it's not required to exist is it? The tmp file would have suffix .bak and that's not what it's complaining about. Perhaps some other thread is deleting the whole profile directory in parallel?

from equinox.

It is not obvious why it is complaining about the destination file preferenceFile not existing when the code just checked that it existed before the move call:

Even though between the check and the move the file could have been deleted I'm more surprised something else according to the javadoc:

1. Move is supposed to fail if the file exits if not StandardCopyOption.REPLACE_EXISTING is given (what is the case here), so from the API do not see any indicateion it should ever fail if the file is not there
2. It is none of the "standard" exceptions the method declares for certain error conditions but a generic I/O error so maybe a os specific error condition (network share?).

from equinox.

The error is really weird. It complains about the target file not existing, but it's not required to exist is it? The tmp file would have suffix .bak and that's not what it's complaining about. Perhaps some other thread is deleting the whole profile directory in parallel?

Right, it is confusing. I think it could complain if the parent directory of the destination does not exist. But the code also does a makeDirs on the parent file also. It would seem some parallel file operations could cause this. But that would be highly timing related. Was this a reproducible error?

from equinox.

The error is really weird. It complains about the target file not existing, but it's not required to exist is it? The tmp file would have suffix .bak and that's not what it's complaining about. Perhaps some other thread is deleting the whole profile directory in parallel?

That's the only possible case I can think of how this can happen.
Unless it is another reason, I don't think that the old code would guard against those cases.
But in general it would be hard to guard against such errors due to concurrent file-system operations since most of them are not atomic and AFAIK one can only lock on files and not directories.

from equinox.

@tjwatson : we see the error only on the branches that use 4.24 as target. 4.21 works fine.
The error is reproducible.
The file/directory tree in question (starting with p2 folder) does not exist before execution and exists after p2 task execution. May be the problem is partly due the fact that we create custom Eclipse product "on the fly" using that partly created Eclipse instance as a tool, so it doesn't have p2 folder before execution. Once p2 task is done, we don't see similar errors during product tests (but we are also don't do anything p2 related in tests). Deleting <eclipse_install_root/p2> directory and triggering p2 task produces the error again.
The task itself looks like:

eclipse -nosplash -consoleLog --launcher.suppressErrors -application org.eclipse.equinox.p2.director -vm /usr/lib/jvm/java-11/bin/java -repository file:////some/random/repo -uninstallIU org.eclipse.e4.core.tools.feature.feature.group,org.eclipse.e4.core.tools.feature.source.feature.group -destination /some/directory/eclipseRE -profile SDKProfile -tag ALL

from equinox.

At laest the old code has some of if (!sourceFile.exists()) do nothing, so don't know if the error was just hidden and/or intentionally ignored.

Also there is Bug 468787 that explicitly mentioning the behavior we see here. So from what this code claims to "not loose the old content in case of a failure", maybe one should simply catch any I/O error here and move on?

from equinox.

By the way the error itself might be misleading at least when I take a look at UnixCopyFile.move(UnixCopyFile.java:468) from my JDK11 the NoSuchFileException is thrown because of the errno() value but the mentioned file in the error is always the source but the unlink of the target file fails. Not sure if this is a JDK bug.

Looking at the code, if not the AtomicFlag is used, it is highly affected by concurrent actions, so maybe here we need some kind of write sync based on the preference to get this right.

from equinox.

In my opinion we should revert eclipse-equinox/equinox.bundles#8. But it is still not clear if it would solve the issue.

@tjwatson : we see the error only on the branches that use 4.24 as target. 4.21 works fine.

Thanks, but not sure that confirms that reverting eclipse-equinox/equinox.bundles#8 would fix the issue in 4.24.

from equinox.

@tjwatson you can simply add a try {} catch{IOException) that would have the same effect... maybe @iloveeclipse can verify that this fixes the issue?

from equinox.

@tjwatson you can simply add a try {} catch{IOException) that would have the same effect... maybe @iloveeclipse can verify that this fixes the issue?

At this stage (in RC2 week), my opinion is that we only have time to revert back to a known working state. Then if others want to revisit fixing the existing NIO code then that can happen in a follow on release.

from equinox.

@tjwatson you can simply add a try {} catch{IOException) that would have the same effect... maybe @iloveeclipse can verify that this fixes the issue?

At this stage (in RC2 week), my opinion is that we only have time to revert back to a known working state. Then if others want to revisit fixing the existing NIO code then that can happen in a follow on release.

I agree that we should be really careful the moment. On the other hand the change suggested by @laeubi seems really save to me since the worst thing that can happen is that the Exception is swallowed (what is actually intended).

If you want to revert eclipse-equinox/equinox.bundles#8, you likely also have to revert eclipse-equinox/equinox.bundles#13 since it is a follow up.

But I'm not convinced that reverting eclipse-equinox/equinox.bundles#8 will solve the issue since Files.move() was called before as well.
It it is really the case that the bak-file was written and before the move starts or even during the move the entire directory is deleted (including the source and maybe the partially moved target file), the only way I see that the previous code prevents the propagation of the IOException is the try-catch block around Files.move(). So Christoph's suggestion would be equivalent.
However the logic within the catch-block makes me doubt, if it really prevents an IOException because it only returns without reattempting a full copy if only the source was deleted and not the target.

@iloveeclipse could you check if the file mentioned in the exception exists after the execution respectively the containing directory as well as the corresponding .bak file?

from equinox.

I don't think the folder is really removed, this could also happen if two concurrent tasks update the same preferences.

from equinox.

Here again slightly different log

!ENTRY org.eclipse.equinox.preferences 4 4 2022-06-01 18:27:22.489
!MESSAGE Exception saving preferences to: /workspaces/socbm599/aloskuto/ws-e4x/opt/93000/src/segments/eclipse/eclipseRE/p2/org.eclipse.equinox.p2.engine/profileRegistry/SDKProfile.profile/.data/.settings/org.eclipse.equinox.p2.metadata.repository.prefs.
!STACK 0
java.nio.file.NoSuchFileException: /workspaces/socbm599/aloskuto/ws-e4x/opt/93000/src/segments/eclipse/eclipseRE/p2/org.eclipse.equinox.p2.engine/profileRegistry/SDKProfile.profile/.data/.settings/org.eclipse.equinox.p2.metadata.repository.prefs.bak -> /workspaces/socbm599/aloskuto/ws-e4x/opt/93000/src/segments/eclipse/eclipseRE/p2/org.eclipse.equinox.p2.engine/profileRegistry/SDKProfile.profile/.data/.settings/org.eclipse.equinox.p2.metadata.repository.prefs
        at java.base/sun.nio.fs.UnixException.translateToIOException(UnixException.java:92)
        at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111)
        at java.base/sun.nio.fs.UnixCopyFile.move(UnixCopyFile.java:478)
        at java.base/sun.nio.fs.UnixFileSystemProvider.move(UnixFileSystemProvider.java:267)
        at java.base/java.nio.file.Files.move(Files.java:1422)
        at org.eclipse.core.internal.preferences.EclipsePreferences.write(EclipsePreferences.java:289)
        at org.eclipse.core.internal.preferences.EclipsePreferences.save(EclipsePreferences.java:1066)
        at org.eclipse.equinox.internal.p2.engine.ProfilePreferences.doSave(ProfilePreferences.java:141)
        at org.eclipse.equinox.internal.p2.engine.ProfilePreferences$SaveJob.run(ProfilePreferences.java:54)
        at org.eclipse.core.internal.jobs.Worker.run(Worker.java:63)

!ENTRY org.eclipse.equinox.p2.engine 2 0 2022-06-01 18:27:22.491
!MESSAGE Exception saving profile preferences
!STACK 0
org.osgi.service.prefs.BackingStoreException: Exception saving preferences to: /workspaces/socbm599/aloskuto/ws-e4x/opt/93000/src/segments/eclipse/eclipseRE/p2/org.eclipse.equinox.p2.engine/profileRegistry/SDKProfile.profile/.data/.settings/org.eclipse.equinox.p2.metadata.repository.prefs.
        at org.eclipse.core.internal.preferences.EclipsePreferences.write(EclipsePreferences.java:296)
        at org.eclipse.core.internal.preferences.EclipsePreferences.save(EclipsePreferences.java:1066)
        at org.eclipse.equinox.internal.p2.engine.ProfilePreferences.doSave(ProfilePreferences.java:141)
        at org.eclipse.equinox.internal.p2.engine.ProfilePreferences$SaveJob.run(ProfilePreferences.java:54)
        at org.eclipse.core.internal.jobs.Worker.run(Worker.java:63)
Caused by: java.nio.file.NoSuchFileException: /workspaces/socbm599/aloskuto/ws-e4x/opt/93000/src/segments/eclipse/eclipseRE/p2/org.eclipse.equinox.p2.engine/profileRegistry/SDKProfile.profile/.data/.settings/org.eclipse.equinox.p2.metadata.repository.prefs.bak -> /workspaces/socbm599/aloskuto/ws-e4x/opt/93000/src/segments/eclipse/eclipseRE/p2/org.eclipse.equinox.p2.engine/profileRegistry/SDKProfile.profile/.data/.settings/org.eclipse.equinox.p2.metadata.repository.prefs
        at java.base/sun.nio.fs.UnixException.translateToIOException(UnixException.java:92)
        at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111)
        at java.base/sun.nio.fs.UnixCopyFile.move(UnixCopyFile.java:478)
        at java.base/sun.nio.fs.UnixFileSystemProvider.move(UnixFileSystemProvider.java:267)
        at java.base/java.nio.file.Files.move(Files.java:1422)
        at org.eclipse.core.internal.preferences.EclipsePreferences.write(EclipsePreferences.java:289)
        ... 4 more

State is (after the error):

$ll /workspaces/socbm599/aloskuto/ws-e4x/opt/93000/src/segments/eclipse/eclipseRE/p2/org.eclipse.equinox.p2.engine/profileRegistry/SDKProfile.profile/.data/.settings/org.eclipse.equinox.p2.metadata.repository.prefs.bak
ls: cannot access /workspaces/socbm599/aloskuto/ws-e4x/opt/93000/src/segments/eclipse/eclipseRE/p2/org.eclipse.equinox.p2.engine/profileRegistry/SDKProfile.profile/.data/.settings/org.eclipse.equinox.p2.metadata.repository.prefs.bak: No such file or directory

$ ll /workspaces/socbm599/aloskuto/ws-e4x/opt/93000/src/segments/eclipse/eclipseRE/p2/org.eclipse.equinox.p2.engine/profileRegistry/SDKProfile.profile/.data/.settings/org.eclipse.equinox.p2.metadata.repository.prefs
-rw-rw-r-- 1 aloskuto users 7241 Jun  1 18:27 /workspaces/socbm599/aloskuto/ws-e4x/opt/93000/src/segments/eclipse/eclipseRE/p2/org.eclipse.equinox.p2.engine/profileRegistry/SDKProfile.profile/.data/.settings/org.eclipse.equinox.p2.metadata.repository.prefs

Note: I will not make it to test with patched version today, and unlikely tomorrow, because of other tasks.

from equinox.

Note: I will not make it to test with patched version today, and unlikely tomorrow, because of other tasks.

Just in case you can attach a debugger, can you create a conditional breakpoint with

preferenceFile.getFileName().equals("org.eclipse.equinox.p2.metadata.repository.prefs")

to see if there are different threads calling the method concurrently?

from equinox.

If anything is to be done here we need a PR now and a request to the PMC to approve fixing it this late in the cycle.

from equinox.

If anything is to be done here we need a PR now and a request to the PMC to approve fixing it this late in the cycle.

I'm not sure. But what I also ask myself:
Are those exception harmful in the sense that functionality is broken or are they just annoying because they are displayed?
With the current Milestone/RC I did not noticed any problems. And from the causes we suspected here I think it could be the latter. If that is the case I would just wrap the call to Files.move() into a tray-catch block to swallow the exception as soon as the master re-opens.

from equinox.

Given that I cannot tell if this is a severe issue I do not think I can justify it as needing a fix and forcing a respin of RC2a.

from equinox.

@HannesWell can you provide a PR to address this issue?

from equinox.

@HannesWell can you provide a PR to address this issue?

Thanks for the reminder, I just created PR #65.

I don't think the folder is really removed, this could also happen if two concurrent tasks update the same preferences.

I created a little test case that showed similar errors like the one from @iloveeclipse based on @laeubi's presumption (code below).

Passing StandardCopyOption.ATOMIC_MOVE just lead to slightly different error messages because it can still happen that another thread moved the file already in the meantime. An itself atomic move does not prevent that.
Therefore I think the entire file operation section in the EclipsePreferences.write() method has to be synchronized to prevent such errors.
They probably also occurred before but were just swallowed.

	public static void main(String[] args) throws IOException {
		Path dir = Files.createTempDirectory("test-dir"); //$NON-NLS-1$
		Path file1 = dir.resolve("file1"); //$NON-NLS-1$
		Path file2 = dir.resolve("file2"); //$NON-NLS-1$

		byte[] bytes = new byte[64 * 1024];
		Random r = new Random();
		r.nextBytes(bytes);
		Files.write(file1, bytes);

		Object lock = new Object();
		for (int threads = 0; threads < 2; threads++) {
			Thread thread = new Thread(() -> {
				for (int i = 0; i < 1_000; i++) {
					try {
						Files.move(file1, file2, StandardCopyOption.REPLACE_EXISTING);
						Files.move(file2, file1, StandardCopyOption.REPLACE_EXISTING);
					} catch (IOException e) {
						e.printStackTrace();
					}
				}
			});
			thread.setDaemon(false);
			thread.start();
		}
	}

from equinox.

The problem is still there.

!ENTRY org.eclipse.equinox.p2.engine 2 0 2022-07-05 07:44:30.041
!MESSAGE Exception saving profile preferences
!STACK 0
org.osgi.service.prefs.BackingStoreException: Exception saving preferences to: /truncated/eclipseRE/p2/org.eclipse.equinox.p2.engine/profileRegistry/SDKProfile.profile/.data/.settings/org.eclipse.equinox.p2.metadata.repository.prefs.
        at org.eclipse.core.internal.preferences.EclipsePreferences.write(EclipsePreferences.java:300)
        at org.eclipse.core.internal.preferences.EclipsePreferences.save(EclipsePreferences.java:1070)
        at org.eclipse.equinox.internal.p2.engine.ProfilePreferences.doSave(ProfilePreferences.java:141)
        at org.eclipse.equinox.internal.p2.engine.ProfilePreferences$SaveJob.run(ProfilePreferences.java:54)
        at org.eclipse.core.internal.jobs.Worker.run(Worker.java:63)
Caused by: java.nio.file.NoSuchFileException: /truncated/eclipseRE/p2/org.eclipse.equinox.p2.engine/profileRegistry/SDKProfile.profile/.data/.settings/org.eclipse.equinox.p2.metadata.repository.prefs
        at java.base/sun.nio.fs.UnixException.translateToIOException(UnixException.java:92)
        at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111)
        at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:116)
        at java.base/sun.nio.fs.UnixCopyFile.move(UnixCopyFile.java:468)
        at java.base/sun.nio.fs.UnixFileSystemProvider.move(UnixFileSystemProvider.java:267)
        at java.base/java.nio.file.Files.move(Files.java:1422)
        at org.eclipse.core.internal.preferences.EclipsePreferences.write(EclipsePreferences.java:292)
        ... 4 more

from equinox.

This issue has been inactive for 180 days and is therefore labeled as stale.
If this issue became irrelevant in the meantime please close it as completed. If it is still relevant and you think it should be fixed some possibilities are listed below.
Please read https://github.com/eclipse-equinox/.github/blob/main/CONTRIBUTING.md#contributing-to-eclipse-equinox for ways to influence development.

from equinox.