Uploaded image for project: 'Hippo CMS'
  1. Hippo CMS
  2. CMS-14946

Fix hanging Jenkins on tests

    XMLWordPrintable

Details

    • Bug
    • Status: Closed
    • Normal
    • Resolution: Fixed
    • None
    • 14.7.4, 15.0.0
    • None
    • None
    • Quasar
    • Team Quasar sprint 278

    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

          Activity

            People

              Unassigned Unassigned
              aschrijvers Ard Schrijvers
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: