You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mina.apache.org by "Lyor Goldstein (Jira)" <ji...@apache.org> on 2020/06/22 15:59:00 UTC
[jira] [Commented] (SSHD-1020) SSH connections getting closed
abruptly with timeout exceptions.
java.nio.channels.InterruptedByTimeoutException
[ https://issues.apache.org/jira/browse/SSHD-1020?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17142220#comment-17142220 ]
Lyor Goldstein commented on SSHD-1020:
--------------------------------------
The version reported in this issue (2.2.0) is old - please try the newly released 2.5.0 and see if you can reproduce the issue. In any case, the attached log snippet seems to indicate that some read/write timeout expires - e.g., no traffic, very high latency, etc... These timeout can be configured + can turn on keep-alive mechanism. Please read the documentation at https://github.com/apache/mina-sshd/
> SSH connections getting closed abruptly with timeout exceptions. java.nio.channels.InterruptedByTimeoutException
> ----------------------------------------------------------------------------------------------------------------
>
> Key: SSHD-1020
> URL: https://issues.apache.org/jira/browse/SSHD-1020
> Project: MINA SSHD
> Issue Type: Bug
> Affects Versions: 2.2.0
> Reporter: Sivanagarajup
> Priority: Blocker
>
> Hi Team
> SSH sessions are closing with timeout exceptions as mentioned below
> {code:java}
> 2020-06-18 03:07:11,942 DEBUG [org.apache.sshd.common.io.nio2.Nio2Session] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) exceptionCaught(Nio2Session[local=/10.1.2.3:8345, remote=/20.24.16.108:41480]) caught InterruptedByTimeoutException[null] - calling handler2020-06-18 03:07:11,942 DEBUG [org.apache.sshd.common.io.nio2.Nio2Session] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) exceptionCaught(Nio2Session[local=/10.1.2.3:8345, remote=/20.24.16.108:41480]) caught InterruptedByTimeoutException[null] - calling handler2020-06-18 03:07:11,943 WARN [org.apache.sshd.server.session.ServerSessionImpl] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) exceptionCaught(ServerSessionImpl[clientNBI@/20.24.16.108:41480])[state=Opened] InterruptedByTimeoutException: null2020-06-18 03:07:11,943 DEBUG [org.apache.sshd.server.session.ServerSessionImpl] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) exceptionCaught(ServerSessionImpl[clientNBI@/20.24.16.108:41480])[state=Opened] details: java.nio.channels.InterruptedByTimeoutException at sun.nio.ch.UnixAsynchronousSocketChannelImpl$1.run(UnixAsynchronousSocketChannelImpl.java:456) [rt.jar:1.8.0_231] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [rt.jar:1.8.0_231] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [rt.jar:1.8.0_231] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [rt.jar:1.8.0_231] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [rt.jar:1.8.0_231] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [rt.jar:1.8.0_231] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [rt.jar:1.8.0_231] at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_231]
> 2020-06-18 03:07:11,945 DEBUG [org.apache.sshd.common.session.helpers.SessionTimeoutListener] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) sessionException(ServerSessionImpl[clientNBI@/20.24.16.108:41480]) InterruptedByTimeoutException: null2020-06-18 03:07:11,945 TRACE [org.apache.sshd.common.session.helpers.SessionTimeoutListener] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) sessionException(ServerSessionImpl[clientNBI@/20.24.16.108:41480]) details: java.nio.channels.InterruptedByTimeoutException at sun.nio.ch.UnixAsynchronousSocketChannelImpl$1.run(UnixAsynchronousSocketChannelImpl.java:456) [rt.jar:1.8.0_231] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [rt.jar:1.8.0_231] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [rt.jar:1.8.0_231] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [rt.jar:1.8.0_231] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [rt.jar:1.8.0_231] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [rt.jar:1.8.0_231] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [rt.jar:1.8.0_231] at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_231]
> 2020-06-18 03:07:11,946 DEBUG [org.apache.sshd.common.session.helpers.SessionTimeoutListener] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) sessionClosed(ServerSessionImpl[clientNBI@/20.24.16.108:41480]) un-tracked2020-06-18 03:07:11,946 DEBUG [org.apache.sshd.server.session.ServerSessionImpl] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) close(ServerSessionImpl[clientNBI@/20.24.16.108:41480]) Closing immediately2020-06-18 03:07:11,946 TRACE [org.apache.sshd.common.session.helpers.SessionTimeoutListener] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) sessionClosed(ServerSessionImpl[clientNBI@/20.24.16.108:41480]) not tracked2020-06-18 03:07:11,946 TRACE [org.apache.sshd.common.util.closeable.SequentialCloseable] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) doClose(true) closing org.apache.sshd.common.util.closeable.ParallelCloseable@a0279422020-06-18 03:07:11,946 TRACE [org.apache.sshd.common.util.closeable.ParallelCloseable] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) doClose(true) pending closeables: 22020-06-18 03:07:11,946 DEBUG [org.apache.sshd.server.session.ServerConnectionService] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) close(ServerConnectionService[ServerSessionImpl[clientNBI@/20.24.16.108:41480]]) Closing immediately2020-06-18 03:07:11,947 TRACE [org.apache.sshd.common.util.closeable.ParallelCloseable] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) doClose(true) pending closeables: 22020-06-18 03:07:11,947 DEBUG [org.apache.sshd.server.channel.ChannelSession] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) close(ChannelSession[id=0, recipient=0]-ServerSessionImpl[clientNBI@/20.24.16.108:41480]) Closing immediately2020-06-18 03:07:11,947 DEBUG [org.apache.sshd.server.channel.ChannelSession] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) close(ChannelSession[id=0, recipient=0]-ServerSessionImpl[clientNBI@/20.24.16.108:41480]) prevent sending EOF2020-06-18 03:07:11,947 DEBUG [org.apache.sshd.common.channel.Window] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) Closing Window[server/local](ChannelSession[id=0, recipient=0]-ServerSessionImpl[clientNBI@/20.24.16.108:41480])2020-06-18 03:07:11,947 DEBUG [org.apache.sshd.common.channel.Window] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) Closing Window[server/remote](ChannelSession[id=0, recipient=0]-ServerSessionImpl[clientNBI@/20.24.16.108:41480])2020-06-18 03:07:11,948 TRACE [org.apache.sshd.common.util.closeable.SequentialCloseable] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) doClose(true) closing org.apache.sshd.server.channel.ChannelSession$CommandCloseable@662e3d1e2020-06-18 03:07:11,948 TRACE [org.apache.sshd.common.util.closeable.SequentialCloseable] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) doClose(true) closing org.apache.sshd.common.util.closeable.SequentialCloseable@da00d8f2020-06-18 03:07:11,948 TRACE [org.apache.sshd.common.util.closeable.SequentialCloseable] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) doClose(true) closing GracefulChannelCloseable[ChannelSession[id=0, recipient=0]-ServerSessionImpl[clientNBI@/20.24.16.108:41480]]2020-06-18 03:07:11,948 DEBUG [org.apache.sshd.common.channel.AbstractChannel$GracefulChannelCloseable] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) close(ChannelSession[id=0, recipient=0]-ServerSessionImpl[clientNBI@/20.24.16.108:41480])[immediately=true] processing2020-06-18 03:07:11,948 TRACE [org.apache.sshd.common.util.closeable.SequentialCloseable] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) doClose(true) closing org.apache.sshd.common.util.closeable.Builder$1@73992fa72020-06-18 03:07:11,948 DEBUG [org.apache.sshd.server.session.ServerConnectionService] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) unregisterChannel(ChannelSession[id=0, recipient=0]-ServerSessionImpl[clientNBI@/20.24.16.108:41480]) result=ChannelSession[id=0, recipient=0]-ServerSessionImpl[clientNBI@/20.24.16.108:41480]2020-06-18 03:07:11,948 DEBUG [org.apache.sshd.common.util.closeable.SequentialCloseable] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) doClose(true) signal close complete2020-06-18 03:07:11,948 TRACE [org.apache.sshd.common.util.closeable.SequentialCloseable] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) doClose(true) closing org.apache.sshd.common.util.closeable.ParallelCloseable@6a4880ff2020-06-18 03:07:11,948 TRACE [org.apache.sshd.common.util.closeable.ParallelCloseable] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) doClose(true) completed pending: 02020-06-18 03:07:11,948 TRACE [org.apache.sshd.common.util.closeable.SequentialCloseable] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) doClose(true) closing org.apache.sshd.common.util.closeable.Builder$1@7d1986652020-06-18 03:07:11,949 DEBUG [org.apache.sshd.server.channel.ChannelSession] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) closeShell(ChannelSession[id=0, recipient=0]-ServerSessionImpl[clientNBI@/20.24.16.108:41480]) exit code=-12020-06-18 03:07:11,949 DEBUG [org.apache.sshd.server.channel.ChannelSession] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) onExit(ChannelSession[id=0, recipient=0]-ServerSessionImpl[clientNBI@/20.24.16.108:41480]) code=-1 message='' shell closed2020-06-18 03:07:11,949 TRACE [org.apache.sshd.server.channel.ChannelSession] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) close(ChannelOutputStream[ChannelSession[id=0, recipient=0]-ServerSessionImpl[clientNBI@/20.24.16.108:41480]] SSH_MSG_CHANNEL_DATA) closing2020-06-18 03:07:11,949 TRACE [org.apache.sshd.server.channel.ChannelSession] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) close(ChannelOutputStream[ChannelSession[id=0, recipient=0]-ServerSessionImpl[clientNBI@/20.24.16.108:41480]] SSH_MSG_CHANNEL_EXTENDED_DATA) closing2020-06-18 03:07:11,950 DEBUG [org.apache.sshd.server.channel.ChannelSession] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) doCloseImmediately(ChannelSession[id=0, recipient=0]-ServerSessionImpl[clientNBI@/20.24.16.108:41480]) failed (SshChannelClosedException) to close resources: flush(ChannelOutputStream[ChannelSession[id=0, recipient=0]-ServerSessionImpl[clientNBI@/20.24.16.108:41480]] SSH_MSG_CHANNEL_DATA) length=0 - stream is already closed2020-06-18 03:07:11,950 DEBUG [org.apache.sshd.server.channel.ChannelSession] (pool-7-thread-757) closeShell(ChannelSession[id=0, recipient=0]-ServerSessionImpl[clientNBI@/20.24.16.108:41480]) exit code=02020-06-18 03:07:11,950 TRACE [org.apache.sshd.server.channel.ChannelSession] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) Suppressed SshChannelClosedException) while close immediately resource(s) of ChannelSession[id=0, recipient=0]-ServerSessionImpl[clientNBI@/20.24.16.108:41480]: flush(ChannelOutputStream[ChannelSession[id=0, recipient=0]-ServerSessionImpl[clientNBI@/20.24.16.108:41480]] SSH_MSG_CHANNEL_EXTENDED_DATA) length=0 - stream is already closed2020-06-18 03:07:11,951 DEBUG [org.apache.sshd.common.util.closeable.SequentialCloseable] (sshd-SshServer[6c96892e](port=8345)-nio2-thread-1) doClose(true) signal close complete
> {code}
> Could you please help us what cause the issue and how to evaluate this?
>
> Thanks
> Siva
--
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