mina-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Gunnar Wagenknecht (JIRA)" <j...@apache.org>
Subject [jira] [Comment Edited] (SSHD-152) Logging may cause deadlock.
Date Tue, 22 May 2012 13:45:40 GMT

    [ https://issues.apache.org/jira/browse/SSHD-152?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13280950#comment-13280950
] 

Gunnar Wagenknecht edited comment on SSHD-152 at 5/22/12 1:43 PM:
------------------------------------------------------------------

So maybe Karaf does? 

Here are my findings:
- Thread-21 has a lock on Object (id=202). This must be the lock object within Logback ConsoleAppender
because all other threads are waiting on this one (as is NioProcessor-2 for example).
- Thread-21 is waiting for Window (id=485) but not because of a lock but because of an Object.wait()
call on Window.
- Karaf must have replaced System.out with a ConsoleOutputStream that wraps a ChannelOutputStream
from SSHD.
- ChannelOutputStream.flush() is called recursively in Thread-21 because of the console logging.
- The formatting above is poor. In thread NioProcessor-2 it should read "waiting for Object
(id=202) which is owned by [Thread-21] which is waiting on Window (id=485)";

The situation must be as follows: Thread-21 is waiting for some other thread to free space
in the Window object (waitForSpace). This is implemented using Object.wait/notify(). However,
no other thread will ever call Window.notify because they are all stuck in ConsoleAppender
while doing some log output because the ConsoleAppender lock is held by Thread-21 which is
sleeping.
                
      was (Author: gunnar):
    So maybe Karaf does? 

Here are my findings:
- Thread-21 has a lock on Object (id=202). This must be the lock object within Logback ConsoleAppender
because all other threads are waiting on this one (as is NioProcessor-2 for example).
- Thread-21 is waiting for Window (id=485) but not because of a lock but because of an Object.wait()
call on Window.
- Karaf must have replaced System.out with a ConsoleOutputStream that wraps a ChannelOutputStream
from SSHD.
- ChannelOutputStream.flush() is called recursively in Thread-21 because of the console logging.
- The formatting above is poor. In thread NioProcessor-2 it should read "waiting for Object
(id=202) which is owned by [Thread-21] which is waiting on Window (id=485)";

The situation must be as follows: Thread-21 waiting for some other thread to free room in
the Window object (waitForSpace). This is implemented using Object.wait/notify(). However,
no other thread will ever call Window.notify because they are all stuck in ConsoleAppender
while doing some log output because the ConsoleAppender lock is held by Thread-21 which is
sleeping.
                  
> Logging may cause deadlock.
> ---------------------------
>
>                 Key: SSHD-152
>                 URL: https://issues.apache.org/jira/browse/SSHD-152
>             Project: MINA SSHD
>          Issue Type: Bug
>    Affects Versions: 0.5.0
>            Reporter: Gunnar Wagenknecht
>            Assignee: Guillaume Nodet
>
> I'm not really sure what I did but I think I somehow managed to deadlock my system using
SSHD in combination with Logback console appender.
> Thread 1
> {noformat}
> Thread [Thread-21] (Suspended)	
> 	owns: ChannelOutputStream  (id=481)	
> 	owns: ConsoleOutputStream  (id=482)	
> 	owns: PrintStream  (id=483)	
> 	owns: Object  (id=202)	
> 		waited by: Thread [...] (Suspended)	
> 		waited by: Thread [...] (Suspended)	
> 		waited by: Thread [...] (Suspended)	
> 		waited by: Thread [NioProcessor-2] (Suspended)	
> 		waited by: Thread [...] (Suspended)	
> 		waited by: Thread [...] (Suspended)	
> 		waited by: Thread [...] (Suspended)	
> 		waited by: Thread [...] (Suspended)	
> 		waited by: Thread [...] (Suspended)	
> 		waited by: Thread [...] (Suspended)	
> 	owns: OutputStreamWriter  (id=484)	
> 	waiting for: Window  (id=485)	
> 	Object.wait(long) line: not available [native method]	
> 	Window(Object).wait() line: 503	
> 	Window.waitForSpace() line: 146	
> 	ChannelOutputStream.flush() line: 104	
> 	ConsoleOutputStream.flush() line: 97	
> 	ConsoleOutputStream.write(int) line: 83	
> 	ConsoleOutputStream(OutputStream).write(byte[], int, int) line: 116	
> 	PrintStream.write(byte[], int, int) line: 480	
> 	PrintStream(FilterOutputStream).write(byte[]) line: 97	
> 	ThreadPrintStream.write(byte[]) line: 245	
> 	ConsoleTarget$1.write(byte[]) line: 36	
> 	PatternLayoutEncoder(LayoutWrappingEncoder<E>).doEncode(E) line: 103	
> 	ConsoleAppender<E>(OutputStreamAppender<E>).writeOut(E) line: 193	
> 	ConsoleAppender<E>(OutputStreamAppender<E>).subAppend(E) line: 217	
> 	ConsoleAppender<E>(OutputStreamAppender<E>).append(E) line: 108	
> 	ConsoleAppender<E>(UnsynchronizedAppenderBase<E>).doAppend(E) line: 88	
> 	AppenderAttachableImpl<E>.appendLoopOnAppenders(E) line: 64	
> 	Logger.appendLoopOnAppenders(ILoggingEvent) line: 285	
> 	Logger.callAppenders(ILoggingEvent) line: 272	
> 	Logger.buildLoggingEventAndAppend(String, Marker, Level, String, Object[], Throwable)
line: 473	
> 	Logger.filterAndLog_2(String, Marker, Level, String, Object, Object, Throwable) line:
464	
> 	Logger.debug(String, Object, Object) line: 542	
> 	ChannelOutputStream.flush() line: 119	
> 	...
> {noformat}
> Thread 2
> {noformat}
> Thread [NioProcessor-2] (Suspended)	
> 	owns: Object  (id=150)	
> 	waiting for: Object  (id=202)	
> 		owned by: Thread [Thread-21] (Suspended)	
> 			waiting for: Window  (id=485)	
> 	ConsoleAppender<E>(OutputStreamAppender<E>).subAppend(E) line: 217	
> 	ConsoleAppender<E>(OutputStreamAppender<E>).append(E) line: 108	
> 	ConsoleAppender<E>(UnsynchronizedAppenderBase<E>).doAppend(E) line: 88	
> 	AppenderAttachableImpl<E>.appendLoopOnAppenders(E) line: 64	
> 	Logger.appendLoopOnAppenders(ILoggingEvent) line: 285	
> 	Logger.callAppenders(ILoggingEvent) line: 272	
> 	Logger.buildLoggingEventAndAppend(String, Marker, Level, String, Object[], Throwable)
line: 473	
> 	Logger.filterAndLog_1(String, Marker, Level, String, Object, Throwable) line: 445	
> 	Logger.debug(String, Object) line: 538	
> 	ServerSession.handleMessage(Buffer) line: 119	
> 	...
> {noformat}
> I think that one thread is waiting for Window to expand. The SSHD logger has a console
appender. Unfortunately, the wait happends within a write by console appender. Thus all other
threads that also log to the console will block because they wait for the Logback console
appender lock.
> I think that a Logback console appender should not write to the SSHD console by default.
Can this be disabled somehow?

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira

        

Mime
View raw message