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

        calvarez César Álvarez Núñez created issue -
        Hide
        calvarez César Álvarez Núñez added a comment -

        Sorry, the envrionment is wrong. OS is "WinXP SP3" and "JRE 6u26 32 bits".

        Show
        calvarez César Álvarez Núñez added a comment - Sorry, the envrionment is wrong. OS is "WinXP SP3" and "JRE 6u26 32 bits".
        Hide
        calvarez César Álvarez Núñez added a comment -

        Googling a bit I've found this thread http://qos.ch/pipermail/logback-dev/2009-February/003620.html from 2009.

        Show
        calvarez César Álvarez Núñez added a comment - Googling a bit I've found this thread http://qos.ch/pipermail/logback-dev/2009-February/003620.html from 2009.
        Hide
        noreply.ceki@qos.ch Ceki Gulcu added a comment -

        Hi César,

        It would be very helpful If you could describe the steps required to reproduce the issue.

        Show
        noreply.ceki@qos.ch Ceki Gulcu added a comment - Hi César, It would be very helpful If you could describe the steps required to reproduce the issue.
        Hide
        calvarez César Álvarez Núñez added a comment - - edited

        I've unsuccessfully tried to create a test case that will detect the bug without the need to use Zookeeper.

        So the only way to catch it is by running the following test case with the zookeeper-trunk (which is based on SLF4j instead of Log4J) and a testng.xml where "org.apache.zookeeper" loggers are attached to a file appender.

        @Test
        public static void test() throws Exception {
        System.setProperty("build.test.dir", "./tmp/zk/");
        final File f = new File("./tmp/zk");
        if (!f.mkdirs())

        { System.out.println("Directory [" + f + "] already exist."); }

        final QuorumUtil qU = new QuorumUtil(1);
        for (int i = 0; i < 10; i++)

        { qU.startQuorum(); qU.shutdownAll(); System.out.println(i); }

        qU.tearDown();
        }

        How to get zookeeper trunk: https://cwiki.apache.org/confluence/display/ZOOKEEPER/HowToContribute

        Show
        calvarez César Álvarez Núñez added a comment - - edited I've unsuccessfully tried to create a test case that will detect the bug without the need to use Zookeeper. So the only way to catch it is by running the following test case with the zookeeper-trunk (which is based on SLF4j instead of Log4J) and a testng.xml where "org.apache.zookeeper" loggers are attached to a file appender. @Test public static void test() throws Exception { System.setProperty("build.test.dir", "./tmp/zk/"); final File f = new File("./tmp/zk"); if (!f.mkdirs()) { System.out.println("Directory [" + f + "] already exist."); } final QuorumUtil qU = new QuorumUtil(1); for (int i = 0; i < 10; i++) { qU.startQuorum(); qU.shutdownAll(); System.out.println(i); } qU.tearDown(); } How to get zookeeper trunk: https://cwiki.apache.org/confluence/display/ZOOKEEPER/HowToContribute
        Hide
        noreply.ceki@qos.ch Ceki Gulcu added a comment - - edited

        Thanks for supplying a recipe for reproducing this problem. I've checked and compiled zookeeper from SVN and added the resulting zookeeper-3.4.0.jar and zookeeper-3.4.0-test.jar files to my class path.

        Here is my test case:

        package ch.qos.logback.classic.issue.lbcore224;
        import org.apache.zookeeper.test.QuorumUtil;
        import org.junit.After;
        import org.junit.Test;

        public class LBCORE224Test {
        final QuorumUtil qU = new QuorumUtil(1);

        @After
        public void teatDown() throws Exception

        { qU.tearDown(); }

        @Test
        public void test() throws Exception {
        for (int i = 0; i < 10; i++)

        { qU.startQuorum(); qU.shutdownAll(); System.out.println(i); }

        }
        }

        Running the above test case I get:
        java.lang.RuntimeException: java.io.IOException: The system cannot find the path specified
        at org.apache.zookeeper.test.QuorumUtil.<init>(QuorumUtil.java:118)
        at ch.qos.logback.classic.issue.lbcore224.LBCORE224Test.<init>(LBCORE224Test.java:10)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
        at org.junit.runners.BlockJUnit4ClassRunner.createTest(BlockJUnit4ClassRunner.java:209)
        at org.junit.runners.BlockJUnit4ClassRunner$1.runReflectiveCall(BlockJUnit4ClassRunner.java:258)
        [snip]
        Caused by: java.io.IOException: The system cannot find the path specified
        at java.io.WinNTFileSystem.createFileExclusively(Native Method)
        at java.io.File.checkAndCreate(File.java:1704)
        at java.io.File.createTempFile(File.java:1792)
        at org.apache.zookeeper.test.ClientBase.createTmpDir(ClientBase.java:320)
        at org.apache.zookeeper.test.ClientBase.createTmpDir(ClientBase.java:317)
        at org.apache.zookeeper.test.QuorumUtil.<init>(QuorumUtil.java:101)
        ... 27 more

        What else is required to run this test case?

        After further investigation, it looks like one needs to define a system property "build.test.dir" to point to some existing directory, say /tmp/zootest/. Anyway, I can reproduce the problem:
        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.test.ClientBase.send4LetterWord(ClientBase.java:227)
        at org.apache.zookeeper.test.ClientBase.waitForServerUp(ClientBase.java:260)
        at org.apache.zookeeper.test.QuorumUtil.startQuorum(QuorumUtil.java:175)
        at ch.qos.logback.classic.issue.lbcore224.LBCORE224Test.test(LBCORE224Test.java:20)
        [snip]

        Show
        noreply.ceki@qos.ch Ceki Gulcu added a comment - - edited Thanks for supplying a recipe for reproducing this problem. I've checked and compiled zookeeper from SVN and added the resulting zookeeper-3.4.0.jar and zookeeper-3.4.0-test.jar files to my class path. Here is my test case: package ch.qos.logback.classic.issue.lbcore224; import org.apache.zookeeper.test.QuorumUtil; import org.junit.After; import org.junit.Test; public class LBCORE224Test { final QuorumUtil qU = new QuorumUtil(1); @After public void teatDown() throws Exception { qU.tearDown(); } @Test public void test() throws Exception { for (int i = 0; i < 10; i++) { qU.startQuorum(); qU.shutdownAll(); System.out.println(i); } } } Running the above test case I get: java.lang.RuntimeException: java.io.IOException: The system cannot find the path specified at org.apache.zookeeper.test.QuorumUtil.<init>(QuorumUtil.java:118) at ch.qos.logback.classic.issue.lbcore224.LBCORE224Test.<init>(LBCORE224Test.java:10) at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27) at java.lang.reflect.Constructor.newInstance(Constructor.java:513) at org.junit.runners.BlockJUnit4ClassRunner.createTest(BlockJUnit4ClassRunner.java:209) at org.junit.runners.BlockJUnit4ClassRunner$1.runReflectiveCall(BlockJUnit4ClassRunner.java:258) [snip] Caused by: java.io.IOException: The system cannot find the path specified at java.io.WinNTFileSystem.createFileExclusively(Native Method) at java.io.File.checkAndCreate(File.java:1704) at java.io.File.createTempFile(File.java:1792) at org.apache.zookeeper.test.ClientBase.createTmpDir(ClientBase.java:320) at org.apache.zookeeper.test.ClientBase.createTmpDir(ClientBase.java:317) at org.apache.zookeeper.test.QuorumUtil.<init>(QuorumUtil.java:101) ... 27 more What else is required to run this test case? After further investigation, it looks like one needs to define a system property "build.test.dir" to point to some existing directory, say /tmp/zootest/. Anyway, I can reproduce the problem: 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.test.ClientBase.send4LetterWord(ClientBase.java:227) at org.apache.zookeeper.test.ClientBase.waitForServerUp(ClientBase.java:260) at org.apache.zookeeper.test.QuorumUtil.startQuorum(QuorumUtil.java:175) at ch.qos.logback.classic.issue.lbcore224.LBCORE224Test.test(LBCORE224Test.java:20) [snip]
        Hide
        calvarez César Álvarez Núñez added a comment -

        Sorry Ceki, I forgot to include the system property and directory creation. I've just updater my comment.
        It could be included on a @Before method in addition to directory removal y the @After method.

        The problem with the code snippet is that not always throws an exception

        Anyway, after reviewing "ch.qos.logback.core.spi.AppenderAttachableImpl.java" I've not found any clue about the problem.
        The code seems to be solid so I think that it could be a java bug.

        The bug "http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=7063861" was a candidate but it has been discarded since it does not fail if the second thread performs a lock prior to the unlock as the AppenderAttachableImpl does.

        Show
        calvarez César Álvarez Núñez added a comment - Sorry Ceki, I forgot to include the system property and directory creation. I've just updater my comment. It could be included on a @Before method in addition to directory removal y the @After method. The problem with the code snippet is that not always throws an exception Anyway, after reviewing "ch.qos.logback.core.spi.AppenderAttachableImpl.java" I've not found any clue about the problem. The code seems to be solid so I think that it could be a java bug. The bug "http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=7063861" was a candidate but it has been discarded since it does not fail if the second thread performs a lock prior to the unlock as the AppenderAttachableImpl does.
        Hide
        noreply.ceki@qos.ch Ceki Gulcu added a comment - - edited

        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. How could an unlock occur without a preceding lock?

        Show
        noreply.ceki@qos.ch Ceki Gulcu added a comment - - edited 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. How could an unlock occur without a preceding lock?
        Hide
        calvarez César Álvarez Núñez added a comment - - edited

        Umm.... with the following code it should be impossible. That's pretty odd :-/

        /**

        • Call the <code>doAppend</code> method on all attached appenders.
          */
          public int appendLoopOnAppenders(E e) {
          int size = 0;
          r.lock();
          try
          Unknown macro: { for (Appender<E> appender }

          finally

          { r.unlock(); }

          return size;
          }

        Could you try luck by disabling "Biased locking" (http://java.sun.com/performance/reference/whitepapers/6_performance.html#2.1.1) or "Lock coarsening" (http://java.sun.com/performance/reference/whitepapers/6_performance.html#2.1.2)?

        If solved it points to a java bug.

        Show
        calvarez César Álvarez Núñez added a comment - - edited Umm.... with the following code it should be impossible. That's pretty odd :-/ /** Call the <code>doAppend</code> method on all attached appenders. */ public int appendLoopOnAppenders(E e) { int size = 0; r.lock(); try Unknown macro: { for (Appender<E> appender } finally { r.unlock(); } return size; } Could you try luck by disabling "Biased locking" ( http://java.sun.com/performance/reference/whitepapers/6_performance.html#2.1.1 ) or "Lock coarsening" ( http://java.sun.com/performance/reference/whitepapers/6_performance.html#2.1.2)? If solved it points to a java bug.
        Hide
        jhuxhorn Joern Huxhorn added a comment -

        Just checked the code and wasn't able to find anything suspicious, either.

        There are some small enhancements you could implement:

        public Appender<E> getAppender(String name) {
        if (name == null)

        { return null; }

        r.lock();
        try {
        for (Appender<E> appender : appenderList) {
        if (name.equals(appender.getName()))

        { return appender; }

        }
        } finally

        { r.unlock(); }
        return null;
        }

        /**
        * Returns <code>true</code> if the specified appender is in the list of
        * attached appenders, <code>false</code> otherwise.
        *
        * @since 1.2
        */
        public boolean isAttached(Appender<E> appender) {
        if (appender == null) { return false; }
        r.lock();
        try {
        for (Appender<E> a : appenderList) {
        if (a == appender) { return true; }
        }
        } finally { r.unlock(); }

        return false;
        }

        The "finally" will be executed automatically before the "return".

        That said, I don't understand how the IllegalMonitorStateException can occur.

        Show
        jhuxhorn Joern Huxhorn added a comment - Just checked the code and wasn't able to find anything suspicious, either. There are some small enhancements you could implement: public Appender<E> getAppender(String name) { if (name == null) { return null; } r.lock(); try { for (Appender<E> appender : appenderList) { if (name.equals(appender.getName())) { return appender; } } } finally { r.unlock(); } return null; } /** * Returns <code>true</code> if the specified appender is in the list of * attached appenders, <code>false</code> otherwise. * * @since 1.2 */ public boolean isAttached(Appender<E> appender) { if (appender == null) { return false; } r.lock(); try { for (Appender<E> a : appenderList) { if (a == appender) { return true; } } } finally { r.unlock(); } return false; } The "finally" will be executed automatically before the "return". That said, I don't understand how the IllegalMonitorStateException can occur.
        Hide
        noreply.ceki@qos.ch Ceki Gulcu added a comment - - edited

        César, you mentioned W7 64bits as your OS. I am also running the tests on W7 64 and JDK 1.6.0_23.

        At this point anything is possible. It could be a bug in ReentrantReadWriteLock, a bug in JIT, in the OS (W7 64bits) or in the CPU. I am running the tests on an AMD Phenom II X6 1100T . Which CPU are you using?

        I will run the tests on different CPU and OS. See what gives.

        Show
        noreply.ceki@qos.ch Ceki Gulcu added a comment - - edited César, you mentioned W7 64bits as your OS. I am also running the tests on W7 64 and JDK 1.6.0_23. At this point anything is possible. It could be a bug in ReentrantReadWriteLock, a bug in JIT, in the OS (W7 64bits) or in the CPU. I am running the tests on an AMD Phenom II X6 1100T . Which CPU are you using? I will run the tests on different CPU and OS. See what gives.
        Hide
        calvarez César Álvarez Núñez added a comment -

        The environment info is wrong.
        It was updated on my first comment [Sorry, the envrionment is wrong. OS is "WinXP SP3" and "JRE 6u26 32 bits"] because I can't edit the "Environment" field.
        My processor is a dual core "Intel Pentium D 945" (http://ark.intel.com/products/27520/Intel-Pentium-D-Processor-945-%284M-Cache-3_40-GHz-800-MHz-FSB%29).

        Show
        calvarez César Álvarez Núñez added a comment - The environment info is wrong. It was updated on my first comment [Sorry, the envrionment is wrong. OS is "WinXP SP3" and "JRE 6u26 32 bits"] because I can't edit the "Environment" field. My processor is a dual core "Intel Pentium D 945" ( http://ark.intel.com/products/27520/Intel-Pentium-D-Processor-945-%284M-Cache-3_40-GHz-800-MHz-FSB%29 ).
        Show
        calvarez César Álvarez Núñez added a comment - Ceki, just in case, did you try disabling "Biased locking" ( http://java.sun.com/performance/reference/whitepapers/6_performance.html#2.1.1 ) or "Lock coarsening" ( http://java.sun.com/performance/reference/whitepapers/6_performance.html#2.1.2 ) ?
        Hide
        noreply.ceki@qos.ch Ceki Gulcu added a comment - - edited

        I am able to reproduce the problem on Windows 7 with the following JDKs:

        1) Java(TM) SE Runtime Environment (build 1.6.0_16-b01)
        Java HotSpot(TM) 64-Bit Server VM (build 14.2-b01, mixed mode)
        2) Java(TM) SE Runtime Environment (build 1.6.0_17-b04)
        Java HotSpot(TM) Client VM (build 14.3-b01, mixed mode, sharing)

        Various JVM optimization settings do not modify the observed behavior. (I've tried many different combinations including -XX:-EliminateLocks and -XX:-UseBiasedLocking ).

        On JDK 1.5.0_21-b01 (same OS and machine) I am unable to reproduce the IlelgalMonitorException. On Ubuntu (virtual machine running on same host as previously), I am equally unable to reproduce the problem.

        It looks like the problem is a JDK 1.6 issue when running on Windows. My next step is to write a test case which does not depend on zookeeper. I'll keep you posted.

        Show
        noreply.ceki@qos.ch Ceki Gulcu added a comment - - edited I am able to reproduce the problem on Windows 7 with the following JDKs: 1) Java(TM) SE Runtime Environment (build 1.6.0_16-b01) Java HotSpot(TM) 64-Bit Server VM (build 14.2-b01, mixed mode) 2) Java(TM) SE Runtime Environment (build 1.6.0_17-b04) Java HotSpot(TM) Client VM (build 14.3-b01, mixed mode, sharing) Various JVM optimization settings do not modify the observed behavior. (I've tried many different combinations including -XX:-EliminateLocks and -XX:-UseBiasedLocking ). On JDK 1.5.0_21-b01 (same OS and machine) I am unable to reproduce the IlelgalMonitorException. On Ubuntu (virtual machine running on same host as previously), I am equally unable to reproduce the problem. It looks like the problem is a JDK 1.6 issue when running on Windows. My next step is to write a test case which does not depend on zookeeper. I'll keep you posted.
        admin JIRA Administrator made changes -
        Field Original Value New Value
        Comment [ I was not successful in reproducing the issue without zookeper. I wonder what zookeper does out of the ordinary. ]
        Hide
        noreply.ceki@qos.ch Ceki Gulcu added a comment -

        I was not successful in reproducing the issue without zookeper. I am left wondering what zookeper does out of the ordinary.

        Show
        noreply.ceki@qos.ch Ceki Gulcu added a comment - I was not successful in reproducing the issue without zookeper. I am left wondering what zookeper does out of the ordinary.
        Hide
        calvarez César Álvarez Núñez added a comment -

        It could be due to threads changing their name after they are created?

        Show
        calvarez César Álvarez Núñez added a comment - It could be due to threads changing their name after they are created?
        Hide
        noreply.ceki@qos.ch Ceki Gulcu added a comment -

        I don't think thread names can be changed after construction.

        Show
        noreply.ceki@qos.ch Ceki Gulcu added a comment - I don't think thread names can be changed after construction.
        Hide
        rgoers@apache.org Ralph Goers added a comment -

        Sure it can. Thread provides a setName() method. Obviously it can only be called after construction.

        Show
        rgoers@apache.org Ralph Goers added a comment - Sure it can. Thread provides a setName() method. Obviously it can only be called after construction.
        Hide
        calvarez César Álvarez Núñez added a comment -

        It is sure that ZooKeeper threads change their name after created with the setName method.

        Show
        calvarez César Álvarez Núñez added a comment - It is sure that ZooKeeper threads change their name after created with the setName method.
        admin JIRA Administrator made changes -
        Comment [ My bad. I don't know why I thought Threads could not change their name after construction. ]
        Hide
        noreply.ceki@qos.ch Ceki Gulcu added a comment -

        My bad. I don't know why I thought Threads could not change their name after construction.

        Show
        noreply.ceki@qos.ch Ceki Gulcu added a comment - My bad. I don't know why I thought Threads could not change their name after construction.
        Hide
        jhuxhorn Joern Huxhorn added a comment -

        Setting/changing the thread-name is possible even after the Thread has been started.

        But doing so does not have any obvious influence on the locking. it simply changes a char[] and performs an additional native call on OS X.
        The locking does only depend on the Thread ID - which is only written to in init(..) (called in c'tors) and clone().

        protected final boolean tryReleaseShared(int unused) {
        HoldCounter rh = cachedHoldCounter;
        Thread current = Thread.currentThread();
        if (rh == null || rh.tid != current.getId())
        rh = readHolds.get();
        if (rh.tryDecrement() <= 0)
        throw new IllegalMonitorStateException();
        for (;

        { int c = getState(); int nextc = c - SHARED_UNIT; if (compareAndSetState(c, nextc)) return nextc == 0; }

        }

        The only chance for failure in the above code is a duplicate or mutable thread id. oO
        tryDecrement() is also trivial. The only place throwing a IllegalMonitorStateException is really inside of that "if".

        This whole problem is extremely strange...
        (The above code is 1.6.0_26 on Mac)

        Show
        jhuxhorn Joern Huxhorn added a comment - Setting/changing the thread-name is possible even after the Thread has been started. But doing so does not have any obvious influence on the locking. it simply changes a char[] and performs an additional native call on OS X. The locking does only depend on the Thread ID - which is only written to in init(..) (called in c'tors) and clone(). protected final boolean tryReleaseShared(int unused) { HoldCounter rh = cachedHoldCounter; Thread current = Thread.currentThread(); if (rh == null || rh.tid != current.getId()) rh = readHolds.get(); if (rh.tryDecrement() <= 0) throw new IllegalMonitorStateException(); for (; { int c = getState(); int nextc = c - SHARED_UNIT; if (compareAndSetState(c, nextc)) return nextc == 0; } } The only chance for failure in the above code is a duplicate or mutable thread id. oO tryDecrement() is also trivial. The only place throwing a IllegalMonitorStateException is really inside of that "if". This whole problem is extremely strange... (The above code is 1.6.0_26 on Mac)
        admin JIRA Administrator made changes -
        Comment [ Instead of spending more time on this issue, I'd like to use CopyOnWriteArrayList instead of ReadWriteLock. Hopefully, performance should be identical but without the occasional IllegalMonitorStateException. ]
        noreply.ceki@qos.ch Ceki Gulcu made changes -
        Assignee Logback dev list [ logback-dev@qos.ch ] Ceki Gulcu [ noreply.ceki@qos.ch ]
        noreply.ceki@qos.ch Ceki Gulcu made changes -
        Status Open [ 1 ] In Progress [ 3 ]
        Hide
        noreply.ceki@qos.ch Ceki Gulcu added a comment - - edited

        The bug is quite fascinating but it very much looks like bug in the JDK rather than in logback.

        Moreover, I am afraid this bug will be a black hole. As such, I'd like to use CopyOnWriteArrayList instead of ReadWriteLock. Hopefully, performance should be identical but without the occasional IllegalMonitorStateException.

        Show
        noreply.ceki@qos.ch Ceki Gulcu added a comment - - edited The bug is quite fascinating but it very much looks like bug in the JDK rather than in logback. Moreover, I am afraid this bug will be a black hole. As such, I'd like to use CopyOnWriteArrayList instead of ReadWriteLock. Hopefully, performance should be identical but without the occasional IllegalMonitorStateException.
        Hide
        noreply.ceki@qos.ch Ceki Gulcu added a comment - - edited
        Show
        noreply.ceki@qos.ch Ceki Gulcu added a comment - - edited Fixed in https://github.com/ceki/logback/commit/eef137b0c6ca9
        noreply.ceki@qos.ch Ceki Gulcu made changes -
        Status In Progress [ 3 ] Resolved [ 5 ]
        Fix Version/s 0.9.31 [ 10172 ]
        Resolution Fixed [ 1 ]
        Hide
        holgerh Holger Hoffstätte added a comment -

        If you google for the exception practically all occurrences show buggy application code as the cause, which explains why this happens only with Zookeeper (no kidding).
        The simplest explanation can be found here: http://jira.porticoproject.org/browse/PORT-168

        Show
        holgerh Holger Hoffstätte added a comment - If you google for the exception practically all occurrences show buggy application code as the cause, which explains why this happens only with Zookeeper (no kidding). The simplest explanation can be found here: http://jira.porticoproject.org/browse/PORT-168
        Hide
        jhuxhorn Joern Huxhorn added a comment - - edited

        I just created https://github.com/huxi/lbcore224 to reproduce this.
        Could someone please verify if the issue shows up on vulnerable systems?
        Simply clone the repository and execute gradlew.bat multiple times.

        Show
        jhuxhorn Joern Huxhorn added a comment - - edited I just created https://github.com/huxi/lbcore224 to reproduce this. Could someone please verify if the issue shows up on vulnerable systems? Simply clone the repository and execute gradlew.bat multiple times.
        Hide
        calvarez César Álvarez Núñez added a comment -

        With a "W7 64 bits".
        I've just updated from "JRE 6u26 64 bits" to "JRE 6u27 64 bits" and the exception occurs even more frequently (66% IllegalMonitorStateException, 33% Ok).
        Could someone please verify it?

        Show
        calvarez César Álvarez Núñez added a comment - With a "W7 64 bits". I've just updated from "JRE 6u26 64 bits" to "JRE 6u27 64 bits" and the exception occurs even more frequently (66% IllegalMonitorStateException, 33% Ok). Could someone please verify it?
        Hide
        calvarez César Álvarez Núñez added a comment -

        I've just downloaded "https://github.com/huxi/lbcore224" and executed it with "6u262 and "6u27" (both 64 bits) with identical result.

        $ ./gradlew
        :clean
        :compileJava UP-TO-DATE
        :processResources UP-TO-DATE
        :classes UP-TO-DATE
        :jar
        :assemble
        :compileTestJava
        :processTestResources
        :testClasses
        :test
        :check
        :build

        BUILD SUCCESSFUL

        Total time: 1 mins 44.554 secs

        I understand that "BUILD SUCCESSFUL" means that everything was compiled and test case was executed without any failure, do I?
        So... where is the main difference with my test cases running on Eclipse? TestNG?

        Show
        calvarez César Álvarez Núñez added a comment - I've just downloaded "https://github.com/huxi/lbcore224" and executed it with "6u262 and "6u27" (both 64 bits) with identical result. $ ./gradlew :clean :compileJava UP-TO-DATE :processResources UP-TO-DATE :classes UP-TO-DATE :jar :assemble :compileTestJava :processTestResources :testClasses :test :check :build BUILD SUCCESSFUL Total time: 1 mins 44.554 secs I understand that "BUILD SUCCESSFUL" means that everything was compiled and test case was executed without any failure, do I? So... where is the main difference with my test cases running on Eclipse? TestNG?
        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
        admin JIRA Administrator made changes -
        Project logback-core [ 10013 ] logback [ 10040 ]
        Key LBCORE-224 LOGBACK-120
        Affects Version/s 0.9.30 [ 10157 ]
        Component/s logback-core [ 10060 ]
        Component/s Appender [ 10022 ]
        Fix Version/s 1.0.0 [ 10172 ]

          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: