[logback-dev] [JIRA] Commented: (LBCLASSIC-154) All threads become blocked in ReconfigureOnChangeFilter when changing log level under load
Ceki Gulcu (JIRA)
noreply-jira at qos.ch
Fri Sep 25 10:33:44 CEST 2009
[ http://jira.qos.ch/browse/LBCLASSIC-154?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11318#action_11318 ]
Ceki Gulcu commented on LBCLASSIC-154:
--------------------------------------
For clarity, I am reproducing the stack traces for "http-0.0.0.0-8080-9" and "http-0.0.0.0-8080-11" which are sufficient to illustrate the deadlock condition.
"http-0.0.0.0-8080-9" daemon prio=10 tid=0x00002aab60c13c00 nid=0x5629 waiting for monitor entry [0x0000000044878000..0x000000004487bc10]
java.lang.Thread.State: BLOCKED (on object monitor)
at ch.qos.logback.classic.turbo.ReconfigureOnChangeFilter.decide(ReconfigureOnChangeFilter.java:99)
- waiting to lock <0x00002aaabd743d58> (a ch.qos.logback.classic.LoggerContext)
at ch.qos.logback.classic.spi.TurboFilterList.getTurboFilterChainDecision(TurboFilterList.java:47)
at ch.qos.logback.classic.LoggerContext.getTurboFilterChainDecision_0_3OrMore(LoggerContext.java:251)
at ch.qos.logback.classic.Logger.callTurboFilters(Logger.java:770)
at ch.qos.logback.classic.Logger.isDebugEnabled(Logger.java:488)
at ch.qos.logback.classic.Logger.isDebugEnabled(Logger.java:484)
at org.slf4j.ext.LoggerWrapper.isDebugEnabled(LoggerWrapper.java:209)
at com.diginsite.services.integration.dao.slave.client.DIISBrokerAccess.processRequest(DIISBrokerAccess.java:106)
at com.diginsite.services.integration.dao.slave.client.DIISBrokerAccess.processRequest(DIISBrokerAccess.java:74)
at com.diginsite.services.integration.dao.slave.BrokerAccessDaoConnection.process(BrokerAccessDaoConnection.java:204)
at com.diginsite.services.integration.logging.IAALogHandler.publish(IAALogHandler.java:226)
at com.diginsite.services.integration.logging.logback.IAALogAppender.append(IAALogAppender.java:131)
at com.diginsite.services.integration.logging.logback.IAALogAppender.append(IAALogAppender.java:23)
at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:89)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:60)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:271)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:258)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:440)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:394)
at ch.qos.logback.classic.Logger.log(Logger.java:813)
at org.slf4j.ext.EventLogger.logEvent(EventLogger.java:36)
"http-0.0.0.0-8080-11" daemon prio=10 tid=0x00002aab60e5fc00 nid=0x5662 waiting on condition [0x0000000046192000..0x0000000046194c90]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00002aaabd755128> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
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)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1114)
at java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:807)
at ch.qos.logback.core.spi.AppenderAttachableImpl.detachAndStopAllAppenders(AppenderAttachableImpl.java:142)
at ch.qos.logback.classic.Logger.detachAndStopAllAppenders(Logger.java:207)
at ch.qos.logback.classic.Logger.recursiveReset(Logger.java:335)
at ch.qos.logback.classic.Logger.recursiveReset(Logger.java:342)
at ch.qos.logback.classic.LoggerContext.reset(LoggerContext.java:212)
at ch.qos.logback.classic.turbo.ReconfigureOnChangeFilter.reconfigure(ReconfigureOnChangeFilter.java:149)
at ch.qos.logback.classic.turbo.ReconfigureOnChangeFilter.decide(ReconfigureOnChangeFilter.java:105)
- locked <0x00002aaabd743d58> (a ch.qos.logback.classic.LoggerContext)
at ch.qos.logback.classic.spi.TurboFilterList.getTurboFilterChainDecision(TurboFilterList.java:47)
at ch.qos.logback.classic.LoggerContext.getTurboFilterChainDecision_0_3OrMore(LoggerContext.java:251)
at ch.qos.logback.classic.Logger.callTurboFilters(Logger.java:770)
at ch.qos.logback.classic.Logger.isTraceEnabled(Logger.java:642)
at org.slf4j.ext.XLogger.exit(XLogger.java:125)
In "http-0.0.0.0-8080-11" ReconfigureOnChangeFilter obtains the LoggerContext lock and then attempts to detachAndStopAllAppenders() which requires a write lock (in AppenderAttachableImpl).
In "http-0.0.0.0-8080-9", while doing "simple" logging, obtains the reader lock in AppenderAttachableImpl, and one the invoked appenders, namely IAALogAppender, attempts to log from within itself. This causes ReconfigureOnChangeFilter to be invoked which is then blocked waiting for the LoggerContext lock. Deadlock...
ReconfigureOnChangeFilter does in-thread reconfiguration in order to avoid the creation of threads which need to be managed, at least closed when the application re-cycles. Such thread management has proven to be troublesome in the past and I would like to avoid it if possible.
I agree with you comment about allowing appenders to log from within. Recursive logging may not always be preventable.
The next step is to duplicate this behavior in a unit test.
> All threads become blocked in ReconfigureOnChangeFilter when changing log level under load
> ------------------------------------------------------------------------------------------
>
> Key: LBCLASSIC-154
> URL: http://jira.qos.ch/browse/LBCLASSIC-154
> Project: logback-classic
> Issue Type: Bug
> Affects Versions: 0.917
> Environment: Linux metro2a.star.dev.diginsite.com 2.6.18-128.1.1.el5 #1 SMP Mon Jan 26 13:58:24 EST 2009 x86_64 x86_64 x86_64 GNU/Linux
> Java(TM) SE Runtime Environment (build 1.6.0_11-b03)
> Java HotSpot(TM) 64-Bit Server VM (build 11.0-b16, mixed mode)
> Reporter: Andrew Perrine
> Assignee: Ceki Gulcu
> Attachments: stacktrace.log
>
>
> We were testing logback's new <configuration scan="true"> feature and when we changed the logging level while our application was under load, all threads became blocked inside logback (full stack trace is very long, here are two examples):
> "http-0.0.0.0-8080-148" daemon prio=10 tid=0x00002aab58679800 nid=0x26ed waiting for monitor entry [0x000000004e617000..0x000000004e618c10]
> java.lang.Thread.State: BLOCKED (on object monitor)
> at ch.qos.logback.classic.turbo.ReconfigureOnChangeFilter.decide(ReconfigureOnChangeFilter.java:99)
> - waiting to lock <0x00002aaabd743d58> (a ch.qos.logback.classic.LoggerContext)
> at ch.qos.logback.classic.spi.TurboFilterList.getTurboFilterChainDecision(TurboFilterList.java:47)
> at ch.qos.logback.classic.LoggerContext.getTurboFilterChainDecision_0_3OrMore(LoggerContext.java:251)
> at ch.qos.logback.classic.Logger.callTurboFilters(Logger.java:770)
> at ch.qos.logback.classic.Logger.isDebugEnabled(Logger.java:488)
> at ch.qos.logback.classic.Logger.isDebugEnabled(Logger.java:484)
> at org.slf4j.ext.LoggerWrapper.debug(LoggerWrapper.java:238)
> at com.diginsite.product.ofx.presentation.CustomRequestWrapper.addCNtoOFXRequest(OFXFilter.java:191)
> at com.diginsite.product.ofx.presentation.CustomRequestWrapper.<init>(OFXFilter.java:153)
> at com.diginsite.product.ofx.presentation.OFXFilter.doFilter(OFXFilter.java:56)
> at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
> at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
> at org.hyperic.hq.product.servlet.filter.JMXFilter.doFilter(JMXFilter.java:324)
> at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
> at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
> at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
> at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
> at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
> at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:230)
> at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175)
> at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:182)
> at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:84)
> at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
> at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
> at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:157)
> at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
> at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:262)
> at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:844)
> at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
> at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:446)
> at java.lang.Thread.run(Thread.java:619)
> "http-0.0.0.0-8080-15" daemon prio=10 tid=0x00002aab600b0400 nid=0x5669 waiting on condition [0x0000000046799000..0x000000004679ac10]
> java.lang.Thread.State: WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x00002aaabd755128> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
> 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.doAcquireShared(AbstractQueuedSynchronizer.java:877)
> at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(AbstractQueuedSynchronizer.java:1197)
> at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock(ReentrantReadWriteLock.java:594)
> at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:57)
> at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:271)
> at ch.qos.logback.classic.Logger.callAppenders(Logger.java:258)
> at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:440)
> at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:394)
> at ch.qos.logback.classic.Logger.log(Logger.java:813)
> at org.slf4j.ext.EventLogger.logEvent(EventLogger.java:36)
> at com.diginsite.services.logging.LoggerUtil.logEvent(LoggerUtil.java:29)
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
More information about the logback-dev
mailing list