[bndtools] JDT Startup deadlock

[kriegfrj]

I'm not sure if this deadlock occurred because of the changes I am in the process of making, or else if the potential for it already existed but I've only just now been unfortunate enough to find it. I suspect possibly the latter. I thought I would record the details just in case as these sorts of timing issues can be hard to track down if you're not fortunate enough to catch it in the debugger as I have.

In summary:

• Initializing Java tooling has tried to initialize a Bnd classpath container, which in turn causes it to acquire the Workspace read lock, and within that lock to call Central.getWorkspace(). getWorkspace() is waiting for the monitor on the static field Central.workspace (the Memoizing supplier that returns the Workspace object).
• The Bnd tester thread is in the process of cleaning the workspace and importing it afresh in preparation for the test run. This has also triggered a call to initialize a Bnd classpath container for one of the Java projects, which has also called Central.getWorkspace(). This thread managed to get into the synchronized block holding the monitor on Central.workspace (and hence is blocking the thread above); however now it is trying to acquire a write lock on the Workspace object itself (which is blocked by the read lock also held by the thread above).

Detailed stack dumps of these two are appended below.

I think that this deadlock could be fixed by moving the write lock acquisition out of the synchronized block. PR to come.

Thread [Worker-6: Initializing Java Tooling] (Suspended)	
	waiting for: MemoizingSupplier<T>  (id=295)	
	Central.getWorkspace() line: 205	
	Central.lambda$14(File) line: 460	
	210593043.get() line: not available	
	Optional<T>.orElseGet(Supplier<? extends T>) line: 267	
	Central.toPath(File) line: 458	
	BndContainerInitializer$Updater.fileToPath(File) line: 912	
	BndContainerInitializer$Updater.lambda$2(String, boolean, LinkedHashMap, Container, BndContainerInitializer$JarInfo) line: 499	
	1485163201.accept(Object, Object) line: not available	
	LinkedHashMap<K,V>.forEach(BiConsumer<? super K,? super V>) line: 684	
	BndContainerInitializer$Updater.convertContainersToCPEs(String, LinkedHashMap<Container,JarInfo>, boolean) line: 474	
	BndContainerInitializer$Updater.calculateContainersClasspath(String, Collection<Container>) line: 558	
	BndContainerInitializer$Updater.calculateProjectClasspath(Project) line: 399	
	BndContainerInitializer$Updater.lambda$0() line: 319	
	1077632036.call() line: not available	
	WorkspaceLock.locked(Lock, long, Callable<T>, BooleanSupplier) line: 128	
	Workspace.readLocked(Callable<T>) line: 1494	
	BndContainerInitializer$Updater.updateClasspathContainer(boolean) line: 319	
	BndContainerInitializer.initialize(IPath, IJavaProject) line: 115	
	ClasspathContainerInitializerFacade.initialize(IPath, IJavaProject) line: 149	
	JavaModelManager.initializeContainer(IJavaProject, IPath) line: 3195	
	JavaModelManager$10.run(IProgressMonitor) line: 3079	
	Workspace.run(ICoreRunnable, ISchedulingRule, int, IProgressMonitor) line: 2292	
	Workspace.run(IWorkspaceRunnable, ISchedulingRule, int, IProgressMonitor) line: 2317	
	JavaModelManager.initializeAllContainers(IJavaProject, IPath) line: 3141	
	JavaModelManager.getClasspathContainer(IPath, IJavaProject) line: 2111	
	JavaCore.initializeAfterLoad(IProgressMonitor) line: 4541	
	InitializeAfterLoadJob$RealJob.run(IProgressMonitor) line: 39	
	Worker.run() line: 63	

Daemon Thread [bnd Runtime Test Bundle] (Suspended)	
	owns: MemoizingSupplier<T>  (id=295)	
	Unsafe.park(boolean, long) line: not available [native method]	
	LockSupport.parkNanos(Object, long) line: 215	
	ReentrantReadWriteLock$FairSync(AbstractQueuedSynchronizer).doAcquireNanos(int, long) line: 934	
	ReentrantReadWriteLock$FairSync(AbstractQueuedSynchronizer).tryAcquireNanos(int, long) line: 1247	
	ReentrantReadWriteLock$WriteLock.tryLock(long, TimeUnit) line: 1115	
	WorkspaceLock.locked(Lock, long, Callable<T>, BooleanSupplier) line: 121	
	Workspace.writeLocked(Callable<T>) line: 1525	
	Central.getWorkspace() line: 234	
	Central.getProject(File) line: 629	
	994928186.apply(Object) line: not available	
	994928186(FunctionWithException<T,R>).lambda$0(Object) line: 21	
	1887421935.apply(Object) line: not available	
	Optional<T>.map(Function<? super T,? extends U>) line: 215	
	Central.getProject(IProject) line: 635	
	BndContainerInitializer$Updater.<init>(IProject, IJavaProject) line: 299	
	BndContainerInitializer.initialize(IPath, IJavaProject) line: 114	
	ClasspathContainerInitializerFacade.initialize(IPath, IJavaProject) line: 149	
	JavaModelManager.initializeContainer(IJavaProject, IPath) line: 3195	
	JavaModelManager$10.run(IProgressMonitor) line: 3079	
	JavaModelManager.initializeAllContainers(IJavaProject, IPath) line: 3139	
	JavaModelManager.getClasspathContainer(IPath, IJavaProject) line: 2111	
	JavaCore.getClasspathContainer(IPath, IJavaProject) line: 3752	
	JavaProject.resolveClasspath(IClasspathEntry[], IClasspathEntry[], boolean, boolean) line: 3196	
	JavaProject.resolveClasspath(JavaModelManager$PerProjectInfo, boolean, boolean) line: 3360	
	JavaProject.getResolvedClasspath() line: 2444	
	DeltaProcessor.deleting(IProject) line: 1155	
	DeltaProcessor.resourceChanged(IResourceChangeEvent) line: 2072	
	DeltaProcessingState.resourceChanged(IResourceChangeEvent) line: 477	
	NotificationManager$1.run() line: 305	
	SafeRunner.run(ISafeRunnable) line: 45	
	NotificationManager.notify(ResourceChangeListenerList$ListenerEntry[], ResourceChangeEvent, boolean) line: 295	
	NotificationManager.handleEvent(LifecycleEvent) line: 271	
	Workspace.broadcastEvent(LifecycleEvent) line: 375	
	Project(Resource).broadcastPreDeleteEvent() line: 1846	
	Project(Resource).delete(int, IProgressMonitor) line: 742	
	Project.delete(boolean, boolean, IProgressMonitor) line: 320	
	WorkspaceImporter.lambda$2(IWorkspaceRoot, Stream, IProgressMonitor) line: 68	
	504478447.run(IProgressMonitor) line: not available	
	Workspace.run(ICoreRunnable, ISchedulingRule, int, IProgressMonitor) line: 2292	
	Workspace.run(IWorkspaceRunnable, IProgressMonitor) line: 2312	
	WorkspaceImporter.importAllProjects(Stream<Path>) line: 63	
	WorkbenchExtension.beforeAll(ExtensionContext) line: 85	
	ClassBasedTestDescriptor.lambda$invokeBeforeAllCallbacks$10(BeforeAllCallback, ExtensionContext) line: 381	
	1993111149.execute() line: not available	
	OpenTest4JAndJUnit4AwareThrowableCollector(ThrowableCollector).execute(ThrowableCollector$Executable) line: 73	
	ClassTestDescriptor(ClassBasedTestDescriptor).invokeBeforeAllCallbacks(JupiterEngineExecutionContext) line: 381	
	ClassTestDescriptor(ClassBasedTestDescriptor).before(JupiterEngineExecutionContext) line: 205	
	ClassTestDescriptor(ClassBasedTestDescriptor).before(EngineExecutionContext) line: 80	
	NodeTestTask<C>.lambda$executeRecursively$6() line: 148	
	1907028442.execute() line: not available	
	OpenTest4JAndJUnit4AwareThrowableCollector(ThrowableCollector).execute(ThrowableCollector$Executable) line: 73	
	NodeTestTask<C>.lambda$executeRecursively$8(EngineExecutionContext) line: 141	
	99993216.invoke(EngineExecutionContext) line: not available	
	ClassTestDescriptor(Node<C>).around(C, Invocation<C>) line: 137	
	NodeTestTask<C>.lambda$executeRecursively$9() line: 139	
	624986455.execute() line: not available	
	OpenTest4JAndJUnit4AwareThrowableCollector(ThrowableCollector).execute(ThrowableCollector$Executable) line: 73	
	NodeTestTask<C>.executeRecursively() line: 138	
	NodeTestTask<C>.execute() line: 95	
	1667666710.accept(Object) line: not available	
	ArrayList<E>.forEach(Consumer<? super E>) line: 1259	
	SameThreadHierarchicalTestExecutorService.invokeAll(List<TestTask>) line: 41	
	NodeTestTask<C>.lambda$executeRecursively$6() line: 155	
	1907028442.execute() line: not available	
	OpenTest4JAndJUnit4AwareThrowableCollector(ThrowableCollector).execute(ThrowableCollector$Executable) line: 73	
	NodeTestTask<C>.lambda$executeRecursively$8(EngineExecutionContext) line: 141	
	99993216.invoke(EngineExecutionContext) line: not available	
	JupiterEngineDescriptor(Node<C>).around(C, Invocation<C>) line: 137	
	NodeTestTask<C>.lambda$executeRecursively$9() line: 139	
	624986455.execute() line: not available	
	OpenTest4JAndJUnit4AwareThrowableCollector(ThrowableCollector).execute(ThrowableCollector$Executable) line: 73	
	NodeTestTask<C>.executeRecursively() line: 138	
	NodeTestTask<C>.execute() line: 95	
	SameThreadHierarchicalTestExecutorService.submit(TestTask) line: 35	
	HierarchicalTestExecutor<C>.execute() line: 57	
	JupiterTestEngine(HierarchicalTestEngine<C>).execute(ExecutionRequest) line: 54	
	BundleDescriptor.executeChild(TestDescriptor, EngineExecutionListener, ConfigurationParameters) line: 49	
	BundleEngine.lambda$14(BundleDescriptor, EngineExecutionListener, ConfigurationParameters, TestDescriptor) line: 120	
	759579721.accept(Object) line: not available	
	ForEachOps$ForEachOp$OfRef<T>.accept(T) line: 183	
	ReferencePipeline$2$1.accept(P_OUT) line: 175	
	LinkedHashMap$LinkedKeyIterator(Iterator<E>).forEachRemaining(Consumer<? super E>) line: 116	
	Spliterators$IteratorSpliterator<T>.forEachRemaining(Consumer<? super T>) line: 1801	
	ReferencePipeline$2(AbstractPipeline<E_IN,E_OUT,S>).copyInto(Sink<P_IN>, Spliterator<P_IN>) line: 482	
	ReferencePipeline$2(AbstractPipeline<E_IN,E_OUT,S>).wrapAndCopyInto(S, Spliterator<P_IN>) line: 472	
	ForEachOps$ForEachOp$OfRef<T>(ForEachOps$ForEachOp<T>).evaluateSequential(PipelineHelper<T>, Spliterator<S>) line: 150	
	ForEachOps$ForEachOp$OfRef<T>.evaluateSequential(PipelineHelper, Spliterator) line: 173	
	ReferencePipeline$2(AbstractPipeline<E_IN,E_OUT,S>).evaluate(TerminalOp<E_OUT,R>) line: 234	
	ReferencePipeline$2(ReferencePipeline<P_IN,P_OUT>).forEach(Consumer<? super P_OUT>) line: 485	
	BundleEngine.executeBundle(BundleDescriptor, EngineExecutionListener, ConfigurationParameters) line: 120	
	BundleEngine.lambda$12(EngineExecutionListener, ConfigurationParameters, BundleDescriptor) line: 100	
	1906938108.accept(Object) line: not available	
	ForEachOps$ForEachOp$OfRef<T>.accept(T) line: 183	
	ReferencePipeline$3$1.accept(P_OUT) line: 193	
	ReferencePipeline$2$1.accept(P_OUT) line: 175	
	LinkedHashMap$LinkedKeyIterator(Iterator<E>).forEachRemaining(Consumer<? super E>) line: 116	
	Spliterators$IteratorSpliterator<T>.forEachRemaining(Consumer<? super T>) line: 1801	
	ReferencePipeline$3(AbstractPipeline<E_IN,E_OUT,S>).copyInto(Sink<P_IN>, Spliterator<P_IN>) line: 482	
	ReferencePipeline$3(AbstractPipeline<E_IN,E_OUT,S>).wrapAndCopyInto(S, Spliterator<P_IN>) line: 472	
	ForEachOps$ForEachOp$OfRef<T>(ForEachOps$ForEachOp<T>).evaluateSequential(PipelineHelper<T>, Spliterator<S>) line: 150	
	ForEachOps$ForEachOp$OfRef<T>.evaluateSequential(PipelineHelper, Spliterator) line: 173	
	ReferencePipeline$3(AbstractPipeline<E_IN,E_OUT,S>).evaluate(TerminalOp<E_OUT,R>) line: 234	
	ReferencePipeline$3(ReferencePipeline<P_IN,P_OUT>).forEach(Consumer<? super P_OUT>) line: 485	
	BundleEngine.execute(ExecutionRequest) line: 100	
	EngineExecutionOrchestrator.execute(TestDescriptor, EngineExecutionListener, ConfigurationParameters, TestEngine) line: 107	
	EngineExecutionOrchestrator.execute(LauncherDiscoveryResult, EngineExecutionListener) line: 88	
	EngineExecutionOrchestrator.lambda$execute$0(InternalTestPlan, LauncherDiscoveryResult, TestExecutionListener) line: 54	
	967990403.accept(Object) line: not available	
	EngineExecutionOrchestrator.withInterceptedStreams(ConfigurationParameters, ListenerRegistry<TestExecutionListener>, Consumer<TestExecutionListener>) line: 67	
	EngineExecutionOrchestrator.execute(InternalTestPlan, TestExecutionListener...) line: 52	
	DefaultLauncher.execute(InternalTestPlan, TestExecutionListener[]) line: 114	
	DefaultLauncher.execute(LauncherDiscoveryRequest, TestExecutionListener...) line: 86	
	DefaultLauncherSession$DelegatingLauncher.execute(LauncherDiscoveryRequest, TestExecutionListener...) line: 86	
	SessionPerRequestLauncher.execute(LauncherDiscoveryRequest, TestExecutionListener...) line: 53	
	Activator.test(LauncherDiscoveryRequest) line: 439	
	Activator.automatic() line: 344	
	Activator.run() line: 216	
	Thread.run() line: 748	

[kriegfrj]

I think that this deadlock could be fixed by moving the write lock acquisition out of the synchronized block. PR to come.

This did not seem to work. I ended up with a thread trying to re-entrantly acquire the write lock (when it already held a read lock), which caused it to block.

Given that this seems to happen rarely, I'm going to park it for now.

[bjhargrave]

This appears to be my fault with locking changes I made for 6.2. I will look into a fix.

[bjhargrave]

This issue can only occur when the Eclipse workspace transition from having a cnf project and not having one (stand alone workspace). This is rare in normal usage of Bndtools but I can see that is triggerable in the testing scenarios.

[kriegfrj]

Yes it can happen transition from cnf to standalone, or from standalone to cnf. This happens anytime that you create or delete a cnf project. Agreed, this is rare in normal Bndtools usage - and even in my tests (which delete and re-import cnf every time the test runs) it is uncommon (I've only hit it that one time so far).

Moving to a pure DS interface for Workspace might solve this issue (instead of allowing anyone to call getWorkspace() at any time).

[maho7791]

I experienced such freezes after creating a bnd workspace from a template in a new Eclipse installation with bnd 5. This would be a usecase for any new User who tries bndtools.

[kriegfrj]

I'm not sure if this particular deadlock would have been around in 5.0... the locking that's causing it was introduced more recently. But yes, setting up a new workspace would be the occasion that could trigger it.

[bjhargrave]

I'm not sure if this particular deadlock would have been around in 5.0

This deadlock is new (I introduced it in 6.2).

Moving to a pure DS interface for Workspace might solve this issue (instead of allowing anyone to call getWorkspace() at any time).

I don't think this is the case since we need to check for the workspace changing shape in the disk and adjusting the Workspace object. So will need need a choke point to do this.