[logback-dev] [JIRA] Commented: (LBCORE-224) java.lang.IllegalMonitorStateException at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:68)

[Ceki Gulcu (JIRA)]

    [ http://jira.qos.ch/browse/LBCORE-224?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12146#action_12146 ] 

Ceki Gulcu commented on LBCORE-224:
-----------------------------------

I have modified AppenderAttachableImpl so that it outputs a line on the console for each lock/unlock operations. The modified code is available in the lbcore224 branch on github. Here is a sample of the produced output:

155  main LOCK
157  main UNLOCK
158  main LOCK
158  main UNLOCK
159  main LOCK
159  main UNLOCK
3889  QuorumPeer[myid=1]/0.0.0.0:11221 LOCK
3889  QuorumPeer[myid=1]/0.0.0.0:11221 UNLOCK
3893  main LOCK
3893  main UNLOCK
3897  Thread-4 LOCK
3897  Thread-4 UNLOCK
3898  main LOCK
3898  main UNLOCK
3898  QuorumPeer[myid=2]/0.0.0.0:11223 LOCK
3899  NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221 LOCK
3899  QuorumPeer[myid=2]/0.0.0.0:11223 UNLOCK
3899  NIOServerCxn.Factory:0.0.0.0/0.0.0.0:11221 UNLOCK
etc ...

About 600 lines are output so it is hard to check for matching lock/unlock operations. To help analyze the output I have written a small application called Reduce (in logback-classic/src/test/.../issues/lbcore224/). 

Interestingly enough, reduction shows that all lock operations are balanced with an unlock, except the last unlock operation which is not preceded by a matching lock which is pretty strange.



> java.lang.IllegalMonitorStateException at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:68)
> ----------------------------------------------------------------------------------------------------------------------------------------------
>
>                 Key: LBCORE-224
>                 URL: http://jira.qos.ch/browse/LBCORE-224
>             Project: logback-core
>          Issue Type: Bug
>          Components: Appender
>    Affects Versions: 0.9.30
>         Environment: W7 64 bits, JRE 6u26 64 bits.
>            Reporter: César Álvarez Núñez
>            Assignee: Logback dev list
>
> I'm trying (unsuccessfully for the time being) to create a test case that will reproduce it.
> It happens randomly with 0.9.30 when running a regression testing with TestNG + Zookeeper + Own code.
> Apparently it does not happen with 0.9.29.
> java.lang.IllegalMonitorStateException
> 	at java.util.concurrent.locks.ReentrantReadWriteLock$Sync.tryReleaseShared(Unknown Source)
> 	at java.util.concurrent.locks.AbstractQueuedSynchronizer.releaseShared(Unknown Source)
> 	at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.unlock(Unknown Source)
> 	at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:68)
> 	at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:285)
> 	at ch.qos.logback.classic.Logger.callAppenders(Logger.java:272)
> 	at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:473)
> 	at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:427)
> 	at ch.qos.logback.classic.Logger.info(Logger.java:631)
> 	at org.apache.zookeeper.server.ZooKeeperServer.shutdown(ZooKeeperServer.java:420)
> 	at org.apache.zookeeper.server.quorum.Leader.shutdown(Leader.java:443)
> 	at org.apache.zookeeper.server.quorum.QuorumPeer.shutdown(QuorumPeer.java:766)
> 	at org.apache.zookeeper.test.QuorumUtil.shutdown(QuorumUtil.java:224)
> 	at org.apache.zookeeper.test.QuorumUtil.shutdownAll(QuorumUtil.java:211)
> 	at org.apache.zookeeper.test.QuorumUtil.tearDown(QuorumUtil.java:255)
> 	at eswf.zk2.agents.ZkEphemeralInfoPublisherTest.tearDown(ZkEphemeralInfoPublisherTest.java:55)
> 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> 	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
> 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
> 	at java.lang.reflect.Method.invoke(Unknown Source)
> 	at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:80)
> 	at org.testng.internal.Invoker.invokeConfigurationMethod(Invoker.java:543)
> 	at org.testng.internal.Invoker.invokeConfigurations(Invoker.java:212)
> 	at org.testng.internal.Invoker.invokeMethod(Invoker.java:772)
> 	at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:883)
> 	at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1208)
> 	at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:127)
> 	at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:111)
> 	at org.testng.TestRunner.privateRun(TestRunner.java:753)
> 	at org.testng.TestRunner.run(TestRunner.java:613)
> 	at org.testng.SuiteRunner.runTest(SuiteRunner.java:335)
> 	at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:330)
> 	at org.testng.SuiteRunner.privateRun(SuiteRunner.java:292)
> 	at org.testng.SuiteRunner.run(SuiteRunner.java:241)
> 	at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:52)
> 	at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:86)
> 	at org.testng.TestNG.runSuitesSequentially(TestNG.java:1169)
> 	at org.testng.TestNG.runSuitesLocally(TestNG.java:1094)
> 	at org.testng.TestNG.run(TestNG.java:1006)
> 	at org.testng.remote.RemoteTestNG.run(RemoteTestNG.java:107)
> 	at org.testng.remote.RemoteTestNG.initAndRun(RemoteTestNG.java:199)
> 	at org.testng.remote.RemoteTestNG.main(RemoteTestNG.java:170)

-- 
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