[logback-dev] IllegalMonitorStateException in AppenderAttachableImpl.appendLoopOnAppenders()

[Ceki Gulcu]

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 at MorganStanley.com <mailto:Zoli.Szel at 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 at 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