You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mina.apache.org by "Gunnar Wagenknecht (Created) (JIRA)" <ji...@apache.org> on 2011/12/09 14:54:39 UTC
[jira] [Created] (SSHD-152) Logging may cause deadlock.
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
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
[jira] [Commented] (SSHD-152) Logging may cause deadlock.
Posted by "Guillaume Nodet (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/SSHD-152?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13280959#comment-13280959 ]
Guillaume Nodet commented on SSHD-152:
--------------------------------------
Honestly, if the use case is that the sshd log is forwarded through an ssh channel, I don't really see how we can get rid of those issue easily.
Sshd can't really know how the backing log has been configured and given it only uses slf4j, I don't really see a way to be smart enough about that.
Ideas welcomed though.
> 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
[jira] [Comment Edited] (SSHD-152) Logging may cause deadlock.
Posted by "Ceki Gulcu (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/SSHD-152?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13280913#comment-13280913 ]
Ceki Gulcu edited comment on SSHD-152 at 5/22/12 12:50 PM:
-----------------------------------------------------------
All Appenders have a guard ensuring recursive calls by an appender to itself have not effect. (If my memory serves me correctly, log4j has a similar protection mechanism.) Thus, the scenario described by Guillaume should not occur. Of course, Guillaume still makes a valid point about not using the console to log events about... the console.
Anyway, I am still studying the lockup which I don't really understand yet. In particular I fail to see who owns "Window (id=485)".
was (Author: ceki@qos.ch):
All Appenders have a guard ensuring recursive calls by an appender to itself have not effect. (If my memory serves me correctly, log4j has a similar protection mechanism.) Thus, the scenario described by Guillaume should not occur. Of course, Guillaume still makes a valid point about not using the console to log events about... the console.
Anyway, I am still studying the lockup which I don't really understand yet.
> 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
[jira] [Comment Edited] (SSHD-152) Logging may cause deadlock.
Posted by "Gunnar Wagenknecht (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/SSHD-152?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13280076#comment-13280076 ]
Gunnar Wagenknecht edited comment on SSHD-152 at 5/21/12 10:52 AM:
-------------------------------------------------------------------
I share your point about best practices. However, I'm really concerned that an administrator runs into the issue. Administrative folks can't be aware of any side effects that may or may not exist in any combination of log-level settings. They tend to enable higher output when analyzing issues without knowing such side-effects.
I think that SSHD should be very careful and add a protection especially when it interacts with streams like System.out/System.err that may be used by many other libs in a system.
Also, I'm not sure if the issue is really a concurrency issue or may be cause be recursive invocation of ChannelOutputStream.flush() line: 119. Does SSHD wrap/replace System.out?
was (Author: gunnar):
I share your point about best practices. However, I'm really concerned that an administrator runs into the issue. Administrative folks can't be aware of any side effects that may or may not exist in any combination of log-level settings. They tend to enable higher output when analyzing issues without knowing such side-effects.
I think that SSHD should be very careful and add a protection especially when it interacts with streams like System.out/System.err that may be used by many other libs in a system.
Also, I'm not sure if the issue is really a concurrency issue or may be cause be recursive invocation of {{ChannelOutputStream.flush() line: 119}}. Does SSHD wrap/replace {{System.out}}?
> 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
[jira] [Reopened] (SSHD-152) Logging may cause deadlock.
Posted by "Gunnar Wagenknecht (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/SSHD-152?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Gunnar Wagenknecht reopened SSHD-152:
-------------------------------------
I share your point about best practices. However, I'm really concerned that an administrator runs into the issue. Administrative folks can't be aware of any side effects that may or may not exist in any combination of log-level settings. They tend to enable higher output when analyzing issues without knowing such side-effects.
I think that SSHD should be very careful and add a protection especially when it interacts with streams like System.out/System.err that may be used by many other libs in a system.
Also, I'm not sure if the issue is really a concurrency issue or may be cause be recursive invocation of {{ChannelOutputStream.flush() line: 119}}. Does SSHD wrap/replace {{System.out}}?
> 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
[jira] [Commented] (SSHD-152) Logging may cause deadlock.
Posted by "Gunnar Wagenknecht (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/SSHD-152?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13280950#comment-13280950 ]
Gunnar Wagenknecht commented on SSHD-152:
-----------------------------------------
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.
- 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
[jira] [Commented] (SSHD-152) Logging may cause deadlock.
Posted by "Gunnar Wagenknecht (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/SSHD-152?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13280981#comment-13280981 ]
Gunnar Wagenknecht commented on SSHD-152:
-----------------------------------------
{quote}
Honestly, if the use case is that the sshd log is forwarded through an ssh channel, I don't really see how we can get rid of those issue easily.
{quote}
Frankly, that wasn't the use case. Logback is configured to log to System.out.But for some reason some other component (Karaf?) switched System.out to the sshd channel.
> 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
[jira] [Resolved] (SSHD-152) Logging may cause deadlock.
Posted by "Guillaume Nodet (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/SSHD-152?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Guillaume Nodet resolved SSHD-152.
----------------------------------
Resolution: Won't Fix
Not sure if there's much to do here.
> 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
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Resolved] (SSHD-152) Logging may cause deadlock.
Posted by "Guillaume Nodet (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/SSHD-152?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Guillaume Nodet resolved SSHD-152.
----------------------------------
Resolution: Won't Fix
Assignee: Guillaume Nodet
Having sshd log send through the same sshd server to a client is quite a bad idea. You may also end up in infinite log generation because sending some data will generate more logs and so on.
The best idea in that case it to make sure that the underlying logging framework (logback in your case) is configured to log sshd events at info level, or to a file, but not to the console for example.
> 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
[jira] [Commented] (SSHD-152) Logging may cause deadlock.
Posted by "Ceki Gulcu (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/SSHD-152?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13280913#comment-13280913 ]
Ceki Gulcu commented on SSHD-152:
---------------------------------
All Appenders have a guard ensuring recursive calls by an appender to itself have not effect. (If my memory serves me correctly, log4j has a similar protection mechanism.) Thus, the scenario described by Guillaume should not occur. Of course, Guillaume still makes a valid point about not using the console to log events about... the console.
Anyway, I am still studying the lockup which I don't really understand yet.
> 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
[jira] [Comment Edited] (SSHD-152) Logging may cause deadlock.
Posted by "Gunnar Wagenknecht (JIRA)" <ji...@apache.org>.
[ 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
[jira] [Commented] (SSHD-152) Logging may cause deadlock.
Posted by "Guillaume Nodet (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/SSHD-152?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13280962#comment-13280962 ]
Guillaume Nodet commented on SSHD-152:
--------------------------------------
And even if we could fix the deadlock, the problem is that it will generate an infinite log queue, because at debug level, each ssh message sent will generate a few more log entries, and it will loop forever.
> 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
[jira] [Comment Edited] (SSHD-152) Logging may cause deadlock.
Posted by "Gunnar Wagenknecht (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/SSHD-152?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13280981#comment-13280981 ]
Gunnar Wagenknecht edited comment on SSHD-152 at 5/22/12 2:17 PM:
------------------------------------------------------------------
{quote}
Honestly, if the use case is that the sshd log is forwarded through an ssh channel, I don't really see how we can get rid of those issue easily.
{quote}
Frankly, that wasn't the use case. Logback is configured to log to System.out.But for some reason some other component (Karaf?) switched System.out to the sshd channel.
{quote}
Ideas welcomed though.
{quote}
I think the safest option would be that sshd somehow is able to detect that logging is indirectly wired to the same ChannelOutputStream and then skip all logging events in such a case. But I'm afraid that none is possible in a clean way without sshd knowing details about the environment (Karaf + Logback).
was (Author: gunnar):
{quote}
Honestly, if the use case is that the sshd log is forwarded through an ssh channel, I don't really see how we can get rid of those issue easily.
{quote}
Frankly, that wasn't the use case. Logback is configured to log to System.out.But for some reason some other component (Karaf?) switched System.out to the sshd channel.
> 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
[jira] [Comment Edited] (SSHD-152) Logging may cause deadlock.
Posted by "Gunnar Wagenknecht (JIRA)" <ji...@apache.org>.
[ 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:42 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 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.
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.
- 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
[jira] [Commented] (SSHD-152) Logging may cause deadlock.
Posted by "Guillaume Nodet (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/SSHD-152?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13280923#comment-13280923 ]
Guillaume Nodet commented on SSHD-152:
--------------------------------------
Sshd does not wrap/replace any system stream. I'm mostly using sshd inside Karaf, which does so, so I was assuming that was the root problem.
It would be nice if you could get a full stack trace so that we could look at it more closely.
> 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