Initialization deadlock on JaveEE server startup

[FelixStuebner]

Description

In our project we are using OpenLiberty as application server with JavaEE 7 feature enabled and discovered a dead lock together with log4j.

Our aim is to log every message by log4j, so we have a StartUpBean which adds a org.apache.logging.log4j.jul.Log4jBridgeHandler on
every java.util.logging.Logger of java.util.logging.LogManager.
In the startup process we encountered a situation where the application logs something via Log4J Logger and at the same time a web request was incoming which did log something via java.util.logging.Logger (Log4jBridgeHandler).
This randomly lead to the following dead lock situation:

Thread 8 is the web request, which is using the in the Log4jBridgeHandler. He is in the of the LoggerContext and waiting for LogManager (ThreadContextMapFactory.java:99)
Thread 1 is a regular application thread, that will log a status message. He is in the LogManager and waits for LoggerContext (BasicContextSelector.java:33)

Configuration

Version: 2.20.0

Operating system: Red Hat Enterprise Linux 8.8 (Ootpa)

JDK: openjdk version 1.8.0_382 IBM Semeru Runtime Open Edition (build 1.8.0_382-b05)

Logs

Thread 8:

"Default Executor-thread-8" J9VMThread:0x00000000006FA300, omrthread_t:0x00007F3F643CBE58, java/lang/Thread:0x0000000067E4DEE8, state:CW, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x3F, isDaemon:true)
3XMJAVALTHRCCL            com/ibm/ws/classloading/internal/ThreadContextClassLoader(0x000000006BBE9F78)
3XMTHREADINFO1            (native thread ID:0x61, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000181)
3XMTHREADINFO2            (native stack address range from:0x00007F3FFC763000, to:0x00007F3FFC7A3000, size:0x40000)
3XMCPUTIME               CPU usage total: 3.104548200 secs, current category="Application"
3XMTHREADBLOCK     Waiting on: java/lang/J9VMInternals$ClassInitializationLock@0x00000000FF200B30 Owned by: <unowned> Initializing thread: "Default Executor-thread-1"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=0 (0x0)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at org/apache/logging/log4j/spi/ThreadContextMapFactory.createThreadContextMap(ThreadContextMapFactory.java:99)
4XESTACKTRACE                at org/apache/logging/log4j/ThreadContext.init(ThreadContext.java:223)
4XESTACKTRACE                at org/apache/logging/log4j/ThreadContext.<clinit>(ThreadContext.java:201)
4XESTACKTRACE                at org/apache/logging/log4j/core/impl/ContextDataInjectorFactory.createDefaultInjector(ContextDataInjectorFactory.java:87)
4XESTACKTRACE                at org/apache/logging/log4j/core/impl/ContextDataInjectorFactory.createInjector(ContextDataInjectorFactory.java:71)
4XESTACKTRACE                at org/apache/logging/log4j/core/lookup/ContextMapLookup.<init>(ContextMapLookup.java:34)
4XESTACKTRACE                at sun/reflect/NativeConstructorAccessorImpl.newInstance0(Native Method)
4XESTACKTRACE                at sun/reflect/NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
4XESTACKTRACE                at sun/reflect/DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
4XESTACKTRACE                at java/lang/reflect/Constructor.newInstance(Constructor.java:423)
4XESTACKTRACE                at org/apache/logging/log4j/core/util/ReflectionUtil.instantiate(ReflectionUtil.java:189)
4XESTACKTRACE                at org/apache/logging/log4j/core/lookup/Interpolator.<init>(Interpolator.java:86)
4XESTACKTRACE                at org/apache/logging/log4j/core/lookup/Interpolator.<init>(Interpolator.java:105)
4XESTACKTRACE                at org/apache/logging/log4j/core/config/AbstractConfiguration.<init>(AbstractConfiguration.java:135)
4XESTACKTRACE                at org/apache/logging/log4j/core/config/NullConfiguration.<init>(NullConfiguration.java:32)
4XESTACKTRACE                at org/apache/logging/log4j/core/LoggerContext.<clinit>(LoggerContext.java:74)
4XESTACKTRACE                at org/apache/logging/log4j/jul/Log4jBridgeHandler.publish(Log4jBridgeHandler.java:184)
5XESTACKTRACE                   (entered lock: org/apache/logging/log4j/jul/Log4jBridgeHandler@0x00000000FF200B40, entry count: 1)
4XESTACKTRACE                at java/util/logging/Logger.log(Logger.java:738)
4XESTACKTRACE                at com/ibm/ws/logging/internal/WsLogger.log(WsLogger.java:140)
4XESTACKTRACE                at com/ibm/ws/logging/internal/WsLogger.log(WsLogger.java:264)
4XESTACKTRACE                at com/ibm/ws/logging/internal/WsLogger.info(WsLogger.java:509)
4XESTACKTRACE                at org/apache/myfaces/config/DefaultFacesConfigurationProvider.getStandardFacesConfig(DefaultFacesConfigurationProvider.java:181)
4XESTACKTRACE                at org/apache/myfaces/config/DefaultFacesConfigurationMerger.getFacesConfigData(DefaultFacesConfigurationMerger.java:69)
4XESTACKTRACE                at org/apache/myfaces/config/FacesConfigurator.configure(FacesConfigurator.java:559)
4XESTACKTRACE                at org/apache/myfaces/webapp/AbstractFacesInitializer.buildConfiguration(AbstractFacesInitializer.java:437)
4XESTACKTRACE                at org/apache/myfaces/webapp/Jsp21FacesInitializer.initContainerIntegration(Jsp21FacesInitializer.java:74)
4XESTACKTRACE                at org/apache/myfaces/webapp/AbstractFacesInitializer.initFaces(AbstractFacesInitializer.java:186)
4XESTACKTRACE                at org/apache/myfaces/webapp/StartupServletContextListener.contextInitialized(StartupServletContextListener.java:119)
4XESTACKTRACE                at com/ibm/ws/webcontainer/webapp/WebApp.notifyServletContextCreated(WebApp.java:2465)
4XESTACKTRACE                at com/ibm/ws/webcontainer31/osgi/webapp/WebApp31.notifyServletContextCreated(WebApp31.java:512)
4XESTACKTRACE                at com/ibm/ws/webcontainer/webapp/WebApp.initialize(WebApp.java:1063)
4XESTACKTRACE                at com/ibm/ws/webcontainer/webapp/WebApp.initialize(WebApp.java:6702)
5XESTACKTRACE                   (entered lock: com/ibm/ws/webcontainer/webapp/WebApp$1@0x000000006BBEA2A0, entry count: 1)
4XESTACKTRACE                at com/ibm/ws/webcontainer/osgi/DynamicVirtualHost.startWebApp(DynamicVirtualHost.java:484)
4XESTACKTRACE                at com/ibm/ws/webcontainer/osgi/DynamicVirtualHost.startWebApplication(DynamicVirtualHost.java:479)
4XESTACKTRACE                at com/ibm/ws/webcontainer/osgi/WebContainer.startWebApplication(WebContainer.java:1207)
4XESTACKTRACE                at com/ibm/ws/webcontainer/osgi/WebContainer.access$100(WebContainer.java:113)
4XESTACKTRACE                at com/ibm/ws/webcontainer/osgi/WebContainer$3.run(WebContainer.java:995)
4XESTACKTRACE                at com/ibm/ws/threading/internal/ExecutorServiceImpl$RunnableWrapper.run(ExecutorServiceImpl.java:247(Compiled Code))
4XESTACKTRACE                at java/util/concurrent/Executors$RunnableAdapter.call(Executors.java:511(Compiled Code))
4XESTACKTRACE                at java/util/concurrent/FutureTask.run(FutureTask.java:266(Compiled Code))
4XESTACKTRACE                at java/util/concurrent/ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
4XESTACKTRACE                at java/util/concurrent/ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
4XESTACKTRACE                at java/lang/Thread.run(Thread.java:826)

Thread 1:

"Default Executor-thread-1" J9VMThread:0x000000000069E000, omrthread_t:0x00007F3F8C01DD48, java/lang/Thread:0x00000000672F8A30, state:CW, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x37, isDaemon:true)
3XMJAVALTHRCCL            com/ibm/ws/classloading/internal/AppClassLoader(0x000000006BBDA718)
3XMTHREADINFO1            (native thread ID:0x59, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000181)
3XMTHREADINFO2            (native stack address range from:0x00007F402C53A000, to:0x00007F402C57A000, size:0x40000)
3XMCPUTIME               CPU usage total: 16.894117600 secs, current category="Application"
3XMTHREADBLOCK     Waiting on: java/lang/J9VMInternals$ClassInitializationLock@0x00000000FF1895A8 Owned by: <unowned> Initializing thread: "Default Executor-thread-8"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=0 (0x0)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at org/apache/logging/log4j/core/selector/BasicContextSelector.<clinit>(BasicContextSelector.java:33)
4XESTACKTRACE                at sun/reflect/NativeConstructorAccessorImpl.newInstance0(Native Method)
4XESTACKTRACE                at sun/reflect/NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
4XESTACKTRACE                at sun/reflect/DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
4XESTACKTRACE                at java/lang/reflect/Constructor.newInstance(Constructor.java:423)
4XESTACKTRACE                at org/apache/logging/log4j/util/LoaderUtil.newInstanceOf(LoaderUtil.java:165)
4XESTACKTRACE                at org/apache/logging/log4j/util/LoaderUtil.newInstanceOf(LoaderUtil.java:186)
4XESTACKTRACE                at org/apache/logging/log4j/util/LoaderUtil.newCheckedInstanceOf(LoaderUtil.java:206)
4XESTACKTRACE                at org/apache/logging/log4j/util/LoaderUtil.newCheckedInstanceOfProperty(LoaderUtil.java:230)
4XESTACKTRACE                at org/apache/logging/log4j/core/util/Loader.newCheckedInstanceOfProperty(Loader.java:338)
4XESTACKTRACE                at org/apache/logging/log4j/core/impl/Log4jContextFactory.createContextSelector(Log4jContextFactory.java:100)
4XESTACKTRACE                at org/apache/logging/log4j/core/impl/Log4jContextFactory.<init>(Log4jContextFactory.java:61)
4XESTACKTRACE                at java/lang/J9VMInternals.newInstanceImpl(Native Method)
4XESTACKTRACE                at java/lang/Class.newInstance(Class.java:2108)
4XESTACKTRACE                at org/apache/logging/log4j/LogManager.<clinit>(LogManager.java:95)
4XESTACKTRACE                at our/project/OurLogger.createLogger(OurLogger:115)
4XESTACKTRACE                at our/project/OurLogger.<init>(OurLogger:41)
4XESTACKTRACE                at sun/reflect/NativeConstructorAccessorImpl.newInstance0(Native Method)
4XESTACKTRACE                at sun/reflect/NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
4XESTACKTRACE                at sun/reflect/DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
4XESTACKTRACE                at java/lang/reflect/Constructor.newInstance(Constructor.java:423)
4XESTACKTRACE                at org/jboss/weld/injection/ConstructorInjectionPoint.newInstance(ConstructorInjectionPoint.java:119)
4XESTACKTRACE                at org/jboss/weld/injection/ConstructorInjectionPoint$1.proceed(ConstructorInjectionPoint.java:101)
4XESTACKTRACE                at com/ibm/ws/cdi/impl/managedobject/ConstructionCallbackImpl.proceed(ConstructionCallbackImpl.java:40)
4XESTACKTRACE                at com/ibm/ejs/container/interceptors/InvocationContextImpl.proceed(InvocationContextImpl.java:597)
4XESTACKTRACE                at com/ibm/ws/cdi/ejb/impl/InterceptorChain.proceed(InterceptorChain.java:121)
4XESTACKTRACE                at com/ibm/ws/cdi/ejb/impl/EJBCDIInterceptorWrapper.invokeInterceptors(EJBCDIInterceptorWrapper.java:133)
4XESTACKTRACE                at com/ibm/ws/cdi/ejb/impl/EJBCDIInterceptorWrapper.aroundConstruct(EJBCDIInterceptorWrapper.java:110)
4XESTACKTRACE                at sun/reflect/NativeMethodAccessorImpl.invoke0(Native Method)
4XESTACKTRACE                at sun/reflect/NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
4XESTACKTRACE                at sun/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43(Compiled Code))
4XESTACKTRACE                at java/lang/reflect/Method.invoke(Method.java:498(Compiled Code))
4XESTACKTRACE                at com/ibm/ejs/container/interceptors/InterceptorProxy.invokeInterceptor(InterceptorProxy.java:191)
4XESTACKTRACE                at com/ibm/ejs/container/interceptors/InvocationContextImpl.proceed(InvocationContextImpl.java:579)
4XESTACKTRACE                at com/ibm/ejs/container/interceptors/InvocationContextImpl.doAroundInterceptor(InvocationContextImpl.java:300)
4XESTACKTRACE                at com/ibm/ejs/container/interceptors/InvocationContextImpl.aroundConstruct(InvocationContextImpl.java:224)
4XESTACKTRACE                at com/ibm/ws/cdi/impl/managedobject/EJBInterceptorAroundConstructCallback.aroundConstruct(EJBInterceptorAroundConstructCallback.java:40)
4XESTACKTRACE                at org/jboss/weld/injection/ConstructorInjectionPoint.invokeAroundConstructCallback(ConstructorInjectionPoint.java:109)
4XESTACKTRACE                at org/jboss/weld/injection/ConstructorInjectionPoint.invokeAroundConstructCallbacks(ConstructorInjectionPoint.java:95)
4XESTACKTRACE                at org/jboss/weld/injection/ConstructorInjectionPoint.newInstance(ConstructorInjectionPoint.java:78)
4XESTACKTRACE                at org/jboss/weld/injection/producer/AbstractInstantiator.newInstance(AbstractInstantiator.java:28)
4XESTACKTRACE                at org/jboss/weld/injection/producer/BasicInjectionTarget.produce(BasicInjectionTarget.java:112)
4XESTACKTRACE                at org/jboss/weld/injection/producer/BeanInjectionTarget.produce(BeanInjectionTarget.java:186)
4XESTACKTRACE                at org/jboss/weld/injection/producer/ejb/SessionBeanInjectionTarget.produce(SessionBeanInjectionTarget.java:126)
4XESTACKTRACE                at com/ibm/ws/cdi/impl/managedobject/AbstractManagedObjectFactory$1.run(AbstractManagedObjectFactory.java:299)
4XESTACKTRACE                at java/security/AccessController.doPrivileged(AccessController.java:690(Compiled Code))
4XESTACKTRACE                at com/ibm/ws/cdi/impl/managedobject/AbstractManagedObjectFactory.createInstance(AbstractManagedObjectFactory.java:296)
4XESTACKTRACE                at com/ibm/ws/cdi/impl/managedobject/AbstractManagedObjectFactory.createManagedObject(AbstractManagedObjectFactory.java:269)
4XESTACKTRACE                at com/ibm/ws/cdi/impl/managedobject/AbstractManagedObjectFactory.createManagedObject(AbstractManagedObjectFactory.java:251)
4XESTACKTRACE                at com/ibm/ws/cdi/impl/managedobject/AbstractManagedObjectFactory.createManagedObject(AbstractManagedObjectFactory.java:258)
4XESTACKTRACE                at com/ibm/ws/cdi/impl/managedobject/CDIEJBManagedObjectFactoryImpl.createManagedObject(CDIEJBManagedObjectFactoryImpl.java:270)
4XESTACKTRACE                at com/ibm/ejs/container/ManagedBeanOBase.callAroundConstructInterceptors(ManagedBeanOBase.java:372)
4XESTACKTRACE                at com/ibm/ejs/container/ManagedBeanOBase.createInterceptorsAndInstance(ManagedBeanOBase.java:215)
4XESTACKTRACE                at com/ibm/ejs/container/SingletonBeanO.initialize(SingletonBeanO.java:278)
4XESTACKTRACE                at com/ibm/ejs/container/BeanOFactory.create(BeanOFactory.java:105)
4XESTACKTRACE                at com/ibm/ejs/container/EJSHome.createSingletonBeanO(EJSHome.java:3478)
4XESTACKTRACE                at com/ibm/ejs/csi/EJBApplicationMetaData.createStartupBeans(EJBApplicationMetaData.java:1005)
4XESTACKTRACE                at com/ibm/ejs/csi/EJBApplicationMetaData.startedModule(EJBApplicationMetaData.java:739)
4XESTACKTRACE                at com/ibm/ws/ejbcontainer/osgi/internal/EJBRuntimeImpl.start(EJBRuntimeImpl.java:1124)
4XESTACKTRACE                at com/ibm/ws/ejbcontainer/osgi/internal/EJBModuleRuntimeContainerImpl.startModule(EJBModuleRuntimeContainerImpl.java:166)
4XESTACKTRACE                at com/ibm/ws/app/manager/module/internal/ModuleHandlerBase.deployModule(ModuleHandlerBase.java:101)
4XESTACKTRACE                at com/ibm/ws/app/manager/module/internal/DeployedModuleInfoImpl.installModule(DeployedModuleInfoImpl.java:51)
4XESTACKTRACE                at com/ibm/ws/app/manager/module/internal/SimpleDeployedAppInfoBase.deployModules(SimpleDeployedAppInfoBase.java:599)
4XESTACKTRACE                at com/ibm/ws/app/manager/module/internal/SimpleDeployedAppInfoBase.installApp(SimpleDeployedAppInfoBase.java:513)
4XESTACKTRACE                at com/ibm/ws/app/manager/module/internal/DeployedAppInfoBase.deployApp(DeployedAppInfoBase.java:351)
4XESTACKTRACE                at com/ibm/ws/app/manager/ear/internal/EARApplicationHandlerImpl.install(EARApplicationHandlerImpl.java:79)
4XESTACKTRACE                at com/ibm/ws/app/manager/internal/statemachine/StartAction.execute(StartAction.java:184)
4XESTACKTRACE                at com/ibm/ws/app/manager/internal/statemachine/ApplicationStateMachineImpl.enterState(ApplicationStateMachineImpl.java:1369)
4XESTACKTRACE                at com/ibm/ws/app/manager/internal/statemachine/ApplicationStateMachineImpl.run(ApplicationStateMachineImpl.java:912)
4XESTACKTRACE                at com/ibm/ws/threading/internal/ExecutorServiceImpl$RunnableWrapper.run(ExecutorServiceImpl.java:247(Compiled Code))
4XESTACKTRACE                at java/util/concurrent/ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
4XESTACKTRACE                at java/util/concurrent/ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
4XESTACKTRACE                at java/lang/Thread.run(Thread.java:826)

Workaround

Our workaround currently is to log something before we add the Log4jBridgeHandler, so that all necessary classes are initialized.

[ppkarwasz]

@FelixStuebner,

I realize this is one year old, but could you check with the newest 2.24.3 release to see if the initialization problem persists? We changed a lot of initialization details in 2.23.x and 2.24.x.

The problem you are describing is due to concurrent initialization of LoggerContext and LogManager. I am not sure how we can ensure that the initialization of LogManager already ended, when LoggerContext is initialized. @jvz, any ideas?