ProviderUtil.lazyInit hangs indefinitely

[hd42]

Description

I am using an Eclipse plugin that uses Apache POI, which in turn uses Log4j. It runs fine in most configurations, but in some constellations I haven't been able to conclusively pin down (installed the same version twice, one works, the other reproducibly blocks), the UI hangs indefinitely. I took thread dumps in multiple occasions and the main thread always is parked inside ProviderUtil.lazyInit.
What could be the cause of this?

Configuration

Version: 2.23.1

Operating system: Windows 10

JDK: different versions, including JustJ (17.0.10) and Temurin (21.0.3)

Logs

"main" #1 [1584] prio=6 os_prio=0 cpu=14515.62ms elapsed=198.83s tid=0x000001f833061830 nid=1584 waiting on condition  [0x0000002f0f6fb000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@21.0.3/Native Method)
	- parking to wait for  <0x00000000813aff10> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
	at java.util.concurrent.locks.LockSupport.park(java.base@21.0.3/LockSupport.java:221)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@21.0.3/AbstractQueuedSynchronizer.java:754)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(java.base@21.0.3/AbstractQueuedSynchronizer.java:1010)
	at java.util.concurrent.locks.ReentrantLock$Sync.lockInterruptibly(java.base@21.0.3/ReentrantLock.java:161)
	at java.util.concurrent.locks.ReentrantLock.lockInterruptibly(java.base@21.0.3/ReentrantLock.java:372)
	at org.apache.logging.log4j.util.ProviderUtil.lazyInit(ProviderUtil.java:151)
	at org.apache.logging.log4j.util.ProviderUtil.hasProviders(ProviderUtil.java:138)
	at org.apache.logging.log4j.LogManager.<clinit>(LogManager.java:89)
	at org.apache.poi.util.IOUtils.<clinit>(IOUtils.java:43)
	at org.apache.poi.poifs.filesystem.FileMagic.valueOf(FileMagic.java:209)
	at org.apache.poi.ss.usermodel.WorkbookFactory.create(WorkbookFactory.java:222)
	at org.apache.poi.ss.usermodel.WorkbookFactory.create(WorkbookFactory.java:185)

[vy]

@hd42, this sounds like a deadlock to me. That is, ProviderUtil is trying to acquire the initialization lock that is already acquired. We can improve the diagnostics by reporting if there is already an on-going initialization, but that will only point the problem, not solve it. Could you share a complete thread dump?

[hd42]

threaddump2.txt
Yes, that's what I figured. I'll try to attach a debugger and see when the initialization is called.

[ppkarwasz]

@hd42,

What kind of application are you developing? It seems you are writing an RCP or an OSGi application?
If so, what kind and version of OSGi framework you are using?

[hd42]

Yes, I am developing an Eclipse Plugin, so the OSGi framework is the one bundled with Eclipse 2024-03.

[hd42]

As far as I can see, org.apache.logging.log4j.util.Activator#unlockIfReady() is called a lot but never enters the if block because ProviderUtil.PROVIDERS remains empty.

[ppkarwasz]

This seems related to the order of activation of the OSGi bundles: the LogManager class initialization will block until the log4j-core bundle is started. Log4j does not have an OSGi-friendly mechanism to switch logging backends.

You should make sure the log4j-core starts before your Eclipse plugin, but I don't have too much familiarity with OSGi frameworks. @HannesWell, any idea?

[hd42]

I see Activator#start gets called but doesn't find any bundle that contains a provider. I don't see log4j-core installed in the plugins.
log4j seems to block itself from working without providers - I would have assumed a default implementation or an error message instead.
So I'll look into the installations that do work to see which bundle installed there includes a log4j provider and install that plugin in my Eclipse.