[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
Wed Sep 23 21:10:44 CEST 2009


    [ http://jira.qos.ch/browse/LBCLASSIC-154?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11311#action_11311 ] 

Ceki Gulcu commented on LBCLASSIC-154:
--------------------------------------

Thank you for this bug report. The deadlock you are reporting is unlike any other I've seen before. Here is a summary I extracted from the stack trace you provided.

"http-0.0.0.0-8080-14" daemon prio=10 tid=0x00002aab606c9400 nid=0x5668 waiting for monitor entry [0x0000000046696000..0x0000000046699b90]
   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.isTraceEnabled(Logger.java:642)
	at org.slf4j.ext.XLogger.exit(XLogger.java:125)
	at com.diginsite.services.integration.dao.slave.client.DIISTransaction.processRequest(DIISTransaction.java:69)
	at com.diginsite.services.integration.dao.slave.client.DIISBrokerAccess.processRequest(DIISBrokerAccess.java:104)
	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)
	at com.diginsite.services.logging.LoggerUtil.logEvent(LoggerUtil.java:29)

tens of similar threads waiting on object monitor <0x00002aaabd743d58> omitted

"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)
	at com.diginsite.product.common.services.security.jaas.LoginAdapter.authenticate(LoginAdapter.java:110)
	at com.diginsite.product.ofx.facade.security.OFXSecurityFacadeBean.authenticate(OFXSecurityFacadeBean.java:114)
	at com.diginsite.product.ofx.busdelegate.SecurityOFXBusinessDelegate.authenticate(SecurityOFXBusinessDelegate.java:78)


"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)
	at com.diginsite.product.common.entity.businessclient.BusinessClientImpl.getCredentialValidator(BusinessClientImpl.java:1046)
	at com.diginsite.product.common.services.security.jaas.LoginAdapter.authenticate(LoginAdapter.java:209)
	at com.diginsite.product.ofx.facade.security.OFXSecurityFacadeBean.authenticate(OFXSecurityFacadeBean.java:114)
	at com.diginsite.product.ofx.busdelegate.SecurityOFXBusinessDelegate.authenticate(SecurityOFXBusinessDelegate.java:78)
	at com.diginsite.product.ofx.presentation.BasePreProcessor.authenticate(BasePreProcessor.java:121)
	at com.diginsite.product.ofx.presentation.BankingPreProcessorHandler.execute(BankingPreProcessorHandler.java:108)
	at com.eei.cmr.RequestProcessorMgr.do(Unknown Source)
	at com.eei.cmr.RequestProcessorMgr.a(Unknown Source)
	at com.eei.cmr.PFMMediator.a(Unknown Source)
	at com.eei.cmr.CMRServlet.a(Unknown Source)
	at com.eei.cmr.CMRServlet.doPost(Unknown Source)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:710)


It looks like there are tens of threads blocked on <0x00002aaabd743d58> (a ch.qos.logback.classic.LoggerContext), and the holder of that lock, thread "http-0.0.0.0-8080-11" which is parked waiting for <0x00002aaabd755128>, and another thread namely
"http-0.0.0.0-8080-15" which holds a reader lock on <0x00002aaabd755128>, all of which in theory should work fine without causing a deadlock.


> 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