[buckminster-dev] No element with id ... was found in storage resolution

[Nick Veys <psylence519@xxxxxxxxx>]

Been running into this issue randomly during the course of our
Buckminster integration and now after attempting to upgrade our target
platform from 3.4.1 -> 3.4.2 it is much more frequent in occurrence.

The simple result is this exception during the build of one of our products:

[java] org.eclipse.buckminster.core.metadata.model.ElementNotFoundException:
No element with id 3999b585-5686-32c8-838b-1959be6a3254 was found in
storage resolution
[java]     at org.eclipse.buckminster.core.metadata.FileStorage.getElement(FileStorage.java:299)
[java]     at org.eclipse.buckminster.core.metadata.WorkspaceInfo.getActiveResolutions(WorkspaceInfo.java:230)
[java]     at org.eclipse.buckminster.core.metadata.WorkspaceInfo.getResolution(WorkspaceInfo.java:622)
[java]     at org.eclipse.buckminster.pde.internal.actor.FragmentsActor.isUpToDate(FragmentsActor.java:111)
[java]     at org.eclipse.buckminster.core.cspec.model.Action.isUpToDate(Action.java:274)
[java]     at org.eclipse.buckminster.core.internal.actor.PerformManager.perform(PerformManager.java:354)
[java]     at org.eclipse.buckminster.core.internal.actor.PerformManager.perform(PerformManager.java:405)
[java]     at org.eclipse.buckminster.core.commands.Perform.internalRun(Perform.java:198)
[java]     at org.eclipse.buckminster.core.commands.WorkspaceCommand.run(WorkspaceCommand.java:99)
[java]     at org.eclipse.buckminster.cmdline.AbstractCommand.basicRun(AbstractCommand.java:155)
[java]     at org.eclipse.buckminster.cmdline.Headless.run(Headless.java:295)
[java]     at org.eclipse.buckminster.cmdline.Headless.run(Headless.java:229)
[java]     at org.eclipse.buckminster.cmdline.Headless.start(Headless.java:304)
[java]     at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:193)
[java]     at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:110)
[java]     at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:79)
[java]     at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:386)
[java]     at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:179)
[java]     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[java]     at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
[java]     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
[java]     at java.lang.reflect.Method.invoke(Method.java:597)
[java]     at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:549)
[java]     at org.eclipse.equinox.launcher.Main.basicRun(Main.java:504)
[java]     at org.eclipse.equinox.launcher.Main.run(Main.java:1236)
[java]     at org.eclipse.equinox.launcher.Main.main(Main.java:1212)
[java] No element with id 3999b585-5686-32c8-838b-1959be6a3254 was
found in storage resolution

Take the line #'s loosely as I've been instrumenting debug...

This will happen with completely new workspaces or ones that worked
just previously.  I found some references to this issue in the group
but they seemed to conclude the issue was workspace metadata
corruption or cruft.  This doesn't seem to be the case.

In the course of debugging I've found that the resolution filestorage
has a few elements removed from it right before failure.  The element
requested is removed just before being checked with getCreationTime,
causing the exception.

Some debug output I instrumented:

... [SNIP, other start/end pairs] ...
[java] INFO:  [start my.pkg.jdepend:osgi.bundle$2.9.1#OSGi#bundle.jar]
[java] WARN:  resolution removed 9b7e17a4-60e5-3b80-bfb8-ede4d0ba9d48,
total: 309
[java] INFO:  [end my.pkg.jdepend:osgi.bundle$2.9.1#OSGi#bundle.jar]
[java] WARN:  resolution removed 3999b585-5686-32c8-838b-1959be6a3254,
total: 308
[java] WARN:  resolution removed e6c4099a-60f3-325b-ab08-18edc887a028,
total: 307
[java] org.eclipse.buckminster.core.metadata.model.ElementNotFoundException:
No element with id 3999b585-5686-32c8-838b-1959be6a3254 was found in
storage resolution
[java]     at org.eclipse.buckminster.core.metadata.FileStorage.getElement(FileStorage.java:299)
[java]     at org.eclipse.buckminster.core.metadata.WorkspaceInfo.getActiveResolutions(WorkspaceInfo.java:230)
... [SNIP ... exception trace] ...

So you can see 3999... was just removed, then fetched.  Stranger (to
me at least) is that the element that is causing the problem is
repeatable, and it's a completely unrelated feature, not used in the
product currently being built.  So it feels a lot like a race
condition of some kind, even more so because enabling remote debug, or
adding too much log output makes it go away or very difficult to make
happen.

However, when it *doesn't* break, it either never calls
FileStore.removeElement() on resolution, or calls it after that
element is needed.

Any ideas?  Unfortunately I haven't been able to create a small
workspace to reproduce.  Whatever I have here as my big old project
workspace seems to create the right conditions.  I'm going to continue
debugging but any guidance would be greatly appreciated.