[ https://issues.apache.org/jira/browse/SSHD-1020?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17147391#comment-17147391 ]
Lyor Goldstein edited comment on SSHD-1020 at 6/28/20, 5:10 PM: ---------------------------------------------------------------- {quote} It took exactly 10 mins 15 secs to close the session even we sent packets in between I am suspecting my issue is related to this ticket https://issues.apache.org/jira/browse/SSHD-901 {quote} I tend to agree - it was what my instinct was telling me {quote} I have gone through this ticket but i am not able to understand what is the solution you provided for this. If my issues is matches with above ticket can you please suggest the solution for it. {quote} Server side heartbeat has no standard implementation. MINA SSHD server provides such a mechanism (see [Providing server-side heartbeat|https://github.com/apache/mina-sshd/blob/master/docs/server-setup.md#providing-server-side-heartbeat]. Note though that it is guaranteed to work only if the client is also MINA SSHD. Otherwise, it might or might not work. Furthermore, if the server in your setup is not MINA SSHD, then you are out of luck.... {quote} What we understood is "nio2-read-timeout" is not resetting even if server sends packets {quote} I believe this is incorrect - the timeout is implicitly "reset" by calling {{doReadCycle}} with it every time after a packet has been received. If it were true, then we would have seen active sessions time out as well - which we do do. Seems that the problem is that you are maintaining a "silent" client session with the server with no or very little traffic. Your challenge is to make sure you generate traffic from the server towards the client (the client heartbeat takes care of the other direction)... was (Author: lgoldstein): {quote} It took exactly 10 mins 15 secs to close the session even we sent packets in between I am suspecting my issue is related to this ticket https://issues.apache.org/jira/browse/SSHD-901 {quote} I then to agree - it was what my instinct was telling me {quote} I have gone through this ticket but i am not able to understand what is the solution you provided for this. If my issues is matches with above ticket can you please suggest the solution for it. {quote} Server side heartbeat has no standard implementation. MINA SSHD server provides such a mechanism (see [Providing server-side heartbeat|https://github.com/apache/mina-sshd/blob/master/docs/server-setup.md#providing-server-side-heartbeat]. Note though that it is guaranteed to work only if the client is also MINA SSHD. Otherwise, it might or might not work. Furthermore, if the server in your setup is not MINA SSHD, then you are out of luck.... {quote} What we understood is "nio2-read-timeout" is not resetting even if server sends packets {quote} I believe this is incorrect - the timeout is implicitly "reset" by calling {{doReadCycle}} with it every time after a packet has been received. If it were true, then we would have seen active sessions time out as well - which we do do. Seems that the problem is that you are maintaining a "silent" client session with the server with no or very little traffic. Your challenge is to make sure you generate traffic from the server towards the client (the client heartbeat takes care of the other direction)... > 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-unsubscr...@mina.apache.org For additional commands, e-mail: dev-h...@mina.apache.org