Uploaded image for project: 'logback'
  1. logback
  2. LOGBACK-120

java.lang.IllegalMonitorStateException at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:68)

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: logback-core
    • Labels:
      None
    • Environment:

      W7 64 bits, JRE 6u26 64 bits.

      Description

      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)

        Activity

        Hide
        jhuxhorn Joern Huxhorn added a comment -

        Yep, that means that the exception did not happen.

        Ceki mentioned the same on the dev-list. IDEA, Eclipse and Maven all seem to produce the error while Gradle isn't. This is getting more mysterious with every new attempt to analyze it.

        A true Heisenbug...

        Show
        jhuxhorn Joern Huxhorn added a comment - Yep, that means that the exception did not happen. Ceki mentioned the same on the dev-list. IDEA, Eclipse and Maven all seem to produce the error while Gradle isn't. This is getting more mysterious with every new attempt to analyze it. A true Heisenbug...
        Hide
        noreply.ceki@qos.ch Ceki Gulcu added a comment - - edited

        The fact that the bug is not reproducible with Gradle could be a valid lead or just incidental.

        Show
        noreply.ceki@qos.ch Ceki Gulcu added a comment - - edited The fact that the bug is not reproducible with Gradle could be a valid lead or just incidental.
        Hide
        jhuxhorn Joern Huxhorn added a comment -

        Heureka!

        I could just confirm the issue on my Mac!

        java.lang.IllegalMonitorStateException
        at java.util.concurrent.locks.ReentrantReadWriteLock$Sync.tryReleaseShared(ReentrantReadWriteLock.java:363)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.releaseShared(AbstractQueuedSynchronizer.java:1317)
        at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.unlock(ReentrantReadWriteLock.java:745)
        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:410)
        at org.apache.zookeeper.server.quorum.Leader.shutdown(Leader.java:445)
        at org.apache.zookeeper.server.quorum.QuorumPeer.shutdown(QuorumPeer.java:765)
        at org.apache.zookeeper.test.QuorumUtil.shutdown(QuorumUtil.java:224)
        at org.apache.zookeeper.test.QuorumUtil.shutdownAll(QuorumUtil.java:211)
        at LBCORE224Test.shouldNotThrowIllegalMonitorStateException(LBCORE224Test.java:40)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:45)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
        at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42)
        at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
        at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
        at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:30)
        at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:46)
        at org.junit.rules.RunRules.evaluate(RunRules.java:18)
        at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:263)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:68)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:47)
        at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
        at org.junit.runner.JUnitCore.run(JUnitCore.java:157)
        at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:71)
        at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:199)
        at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:62)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at com.intellij.rt.execution.application.AppMain.main(AppMain.java:120)

        Environment:
        ------------------------------------------------------------
        Gradle 1.0-milestone-5-20111008000006+0200
        ------------------------------------------------------------

        Gradle build time: Saturday, October 8, 2011 12:00:06 AM CEST
        Groovy: 1.7.10
        Ant: Apache Ant(TM) version 1.8.2 compiled on December 20 2010
        Ivy: 2.2.0
        JVM: 1.6.0_26 (Apple Inc. 20.1-b02-384)
        OS: Mac OS X 10.6.8 x86_64

        I updated the Gradle build a little bit but it doesn't seem to make a big difference.

        Ceki,
        I hope you are ok with this "misuse" of the ticket. Let me know if it bothers you.

        Show
        jhuxhorn Joern Huxhorn added a comment - Heureka! I could just confirm the issue on my Mac! java.lang.IllegalMonitorStateException at java.util.concurrent.locks.ReentrantReadWriteLock$Sync.tryReleaseShared(ReentrantReadWriteLock.java:363) at java.util.concurrent.locks.AbstractQueuedSynchronizer.releaseShared(AbstractQueuedSynchronizer.java:1317) at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.unlock(ReentrantReadWriteLock.java:745) 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:410) at org.apache.zookeeper.server.quorum.Leader.shutdown(Leader.java:445) at org.apache.zookeeper.server.quorum.QuorumPeer.shutdown(QuorumPeer.java:765) at org.apache.zookeeper.test.QuorumUtil.shutdown(QuorumUtil.java:224) at org.apache.zookeeper.test.QuorumUtil.shutdownAll(QuorumUtil.java:211) at LBCORE224Test.shouldNotThrowIllegalMonitorStateException(LBCORE224Test.java:40) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:45) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42) at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20) at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28) at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:30) at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:46) at org.junit.rules.RunRules.evaluate(RunRules.java:18) at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:263) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:68) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:47) at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229) at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222) at org.junit.runners.ParentRunner.run(ParentRunner.java:300) at org.junit.runner.JUnitCore.run(JUnitCore.java:157) at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:71) at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:199) at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:62) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at com.intellij.rt.execution.application.AppMain.main(AppMain.java:120) Environment: ------------------------------------------------------------ Gradle 1.0-milestone-5-20111008000006+0200 ------------------------------------------------------------ Gradle build time: Saturday, October 8, 2011 12:00:06 AM CEST Groovy: 1.7.10 Ant: Apache Ant(TM) version 1.8.2 compiled on December 20 2010 Ivy: 2.2.0 JVM: 1.6.0_26 (Apple Inc. 20.1-b02-384) OS: Mac OS X 10.6.8 x86_64 I updated the Gradle build a little bit but it doesn't seem to make a big difference. Ceki, I hope you are ok with this "misuse" of the ticket. Let me know if it bothers you.
        Hide
        jhuxhorn Joern Huxhorn added a comment -

        Ok, the difference seems to be that IDEA (and probably also Eclipse and Maven) are using org.junit.runner.JUnitCore.run() while Gradle is using its own code for execution...

        Part of Gradle stacktrace:
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
        at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecuter.execute(JUnitTestClassExecuter.java:51)
        at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassProcessor.processTestClass(JUnitTestClassProcessor.java:63)
        at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.processTestClass(SuiteTestClassProcessor.java:49)

        Part of IDEA stacktrace:
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
        at org.junit.runner.JUnitCore.run(JUnitCore.java:157)
        at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:71)

        I don't know what strangeness is happening beside that...

        Show
        jhuxhorn Joern Huxhorn added a comment - Ok, the difference seems to be that IDEA (and probably also Eclipse and Maven) are using org.junit.runner.JUnitCore.run() while Gradle is using its own code for execution... Part of Gradle stacktrace: at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222) at org.junit.runners.ParentRunner.run(ParentRunner.java:300) at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecuter.execute(JUnitTestClassExecuter.java:51) at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassProcessor.processTestClass(JUnitTestClassProcessor.java:63) at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.processTestClass(SuiteTestClassProcessor.java:49) Part of IDEA stacktrace: at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222) at org.junit.runners.ParentRunner.run(ParentRunner.java:300) at org.junit.runner.JUnitCore.run(JUnitCore.java:157) at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:71) I don't know what strangeness is happening beside that...
        Hide
        jhuxhorn Joern Huxhorn added a comment -

        My bug in the Java Bug Database got accepted:
        http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=7099601

        Show
        jhuxhorn Joern Huxhorn added a comment - My bug in the Java Bug Database got accepted: http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=7099601

          People

          • Assignee:
            noreply.ceki@qos.ch Ceki Gulcu
            Reporter:
            calvarez César Álvarez Núñez
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: