You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mina.apache.org by "Markus Spann (Jira)" <ji...@apache.org> on 2020/08/18 08:10:00 UTC

[jira] [Comment Edited] (SSHD-1058) ChannelOutputStream#flush should not log at error level

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

Markus Spann edited comment on SSHD-1058 at 8/18/20, 8:09 AM:
--------------------------------------------------------------

Thanks for pointing out issue SSHD-977 which I was not aware of.

I utilize sshd to offer an administrative rmi console in an application. RMI commands also get executed by scripts e.g. checking system health/status periodically.
 Every such invocation causes an error log now.
 We are being called in destroy(ChannelSession) by ChannelSession#closeImmediately0. We then go on by calling AbstractTerminal#close which ultimately gets the WindowClosedException in Window#waitForCondition.

I am wondering whether the solution is to NOT close the terminal after #destroy was called?
 (Our stackframes start with my.app.rmi)
{noformat}
2020-08-17 11:22:43,969 ERROR [sshd-pool-thread-10] server.channel.ChannelSession - flush(ChannelOutputStream[ChannelSession[id=0, recipient=0]-ServerSessionImpl[rmiadmin@/0:0:0:0:0:0:0:1:58844]] SSH_MSG_CHANNEL_DATA) wait for space len=1 exception details
org.apache.sshd.common.channel.WindowClosedException: Already closed: Window[server/remote](ChannelSession[id=0, recipient=0]-ServerSessionImpl[rmiadmin@/0:0:0:0:0:0:0:1:58844])
  at org.apache.sshd.common.channel.Window.waitForCondition(Window.java:304)
  at org.apache.sshd.common.channel.Window.waitForSpace(Window.java:255)
  at org.apache.sshd.common.channel.ChannelOutputStream.flush(ChannelOutputStream.java:197)
  at org.apache.sshd.common.channel.ChannelOutputStream.close(ChannelOutputStream.java:271)
  at org.jline.terminal.impl.LineDisciplineTerminal$FilteringOutputStream.close(LineDisciplineTerminal.java:306)
  at java.base/sun.nio.cs.StreamEncoder.implClose(StreamEncoder.java:341)
  at java.base/sun.nio.cs.StreamEncoder.close(StreamEncoder.java:161)
  at java.base/java.io.OutputStreamWriter.close(OutputStreamWriter.java:258)
  at java.base/java.io.PrintWriter.close(PrintWriter.java:415)
  at org.jline.terminal.impl.LineDisciplineTerminal.doClose(LineDisciplineTerminal.java:270)
  at org.jline.terminal.impl.ExternalTerminal.doClose(ExternalTerminal.java:89)
  at org.jline.terminal.impl.AbstractTerminal.close(AbstractTerminal.java:95)
      at my.app.rmi.server.ssh.AbstractEmbeddedShell.close(AbstractEmbeddedShell.java:569)
      at my.app.rmi.server.ssh.EmbeddedShell.close(EmbeddedShell.java:270)
      at my.app.rmi.server.ssh.AbstractEmbeddedShell.destroy(AbstractEmbeddedShell.java:515)
  at org.apache.sshd.server.channel.ChannelSession.closeImmediately0(ChannelSession.java:213)
  at org.apache.sshd.common.util.closeable.Builder$1.doClose(Builder.java:47){noformat}
 

 


was (Author: spannjp):
Thanks for pointing out issue SSHD-977 which I was not aware of.

I utilize sshd to offer an administrative rmi console in an application. RMI commands also get executed by scripts e.g. checking system health/status periodically.
Every such invocation causes an error log now.
We are being called in destroy(ChannelSession) by ChannelSession#closeImmediately0. We then go on by calling AbstractTerminal#close which ultimately gets the WindowClosedException in Window#waitForCondition.


I am wondering whether the solution is to NOT close the terminal after #destroy was called?
(Our stackframes start with my.app.rmi)

 
{noformat}
2020-08-17 11:22:43,969 ERROR [sshd-pool-thread-10] server.channel.ChannelSession - flush(ChannelOutputStream[ChannelSession[id=0, recipient=0]-ServerSessionImpl[rmiadmin@/0:0:0:0:0:0:0:1:58844]] SSH_MSG_CHANNEL_DATA) wait for space len=1 exception details
org.apache.sshd.common.channel.WindowClosedException: Already closed: Window[server/remote](ChannelSession[id=0, recipient=0]-ServerSessionImpl[rmiadmin@/0:0:0:0:0:0:0:1:58844])
  at org.apache.sshd.common.channel.Window.waitForCondition(Window.java:304)
  at org.apache.sshd.common.channel.Window.waitForSpace(Window.java:255)
  at org.apache.sshd.common.channel.ChannelOutputStream.flush(ChannelOutputStream.java:197)
  at org.apache.sshd.common.channel.ChannelOutputStream.close(ChannelOutputStream.java:271)
  at org.jline.terminal.impl.LineDisciplineTerminal$FilteringOutputStream.close(LineDisciplineTerminal.java:306)
  at java.base/sun.nio.cs.StreamEncoder.implClose(StreamEncoder.java:341)
  at java.base/sun.nio.cs.StreamEncoder.close(StreamEncoder.java:161)
  at java.base/java.io.OutputStreamWriter.close(OutputStreamWriter.java:258)
  at java.base/java.io.PrintWriter.close(PrintWriter.java:415)
  at org.jline.terminal.impl.LineDisciplineTerminal.doClose(LineDisciplineTerminal.java:270)
  at org.jline.terminal.impl.ExternalTerminal.doClose(ExternalTerminal.java:89)
  at org.jline.terminal.impl.AbstractTerminal.close(AbstractTerminal.java:95)
      at my.app.rmi.server.ssh.AbstractEmbeddedShell.close(AbstractEmbeddedShell.java:569)
      at my.app.rmi.server.ssh.EmbeddedShell.close(EmbeddedShell.java:270)
      at my.app.rmi.server.ssh.AbstractEmbeddedShell.destroy(AbstractEmbeddedShell.java:515)
  at org.apache.sshd.server.channel.ChannelSession.closeImmediately0(ChannelSession.java:213)
  at org.apache.sshd.common.util.closeable.Builder$1.doClose(Builder.java:47){noformat}
 

 

> ChannelOutputStream#flush should not log at error level
> -------------------------------------------------------
>
>                 Key: SSHD-1058
>                 URL: https://issues.apache.org/jira/browse/SSHD-1058
>             Project: MINA SSHD
>          Issue Type: Bug
>    Affects Versions: 2.5.0, 2.5.1
>         Environment: Linux, Java 11
>            Reporter: Markus Spann
>            Assignee: Lyor Goldstein
>            Priority: Minor
>
> When calling flush on ChannelOutputStream, Window.waitForSpace may throw a WindowClosedException. This exception is always logged at error level, then rethrown. If Debug is enabled on the logger, the error log is issued twice (second time with stacktrace).
> During deinitialization it is common practice to call flush on output streams. Due to the asynchronous nature of the code in this library, the call may fail. The caller should decide how to deal with the exception and log at error level if needed.
> The implementation should not log at error level regardless.
> I would suggest INFO level instead (if logging at all).
>  
> {code:java}
> // lines 202 ff.
> if (log.isDebugEnabled()) {
>     log.info("flush({}) failed ({}) to wait for space of len={}: {}: ", this, e.getClass().getSimpleName(), total, e.getMessage(), e); // with stacktrace
> } else {
>     log.info("flush({}) failed ({}) to wait for space of len={}: {}",
>  this, e.getClass().getSimpleName(), total, e.getMessage());
> }
> throw e;
> {code}
> Thanks,
> Markus
>  
>  



--
This message was sent by Atlassian Jira
(v8.3.4#803005)

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@mina.apache.org
For additional commands, e-mail: dev-help@mina.apache.org