Deadlock in ProvisioningAgent

[basilevs]

To reproduce shutdown Eclipse Platform before background startup completes. The error is intermittent.
Discovered by a test, that restarts the application immediately after workbench startup. Failed RCPTT build.

console.txt

!ENTRY org.eclipse.osgi 2 0 2025-08-29 22:25:33.380
!MESSAGE While loading class "org.eclipse.equinox.internal.p2.ui.ValidationDialogServiceUI", thread "Thread[#41,Worker-2: Deferred Early Start,5,main]" timed out waiting (30063ms) for thread "Thread[#67,Framework stop - Equinox Container: cf03d63d-e8f0-4178-8c00-4a17b155f4c7,6,main]" to finish starting bundle "org.eclipse.equinox.p2.ui_2.8.300.v20240207-1113 [241]". To avoid deadlock, thread "Thread[#41,Worker-2: Deferred Early Start,5,main]" is proceeding but "org.eclipse.equinox.internal.p2.ui.ValidationDialogServiceUI" may not be fully initialized.
!STACK 0
org.osgi.framework.BundleException: Unable to acquire the state change lock for the module: osgi.identity; type="osgi.bundle"; version:Version="2.8.300.v20240207-1113"; osgi.identity="org.eclipse.equinox.p2.ui"; singleton:="true" [id=241] STARTED [STOPPED]
	at org.eclipse.osgi.container.Module.lockStateChange(Module.java:373)
	at org.eclipse.osgi.container.Module.start(Module.java:447)
	at org.eclipse.osgi.framework.util.SecureAction.start(SecureAction.java:528)
	at org.eclipse.osgi.internal.hooks.EclipseLazyStarter.postFindLocalClass(EclipseLazyStarter.java:122)
	at org.eclipse.osgi.internal.loader.classpath.ClasspathManager.findLocalClass(ClasspathManager.java:620)
	at org.eclipse.osgi.internal.loader.ModuleClassLoader.findLocalClass(ModuleClassLoader.java:348)
	at org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:414)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass0(BundleLoader.java:520)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:434)
	at org.eclipse.osgi.internal.loader.ModuleClassLoader.loadClass(ModuleClassLoader.java:174)
	at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:526)
	at org.eclipse.equinox.internal.p2.ui.ServiceUIComponent.createService(ServiceUIComponent.java:28)
	at org.eclipse.equinox.internal.p2.core.ProvisioningAgent.getService(ProvisioningAgent.java:74)
	at org.eclipse.oomph.setup.internal.core.util.SetupCoreUtil.<clinit>(SetupCoreUtil.java:159)
	at org.eclipse.oomph.setup.ui.recorder.RecorderManager.<clinit>(RecorderManager.java:121)
	at org.eclipse.oomph.setup.ui.SetupUIPlugin.performStartup(SetupUIPlugin.java:218)
	at org.eclipse.oomph.setup.ui.EarlyStartup.earlyStartup(EarlyStartup.java:23)
	at org.eclipse.oomph.internal.ui.EarlyStart.run(EarlyStart.java:119)
	at org.eclipse.oomph.internal.ui.EarlyStart$1.run(EarlyStart.java:98)
	at org.eclipse.core.internal.jobs.Worker.run(Worker.java:63)
Caused by: java.util.concurrent.TimeoutException: Timeout after waiting 30 seconds to acquire the lock.
	at org.eclipse.osgi.container.Module.lockStateChange(Module.java:368)
	... 19 more
Caused by: org.eclipse.osgi.framework.util.ThreadInfoReport: Thread dump

ThreadId: 41 ThreadName: Worker-2: Deferred Early Start ThreadState: RUNNABLE
  Blocked On: org.eclipse.osgi.internal.container.EquinoxReentrantLock@2d421b29[Locked by thread Framework stop - Equinox Container: cf03d63d-e8f0-4178-8c00-4a17b155f4c7]
  Synchronizers Locked: none
  Monitors Locked: 
    java.util.Collections$SynchronizedMap@3a6ad9cd
  Stack Trace: 
    java.management@21.0.7/sun.management.ThreadImpl.dumpThreads0(Native Method)
    java.management@21.0.7/sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:518)
    java.management@21.0.7/sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:506)
    org.eclipse.osgi.framework.util.ThreadInfoReport.getThreadDump(ThreadInfoReport.java:30)
    org.eclipse.osgi.framework.util.ThreadInfoReport.<init>(ThreadInfoReport.java:23)
    org.eclipse.osgi.container.Module.lockStateChange(Module.java:370)
    org.eclipse.osgi.container.Module.start(Module.java:447)
    org.eclipse.osgi.framework.util.SecureAction.start(SecureAction.java:528)
    org.eclipse.osgi.internal.hooks.EclipseLazyStarter.postFindLocalClass(EclipseLazyStarter.java:122)
    org.eclipse.osgi.internal.loader.classpath.ClasspathManager.findLocalClass(ClasspathManager.java:620)
    org.eclipse.osgi.internal.loader.ModuleClassLoader.findLocalClass(ModuleClassLoader.java:348)
    org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:414)
    org.eclipse.osgi.internal.loader.BundleLoader.findClass0(BundleLoader.java:520)
    org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:434)
    org.eclipse.osgi.internal.loader.ModuleClassLoader.loadClass(ModuleClassLoader.java:174)
    java.base@21.0.7/java.lang.ClassLoader.loadClass(ClassLoader.java:526)
    org.eclipse.equinox.internal.p2.ui.ServiceUIComponent.createService(ServiceUIComponent.java:28)
    org.eclipse.equinox.internal.p2.core.ProvisioningAgent.getService(ProvisioningAgent.java:74)
    org.eclipse.oomph.setup.internal.core.util.SetupCoreUtil.<clinit>(SetupCoreUtil.java:159)
    org.eclipse.oomph.setup.ui.recorder.RecorderManager.<clinit>(RecorderManager.java:121)
    org.eclipse.oomph.setup.ui.SetupUIPlugin.performStartup(SetupUIPlugin.java:218)
    org.eclipse.oomph.setup.ui.EarlyStartup.earlyStartup(EarlyStartup.java:23)
    org.eclipse.oomph.internal.ui.EarlyStart.run(EarlyStart.java:119)
    org.eclipse.oomph.internal.ui.EarlyStart$1.run(EarlyStart.java:98)
    org.eclipse.core.internal.jobs.Worker.run(Worker.java:63)

ThreadId: 67 ThreadName: Framework stop - Equinox Container: cf03d63d-e8f0-4178-8c00-4a17b155f4c7 ThreadState: BLOCKED
  Blocked On: java.util.Collections$SynchronizedMap@3a6ad9cd LockOwnerId: 41 LockOwnerName: Worker-2: Deferred Early Start
  Synchronizers Locked: 
    java.util.concurrent.locks.ReentrantLock$NonfairSync@1091f5bf
    java.util.concurrent.locks.ReentrantLock$NonfairSync@48d78960
    java.util.concurrent.locks.ReentrantLock$NonfairSync@45a3780e
  Monitors Locked: 
    java.lang.Object@33f8177
  Stack Trace: 
    java.base@21.0.7/java.util.Collections$SynchronizedMap.get(Collections.java:2892)
    org.eclipse.equinox.internal.p2.core.ProvisioningAgent.removedService(ProvisioningAgent.java:177)
    org.osgi.util.tracker.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:973)
    org.osgi.util.tracker.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:1)
    org.osgi.util.tracker.AbstractTracked.untrack(AbstractTracked.java:342)
    org.osgi.util.tracker.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:915)
    org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:133)
    org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:985)
    org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)
    org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:151)
    org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:956)
    org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:890)
    org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.unregister(ServiceRegistrationImpl.java:245)
    org.apache.felix.scr.impl.manager.AbstractComponentManager$3.unregister(AbstractComponentManager.java:952)
    org.apache.felix.scr.impl.manager.AbstractComponentManager$3.unregister(AbstractComponentManager.java:915)
    org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:140)
    org.apache.felix.scr.impl.manager.AbstractComponentManager.unregisterService(AbstractComponentManager.java:994)
    org.apache.felix.scr.impl.manager.AbstractComponentManager.doDeactivate(AbstractComponentManager.java:844)
    org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:825)
    org.apache.felix.scr.impl.manager.AbstractComponentManager.dispose(AbstractComponentManager.java:589)
    org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.disposeComponents(ConfigurableComponentHolder.java:722)
    org.apache.felix.scr.impl.BundleComponentActivator.dispose(BundleComponentActivator.java:492)
    org.apache.felix.scr.impl.Activator.disposeComponents(Activator.java:672)
    org.apache.felix.scr.impl.Activator.access$300(Activator.java:75)
    org.apache.felix.scr.impl.Activator$ScrExtension.destroy(Activator.java:510)
    org.apache.felix.scr.impl.AbstractExtender$1.run(AbstractExtender.java:216)
    java.base@21.0.7/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
    java.base@21.0.7/java.util.concurrent.FutureTask.run(FutureTask.java:317)
    org.apache.felix.scr.impl.AbstractExtender.destroyExtension(AbstractExtender.java:238)
    org.apache.felix.scr.impl.AbstractExtender.bundleChanged(AbstractExtender.java:132)
    org.apache.felix.scr.impl.Activator.bundleChanged(Activator.java:256)
    org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:972)
    org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)
    org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:151)
    org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:235)
    org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:134)
    org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:126)
    org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:229)
    org.eclipse.osgi.container.Module.publishEvent(Module.java:531)
    org.eclipse.osgi.container.Module.doStop(Module.java:693)
    org.eclipse.osgi.container.Module.stop(Module.java:554)
    org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.decStartLevel(ModuleContainer.java:2115)
    org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1985)
    org.eclipse.osgi.container.SystemModule.stopWorker(SystemModule.java:281)
    org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule.stopWorker(EquinoxBundle.java:222)
    org.eclipse.osgi.container.Module.doStop(Module.java:695)
    org.eclipse.osgi.container.Module.stop(Module.java:554)
    org.eclipse.osgi.container.SystemModule.stop(SystemModule.java:212)
    org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle$EquinoxSystemModule$1.run(EquinoxBundle.java:240)
    java.base@21.0.7/java.lang.Thread.runWith(Thread.java:1596)
    java.base@21.0.7/java.lang.Thread.run(Thread.java:1583)

[merks]

Probably you don't want to run tests with Oomph installed such that jobs that are intended to run in a user's IDE but not in tests are started. Probably this problem is not reproducible without the jobs that Oomph starts, so this is not likely something that Platform will try to fix.

Why do you run tests with Oomph installed? I would avoid that completely.

Is the problem reproducible if you specify -Dheadless.startup=true for the test launch?

[basilevs]

Probably you don't want to run tests with Oomph installed such that jobs that are intended to run in a user's IDE but not in tests are started. Probably this problem is not reproducible without the jobs that Oomph starts, so this is not likely something that Platform will try to fix.

Why do you run tests with Oomph installed? I would avoid that completely.

Is the problem reproducible if you specify -Dheadless.startup=true for the test launch?

RCPTT system-tests pre-built UI applications. Those most of the time include UI and Oomph and have to run UI.

An attempt to kill Oomph somehow would make tests unfair.

Anyway, the problem is (probably) end user-observable, so discussion about "how to test something" is less relevant.

[merks]

Users don't tend to terminate their IDE within 5 second of starting it. And, unfortunately,unless you intend to work on the problem probably no one will work on the problem. ☹️ So that leaves you with a build/test problem for which I'm trying to help you find a quick fix...

Have you tried -Dheadless.startup=true? That will nip things in the bud at the org.eclipse.oomph.setup.ui.SetupUIPlugin.performStartup() call. I expect you don't need preference synchronization or any other Oomph setup activities during startup while testing.

There's also -Dorg.eclipse.oomph.ui.deferredEarlyStart=false that will do the early start activities immediately instead of deferring them for 5000 ms or there is `-Dorg.eclipse.oomph.ui.deferredEarlyStart.schedule=..." to control how long it's deferred.

[basilevs]

So that leaves you with a build/test problem for which I'm trying to help you find a quick fix...

The quick fix for this particular test would be disabling Oomph somehow. This will not fix tests for RCPTT users if those restart the application though.

-Dheadless.startup=true would prevent workbench startup and RCPTT injected runtime startup. This makes the test meaningless.

I assume -Dorg.eclipse.oomph.ui.deferredEarlyStart will shift timings elsewhere, which would not necessarily make the bug more stable. Is there an option to kill Oomph completely?

What is the maximum value for -Dorg.eclipse.oomph.ui.deferredEarlyStart.schedule=?

[basilevs]

Users don't tend to terminate their IDE within 5 second of starting it

Stacktraces imply that the situation is not exclusive to shutdown - other scenarios of concurrent access to SynchronizedMap could also lead to deadlock.

The bug is well localized to ProvisioningAgent class, and it should not hold the lock while calling external code, independently of clients.

[merks]

Again, one might see all kinds of potential problems, and I'm not suggesting these are not valid problem. But it's relevant to point out that I do not have spare cycles for such problems and I suspect that probably you don't either, so that's why I think it's maybe best we focus on getting you unstuck. After all, the Platform is shutdown for 4.37. That's your personal choice though.

You seem to believe that headless.startup is some general thing. It's a property used only by Oomph and only here

https://github.com/eclipse-oomph/oomph/blob/feb53bf7dbcf5abab3ee8d3610b7aff3264f7810/plugins/org.eclipse.oomph.setup.ui/src/org/eclipse/oomph/setup/ui/SetupUIPlugin.java#L222-L224

which is exactly this part of your call stack:

	at org.eclipse.oomph.setup.ui.recorder.RecorderManager.<clinit>(RecorderManager.java:121)
	at org.eclipse.oomph.setup.ui.SetupUIPlugin.performStartup(SetupUIPlugin.java:218)

(Probably it's poorly named, but I don't think it makes your tests meaningless.)

The value of org.eclipse.oomph.ui.deferredEarlyStart.schedule is passed to Job.schedule(...) so yes, it will shift the problem by this amount. If you make it very long, then you will be shutting down while there is a scheduled job waiting to start.

[basilevs]

It's a property used only by Oomph and only here

I see, thanks, I'll try the option.

Probably it's poorly named, but I don't think it makes your tests meaningless.

Not these particular tests, no.

If you make it very long, then you will be shutting down while there is a scheduled job waiting to start.

Yes, this would (probably) produce an unpleasant warning in the application log, thanks for the reminder.

[merks]

Good luck. 🤞 Please share the results when you have them. 🙏