Details
Description
Investigation
The problem is insanely complex and really hard to fully understand, which mind you, I also do not fully do yet. What I observed is the following:
Between an upgrade of log4j 2.17.0 and 2.17.1 there seems to be some locking added or some code flow changes related to locking introduced in log4j. As a result, when using PowerMock this can result in a deadlock during tests.
Reproduction
@RunWith(PowerMockRunner.class) @PowerMockIgnore({"org.apache.logging.*", "org.slf4j.*", "javax.management.*", "com.sun.org.apache.xerces.*", "javax.xml.*", "org.xml.*", "org.w3c.dom.*", "com.sun.org.apache.xalan.*", "javax.activation.*", "javax.net.ssl.*"}) @PrepareForTest({LogDummy.class}) public class DoItTests { @Before public void setup() { PowerMock.mockStatic(LogDummy.class); } @Test public void doIt() { System.out.println("YES"); } } package org.onehippo.cms.channelmanager.content; import org.slf4j.Logger; import org.slf4j.LoggerFactory; public final class LogDummy { private static final Logger log = LoggerFactory.getLogger(MockCmsSessionContext.class); private LogDummy() { } }
Running the above test, results in a deadlock. Replacing
private static final Logger log = LoggerFactory.getLogger(MockCmsSessionContext.class);
with
private final Logger log = LoggerFactory.getLogger(MockCmsSessionContext.class);
avoids the deadlock.
Explanation
From the above trivial setup, the issue seems to be caused by
@PrepareForTest({LogDummy.class})
where the 'LogDummy' class contains:
private static final Logger log = LoggerFactory.getLogger(MockCmsSessionContext.class);
Although I really don't want to know anything about PowerMock other than ammunition I can use to make sure others don't use it, there is something really quirky going on. The PrepareForTest seems with a separate thread to intercept static initialization, triggering in the end a new thread in log4j to invoked the code from ThreadContextDataInjector :
public static void initServiceProviders() { if (serviceProviders == null) { providerLock.lock(); try { if (serviceProviders == null) { serviceProviders = getServiceProviders(); } } finally { providerLock.unlock(); } } }
The problem however is that another non-powermock initiated thread (the main thread) also seems to be initializing Log4j at the same time : as a result,
getServiceProviders();
seem to hit a lock from another thread, where I think that other thread in turn is blocked by a lock initiated by a thread in PowerMock class loading ( I had this in break point, don't know the powermock class any more doing this)
Workaround
I could not (yet) find any hints via google of other people hitting this issue: it is fairly specific.
It seemed that removing
"org.apache.logging.*"
would fix it but I got the same problem after some more tests. Also removing
"org.apache.logging.*"
might have adverse effects wrt ENT-2191 . Then I attempted to use @SuppressStaticInitializationFor("LogDummy") but this results in the static log variable not being initialized at all and being null.
An alternative of removing the 'static' for the log for all classes which are used in 'PrepareForTest' is also undesirable (though would work)
A simple and effective workaround seems to be to add to every PowerMock test class the following line:
// WORKAROUND ENT-4370 : trigger log4j initialization to avoid power mock triggered deadlock in log4j private static final Logger ignore = LoggerFactory.getLogger(Object.class);
This triggers Log4j to be initialized in a different order, most likely because PowerMock is triggered now after Log4j initialization and during PowerMock classloading the 'initServiceProviders' has already non-null value for serviceProviders . Hopefully it does not re-introduce the issue fixed in ENT-2191.
I don't like the workaround but for now it seems effective. We can wait a bit and test new log4j releases whether they have the same issue and whether others are being hit by this as well which might make it easier to find a real solution later on. Note that by far my preferred solution was to abandon PowerMock for good
Attachments
Issue Links
- causes
-
CMS-14948 Remove workaround for avoiding Log4j deadlock in tests
- New