You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mina.apache.org by "Guillaume Nodet (Jira)" <ji...@apache.org> on 2020/07/19 19:43: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=17160804#comment-17160804 ]
Guillaume Nodet commented on SSHD-1020:
---------------------------------------
I don't really understand why the read timeout should cause the session to close. It looks like such exception is recoverable and we should perform the read operation again instead of closing the connection. Do you agree [~lgoldstein] ?
> 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
> Attachments: image-2020-06-26-15-18-58-509.png, image-2020-06-26-15-22-17-259.png, server.log
>
>
> 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