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.

[ppkarwasz]

log4j-core, log4j-to-slf4j and log4j-to-jul are Log4j API providers.

There is a simple provider embedded in log4j-api, but typically that is not what you want to use. Since Logger implementations are usually static fields, the API waits for the "definitive" provider to come online, before it returns a Logger.

[hd42]

I debugged a working installation and was surprised to see that it didn't ever call Activator#start. The first call was to ProviderUtil#lazyInit(), which unlocks even with empty PROVIDERS.

So now I need to figure out, why some installations call the Activator and others don't. Both have no provider installed, so maybe I'll try installing one to not have to worry about Log4J waiting forever.

[hd42]

Adding log4j-to-slf4j has fixed my problem as far as I can see. Thank you for your help.

An indefinite wait still seems problematic to me, so maybe you should throw an "No Providers Configured" exception after a timeout.