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

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

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

Hi César,

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

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

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

qU.tearDown();
}

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

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

@Test
public void test() throws Exception {
for (int i = 0; i < 10; 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]

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.

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?

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.

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)

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

}
} finally

return false;
}

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

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

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.

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

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

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.

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

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

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

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

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

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

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

}

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)

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.

Fixed in https://github.com/ceki/logback/commit/eef137b0c6ca9

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

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.

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?

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?

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

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

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.

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

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