Hi, Unfortunately not, we cannot reproduce it but we have the strong feeling this is about out of memory as you mentioned. Regards, Zoltan Szel Morgan Stanley | IDEAS Practice Areas Lechner Odon fasor 8 | Floor 07 Budapest, 1095 Phone: +36 1 881-3978 Zoli.Szel@MorganStanley.com -----Original Message----- From: Ceki Gulcu [mailto:ceki@qos.ch] Sent: Monday, February 02, 2009 11:17 PM To: logback developers list Subject: Re: [logback-dev] IllegalMonitorStateException in AppenderAttachableImpl.appendLoopOnAppenders() Any luck reproducing this issue? Ceki Gulcu wrote:

Hello Zoltan,

Looking at this exception and related code in AppenderAttachableImpl, moving the r.lock(); statement outside of the try block will not change anything because I believe that r.lock() does not throw exceptions. However, looking at ReentrantReadWriteLock.ReadLock class' lock() method, one is directed to the ReentrantReadWriteLock.Sync class and its acquireShared() method. If this method fails to acquire the lock due to a RuntimeException, then the subsequent r.unlock() call will fail with an IllegalMonitorStateException. In any case, r.lock() will not throw an exception since the exception is absorbed by the sync.acquireShared method.

It would be quite helpful if you were able to reproduce the problem.

We could place the r.unlock() invocation within a try/catch block (absorbing the IllegalMonitorStateException you got). However, this is may only obfuscate the real cause of the problem, that is an OutOfMemoryException or such. We could also imagine that there is a bug in ReentrantReadWriteLock. Given its complexity, it's not such an outlandish hypothesis.

Otherwise, the only remaining possibility is a bug in logback. But we all know that is impossible.

More seriously, I think this bug will be hard to nail down.

Szel, Zoltan (IDEAS) wrote:

...

Hi,

We have hit the exception mentioned in the subject in one of our applications. We are using JDK 6 and Logback 0.9.14. Here is the stacktrace:

Caused by: java.lang.IllegalMonitorStateException at java.util.concurrent.locks.ReentrantReadWriteLock$Sync.tryReleaseShared(ReentrantReadWriteLock.java:363)

at java.util.concurrent.locks.AbstractQueuedSynchronizer.releaseShared(AbstractQueuedSynchronizer.java:1253)

at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.unlock(ReentrantReadWriteLock.java:745)

at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:64)

at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:439) at ch.qos.logback.classic.Logger.filterAndLog_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504)

I have checked the code and it seems to me this can only happen if the readLock.lock() method throws an exception:

*public* *int* appendLoopOnAppenders(E e) {

56 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#56> *int* size = 0;

57 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#57> *try* {

58 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#58> r.lock();

59 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#59> *for* (Appender<E> appender : appenderList) {

60 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#60> appender.doAppend(e);

61 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#61> size++;

62 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#62> }

63 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#63> } *finally* {

64 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#64> r.unlock();

65 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#65> }

66 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#66> *return* size;

67 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#67> }

if r.lock() in line 58 throws an exception for some reason than in the finally block the unlock will throw also an exception which will hide the original one. I cannot see any other reason why the unlock would throw this exception in this scenario. I am not yet able to reproduce it, but I thought this exception worth a mail. The only suggestion I have for now is to move the r.lock() call out of the try block, because if that is the bad guy, than we would have the original exception propagated.

If I have more information on this issue I will update this thread.

Regards,

Zoltan Szel *Morgan Stanley | IDEAS PRACTICE AREAS *Lechner Odon fasor 8 | Floor 07 Budapest, 1095 Phone: +36 1 881-3978 Zoli.Szel@MorganStanley.com <mailto:Zoli.Szel@MorganStanley.com>

------------------------------------------------------------------------

NOTICE: If received in error, please destroy and notify sender. Sender does not intend to waive confidentiality or privilege. Use of this email is prohibited when received in error.

------------------------------------------------------------------------

_______________________________________________ logback-dev mailing list logback-dev@qos.ch http://qos.ch/mailman/listinfo/logback-dev

-- Ceki Gülcü Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch -------------------------------------------------------------------------- NOTICE: If received in error, please destroy and notify sender. Sender does not intend to waive confidentiality or privilege. Use of this email is prohibited when received in error.

Hi, I agree with Maarten, if the r.lock() call would be outside the try block than the original exception would be propagated. Having a look at the RWDictionary example in the javadocs of ReentrantReadWriteLock(http://java.sun.com/javase/6/docs/api/java/util/concurrent/locks/ReentrantRe...), they have the call to the lock() method outside of the try block. Regards, Zoltan Szel Morgan Stanley | IDEAS Practice Areas Lechner Odon fasor 8 | Floor 07 Budapest, 1095 Phone: +36 1 881-3978 Zoli.Szel@MorganStanley.com<mailto:Zoli.Szel@MorganStanley.com> From: logback-dev-bounces@qos.ch [mailto:logback-dev-bounces@qos.ch] On Behalf Of Maarten Bosteels Sent: Tuesday, February 03, 2009 2:34 PM To: logback developers list Subject: Re: [logback-dev] IllegalMonitorStateException inAppenderAttachableImpl.appendLoopOnAppenders() Hello, I think moving r.lock(); outside of the try block WILL help, because the original exception will no longer be hidden.

Looking at this exception and related code in AppenderAttachableImpl, moving the r.lock(); statement outside of the try block will not change anything because I believe that r.lock() does not throw exceptions. However, looking at ReentrantReadWriteLock. ReadLock class' lock() method, one is directed to the ReentrantReadWriteLock.Sync class and its acquireShared() method. If this method fails to acquire the lock due to a RuntimeException, then the subsequent r.unlock() call will fail with an IllegalMonitorStateException.

but if I understand correctly there will be no subsequent call to r.unlock in this case ?? public int appendLoopOnAppenders(E e) { int size = 0; r.lock(); try { for (Appender<E> appender : appenderList) { appender.doAppend(e); size++; } } finally { r.unlock(); } return size; } Noiw, when r.lock() throws a RuntimeException, this one will be propagated to the caller, and we don't reach r.unlock(), right ? Maarten In any case,

r.lock() will not throw an exception since the exception is absorbed by the sync.acquireShared method.

On Tue, Feb 3, 2009 at 12:43 PM, Szel, Zoltan (IDEAS) <Zoli.Szel@morganstanley.com<mailto:Zoli.Szel@morganstanley.com>> wrote: Hi, Unfortunately not, we cannot reproduce it but we have the strong feeling this is about out of memory as you mentioned. Regards, Zoltan Szel Morgan Stanley | IDEAS Practice Areas Lechner Odon fasor 8 | Floor 07 Budapest, 1095 Phone: +36 1 881-3978 Zoli.Szel@MorganStanley.com -----Original Message----- From: Ceki Gulcu [mailto:ceki@qos.ch<mailto:ceki@qos.ch>] Sent: Monday, February 02, 2009 11:17 PM To: logback developers list Subject: Re: [logback-dev] IllegalMonitorStateException in AppenderAttachableImpl.appendLoopOnAppenders() Any luck reproducing this issue? Ceki Gulcu wrote:

Hello Zoltan,

Looking at this exception and related code in AppenderAttachableImpl, moving the r.lock(); statement outside of the try block will not change anything because I believe that r.lock() does not throw exceptions. However, looking at ReentrantReadWriteLock.ReadLock class' lock() method, one is directed to the ReentrantReadWriteLock.Sync class and its acquireShared() method. If this method fails to acquire the lock due to a RuntimeException, then the subsequent r.unlock() call will fail with an IllegalMonitorStateException. In any case, r.lock() will not throw an exception since the exception is absorbed by the sync.acquireShared method.

It would be quite helpful if you were able to reproduce the problem.

We could place the r.unlock() invocation within a try/catch block (absorbing the IllegalMonitorStateException you got). However, this is may only obfuscate the real cause of the problem, that is an OutOfMemoryException or such. We could also imagine that there is a bug in ReentrantReadWriteLock. Given its complexity, it's not such an outlandish hypothesis.

Otherwise, the only remaining possibility is a bug in logback. But we all know that is impossible.

More seriously, I think this bug will be hard to nail down.

Szel, Zoltan (IDEAS) wrote:

...

Hi,

We have hit the exception mentioned in the subject in one of our applications. We are using JDK 6 and Logback 0.9.14. Here is the stacktrace:

Caused by: java.lang.IllegalMonitorStateException at java.util.concurrent.locks.ReentrantReadWriteLock$Sync.tryReleaseShared(ReentrantReadWriteLock.java:363)

at java.util.concurrent.locks.AbstractQueuedSynchronizer.releaseShared(AbstractQueuedSynchronizer.java:1253)

at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.unlock(ReentrantReadWriteLock.java:745)

at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:64)

at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:439) at ch.qos.logback.classic.Logger.filterAndLog_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504)

I have checked the code and it seems to me this can only happen if the readLock.lock() method throws an exception:

*public* *int* appendLoopOnAppenders(E e) {

56 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#56> *int* size = 0;

57 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#57> *try* {

58 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#58> r.lock();

59 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#59> *for* (Appender<E> appender : appenderList) {

60 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#60> appender.doAppend(e);

61 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#61> size++;

62 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#62> }

63 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#63> } *finally* {

64 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#64> r.unlock();

65 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#65> }

66 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#66> *return* size;

67 <http://logback.qos.ch/xref/ch/qos/logback/core/spi/AppenderAttachableImpl.html#67> }

if r.lock() in line 58 throws an exception for some reason than in the finally block the unlock will throw also an exception which will hide the original one. I cannot see any other reason why the unlock would throw this exception in this scenario. I am not yet able to reproduce it, but I thought this exception worth a mail. The only suggestion I have for now is to move the r.lock() call out of the try block, because if that is the bad guy, than we would have the original exception propagated.

If I have more information on this issue I will update this thread.

Regards,

Zoltan Szel *Morgan Stanley | IDEAS PRACTICE AREAS *Lechner Odon fasor 8 | Floor 07 Budapest, 1095 Phone: +36 1 881-3978 Zoli.Szel@MorganStanley.com <mailto:Zoli.Szel@MorganStanley.com<mailto:Zoli.Szel@MorganStanley.com>>

------------------------------------------------------------------------

NOTICE: If received in error, please destroy and notify sender. Sender does not intend to waive confidentiality or privilege. Use of this email is prohibited when received in error.

------------------------------------------------------------------------

_______________________________________________ logback-dev mailing list logback-dev@qos.ch http://qos.ch/mailman/listinfo/logback-dev

-- Ceki Gülcü Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch -------------------------------------------------------------------------- NOTICE: If received in error, please destroy and notify sender. Sender does not intend to waive confidentiality or privilege. Use of this email is prohibited when received in error. _______________________________________________ logback-dev mailing list logback-dev@qos.ch http://qos.ch/mailman/listinfo/logback-dev -------------------------------------------------------------------------- NOTICE: If received in error, please destroy and notify sender. Sender does not intend to waive confidentiality or privilege. Use of this email is prohibited when received in error.

Hi Maarteen, Maarten Bosteels wrote:

Hello,

I think moving r.lock(); outside of the try block WILL help, because the original exception will no longer be hidden.

Moving r.lock() outside the try block MAY help because the finally block which throws a related but distinct exception will no longer be invoked. The second exception effectively hides the first exception. However, this is true if r.lock() throws an exception *visible* in logback code. I tend to think, for reasons explained in my previous post, that somewhere within r.lock() call there is a RuntimeException thrown but which is absorbed somewhere within the r.lock() invocation. So, there is a good chance (but less than 100%) that displacing the r.lock() call to outside the try block will *not* reveal anything new. Having said that, if for one reason or another, the r.lock() call throws an exception, which it certainly does, even if it is not visible, there is arguably no point in calling r.unlock(). Calling r.lock() outside the try block MAY reveal the original exception without having a downside. On the other hand, if calling r.unlock has a positive side-effect even if r.lock() fails, then moving r.lock() outside the try block may not be such a good idea after all. To summarize, although not guaranteed, there is a good chance that moving the r.lock() call outside the try block will reveal new information. However, this change may be problematic in certain cases, which at this time we can only imagine but not pinpoint to. In Rumsfeld-speak, moving r.lock has a known but uncertain positive effect and uncertain and unknown negative effects. Alternatively, we could invoke r.unlock in a safe manner, that is within a try/catch block (embedded within finally). This would not obfuscate the first exception and would ensure that r.unlock is always invoked. I am not sure splitting hairs as demonstrated above gets us any closer to a solution. Zoltan, do you need any specific help from my side? -- Ceki Gülcü Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch

Hi Joern, By "hair splitting", I was not referring to Maartens' message but to mine. Anyway, I think you have made the case for moving the r.lock() invocation out of the try block very convincingly. I'll commit the relevant change shortly. Thank you for your highly valuable input. Joern Huxhorn wrote:

Hi Ceki,

On 03.02.2009, at 17:54, Ceki Gulcu wrote:

...

Hi Maarteen,

Maarten Bosteels wrote:

...

Hello, I think moving r.lock(); outside of the try block WILL help, because the original exception will no longer be hidden.

Even though I hate being a smart ass and I also don't like to say something like "See, I said so", I have to do just that.

This is exactly what I meant when I wrote "It's generally a very bad idea to save a bit of standard code just because a possible problem isn't imaginable at the moment. I'm not even sure if the code without try {} finally {} will execute faster or if there won't be any difference at all. " in http://jira.qos.ch/browse/LBCORE-67 and is also the prime reason why I submitted the ticket in the first place.

The documentation of the Lock interface at http://java.sun.com/javase/6/docs/api/java/util/concurrent/locks/Lock.html clearly states: <quote> With this increased flexibility comes additional responsibility. The absence of block-structured locking removes the automatic release of locks that occurs with synchronized methods and statements. In most cases, the following idiom should be used:

Lock l = ...; l.lock(); try { // access the resource protected by this lock } finally { l.unlock(); } </quote> The "should" is only there because there might be an obscure case where a different pattern would probably be helpful - and this isn't such a case.

...

Moving r.lock() outside the try block MAY help because the finally block which throws a related but distinct exception will no longer be invoked. The second exception effectively hides the first exception. However, this is true if r.lock() throws an exception *visible* in logback code. I tend to think, for reasons explained in my previous post, that somewhere within r.lock() call there is a RuntimeException thrown but which is absorbed somewhere within the r.lock() invocation. So, there is a good chance (but less than 100%) that displacing the r.lock() call to outside the try block will *not* reveal anything new.

The documentation of the lock() method at http://java.sun.com/javase/6/docs/api/java/util/concurrent/locks/Lock.html#l...) states:

<quote> Implementation Considerations

A Lock implementation may be able to detect erroneous use of the lock, such as an invocation that would cause deadlock, and may throw an (unchecked) exception in such circumstances. The circumstances and the exception type must be documented by that Lock implementation. </quote>

Furthermore, the documentation of ReentrantReadWriteLock (the one used in AppenderAttachableImpl) at http://java.sun.com/javase/6/docs/api/java/util/concurrent/locks/ReentrantRe... does actually document a case where exactly such a scenario happens: <quote> Implementation Notes

This lock supports a maximum of 65535 recursive write locks and 65535 read locks. Attempts to exceed these limits result in Error throws from locking methods. </quote>

While this most likely isn't the case here it certainly illustrates one thing: Just stick to the pattern.

...

Having said that, if for one reason or another, the r.lock() call throws an exception, which it certainly does, even if it is not visible, there is arguably no point in calling r.unlock(). Calling r.lock() outside the try block MAY reveal the original exception without having a downside.

It will.

...

On the other hand, if calling r.unlock has a positive side-effect even if r.lock() fails, then moving r.lock() outside the try block may not be such a good idea after all.

It won't have a positive effect because it would be - in fact - an undocumented behavior and that is *never* something to desire.

lock() does only throw an unchecked exception if it couldn't acquire the lock (for one reason or another) while unlock() throws the exception mentioned in the subject if the lock is not held (see http://java.sun.com/javase/6/docs/api/java/util/concurrent/locks/ReentrantRe...) ).

...

To summarize, although not guaranteed, there is a good chance that moving the r.lock() call outside the try block will reveal new information. However, this change may be problematic in certain cases, which at this time we can only imagine but not pinpoint to. In Rumsfeld-speak, moving r.lock has a known but uncertain positive effect and uncertain and unknown negative effects.

Everything is perfectly documented and defined. This is mainly caused by the fact that java.util.concurrent was created by Doug Lea and this guy really knows what he's doing. His book on concurrency is quite excellent. Beside that, I dislike Rumsfeld ;)

...

Alternatively, we could invoke r.unlock in a safe manner, that is within a try/catch block (embedded within finally). This would not obfuscate the first exception and would ensure that r.unlock is always invoked.

I am not sure splitting hairs as demonstrated above gets us any closer to a solution. Zoltan, do you need any specific help from my side?

I fail to see the hairsplitting in Maartens message and I agree with him.

Instead of invoking unlock and circumventing the built in security measures using try{...}catch(Throwable){} we should just use the Lock as defined in the API.

Sorry for being nosy, Joern.

-- Ceki Gülcü Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch