Finalizer and Timer-Log4jService threads deadlock ------------------------------------------------- Key: JBAS-8261 URL: https://issues.jboss.org/browse/JBAS-8261 Project: Application Server 3 4 5 and 6 Issue Type: Bug Security Level: Public(Everyone can see) Components: Logging Affects Versions: JBossAS-5.1.0.GA Environment: OS: Linux (2.6.16.46-0.12-bigsmp) JVM: Java HotSpot(TM) Server VM (16.3-b01, mixed mode) (JRE 1.6.0_20) Reporter: Bart Berger Assignee: David Lloyd Fix For: No Release Encountered the following deadlock: "Finalizer" daemon prio=8 tid=3 BLOCKED at org.jboss.logmanager.LoggerNode.getParentLogger(LoggerNode.java:142) Local Variable: org.jboss.logmanager.LoggerNode#362 at org.jboss.logmanager.LoggerInstance.getParent(LoggerInstance.java:167) at org.jboss.logmanager.LoggerInstance.setLevel(LoggerInstance.java:96) Local Variable: java.util.logging.Level#2 Local Variable: org.jboss.logmanager.LogContext#1 at org.jboss.logmanager.LoggerInstance.finalize(LoggerInstance.java:204) at java.lang.ref.Finalizer.$$YJP$$invokeFinalizeMethod(Native Method) at java.lang.ref.Finalizer.invokeFinalizeMethod(Finalizer.java) at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:83) Local Variable: org.jboss.logmanager.LoggerInstance#161 at java.lang.ref.Finalizer.access$100(Finalizer.java:14) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:160) Local Variable: java.lang.ref.Finalizer#65597 "Timer-Log4jService" daemon prio=5 tid=25 WAITING at sun.misc.Unsafe.$$YJP$$park(Native Method) at sun.misc.Unsafe.park(Unsafe.java) Local Variable: sun.misc.Unsafe#1 at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158) at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:747) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:778) Local Variable: java.util.concurrent.locks.AbstractQueuedSynchronizer$Node#629 Local Variable: java.util.concurrent.locks.AbstractQueuedSynchronizer$Node#630 at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1114) at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:186) Local Variable: java.util.concurrent.locks.ReentrantLock$NonfairSync#89 at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:262) Local Variable: java.util.concurrent.locks.ReentrantLock#42 at org.jboss.logmanager.LoggerInstance.setLevel(LoggerInstance.java:89) at org.jboss.logmanager.LoggerInstance.<init>(LoggerInstance.java:53) Local Variable: org.jboss.logmanager.LoggerInstance#1049 Local Variable: java.lang.String#936666 at org.jboss.logmanager.LoggerNode.getOrCreateLogger(LoggerNode.java:127) at org.jboss.logmanager.LogContext.getLogger(LogContext.java:71) at org.jboss.logmanager.LogManager.getLogger(LogManager.java:273) at java.util.logging.LogManager.demandLogger(LogManager.java:390) at java.util.logging.Logger.getLogger(Logger.java:274) Local Variable: org.jboss.logmanager.LogManager#1 at org.jboss.logbridge.LogBridgeHandler.updateLoggers(LogBridgeHandler.java:123) Local Variable: java.util.Collections$SynchronizedMap#43 Local Variable: java.util.Vector$1#3 Local Variable: org.apache.log4j.spi.RootLogger#1 Local Variable: org.apache.log4j.Hierarchy#1 Local Variable: org.apache.log4j.Logger#375 Local Variable: java.lang.String#582052 Local Variable: org.jboss.logbridge.LevelMapper#1 Local Variable: org.jboss.logbridge.LogBridgeHandler#1 at org.jboss.logbridge.LogNotificationListener.handleNotification(LogNotificationListener.java:67) at sun.reflect.GeneratedMethodAccessor203.invoke(<unknown string>) Local Variable: sun.reflect.GeneratedMethodAccessor203#1 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) Local Variable: sun.reflect.DelegatingMethodAccessorImpl#458 at java.lang.reflect.Method.invoke(Method.java:597) Local Variable: org.jboss.logbridge.LogNotificationListener#1 at org.jboss.mx.notification.NotificationListenerProxy.invoke(NotificationListenerProxy.java:153) Local Variable: java.lang.String#2851584 Local Variable: java.lang.Object[]#760535 Local Variable: org.jboss.mx.notification.NotificationListenerProxy#2 Local Variable: java.lang.reflect.Method#16042 at $Proxy73.handleNotification(<unknown string>) at org.jboss.mx.util.JBossNotificationBroadcasterSupport.handleNotification(JBossNotificationBroadcasterSupport.java:127) Local Variable: $Proxy73#1 at org.jboss.mx.util.JBossNotificationBroadcasterSupport.sendNotification(JBossNotificationBroadcasterSupport.java:108) Local Variable: org.jboss.mx.notification.DefaultListenerRegistration#3 Local Variable: org.jboss.mx.notification.ListenerRegistry$ListenerRegistrationIterator#1 at org.jboss.logging.Log4jService.emitReconfigureNotification(Log4jService.java:560) Local Variable: org.jboss.logging.Log4jService#1 Local Variable: javax.management.Notification#1 at org.jboss.logging.Log4jService$URLWatchTimerTask.reconfigure(Log4jService.java:716) at org.jboss.logging.Log4jService$URLWatchTimerTask.run(Log4jService.java:636) Local Variable: org.jboss.net.protocol.resource.ResourceURLConnection#1 at java.util.TimerThread.mainLoop(Timer.java:512) Local Variable: java.lang.Object#18446 Local Variable: org.jboss.logging.Log4jService$URLWatchTimerTask#1 Local Variable: java.util.TaskQueue#5 at java.util.TimerThread.run(Timer.java:462) The timer thread ran logging configuration while the finalizer was processing LoggerInstance objects. The Finalizer thread calls context.levelTreeLock.lock() in LoggerInstance.setLevel(), then enters a synchronized code block in LoggerNode.getParentLogger(). The configuration thread enters a synchronized code block in LoggerNode.getOrCreateLogger(), then creates a new LoggerInstance which calls context.levelTreeLock.lock() in LoggerInstance.setLevel().