[
https://issues.apache.org/jira/browse/SSHD-1020?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17146144#comment-17146144
]
Sivanagarajup edited comment on SSHD-1020 at 6/26/20, 10:15 AM:
----------------------------------------------------------------
Hi [~lgoldstein],
Thank you for the response
I think its not due to "no traffic" issue
Application sent data to remote client last time at *2020-06-18 03:06:28*
{code:java}
2020-06-18 03:06:28,222 DEBUG [org.apache.sshd.common.io.nio2.Nio2Session]
(sshd-SshServer[6c96892e](port=8345)-nio2-thread-3)
handleCompletedWriteCycle(Nio2Session[local=/10.10.22.22:8345,
remote=/308.151.178.99:41480]) finished writing len=1168 {code}
We have see timeout exception at *2020-06-18 03:07:11*
{code:java}
2020-06-18 03:07:11,943 DEBUG
[org.apache.sshd.server.session.ServerSessionImpl]
(sshd-SshServer[6c96892e](port=8345)-nio2-thread-1)
exceptionCaught(ServerSessionImpl[clientNBI@/308.151.178.99:41480])[state=Opened]
details: java.nio.channels.InterruptedByTimeoutException {code}
if we can observe only 43 seconds gap b/w last time data sent and exception
caught,
we have *tcp dump screen* for when we sent last time data to client and when
the connection is closed due to timeout
*Data sent to last time to client*
!image-2020-06-26-15-18-58-509.png!
*Closed the session due to time out*
!image-2020-06-26-15-22-17-259.png!
Note : forget about the time stamp in tcpdump screen, we have 4 hrs timestamp
difference in tcpdump screen
from the above information we can say its not due to "no traffic"
The timeout you are suspecting is due to server side or client side ?
what all logs are required from client to analyse if it is from client ?
//Siva
was (Author: siva999):
Hi [~lgoldstein],
Application sent data to remote client last time at *2020-06-18 03:06:28*
{code:java}
2020-06-18 03:06:28,222 DEBUG [org.apache.sshd.common.io.nio2.Nio2Session]
(sshd-SshServer[6c96892e](port=8345)-nio2-thread-3)
handleCompletedWriteCycle(Nio2Session[local=/10.10.22.22:8345,
remote=/308.151.178.99:41480]) finished writing len=1168 {code}
We have see timeout exception at *2020-06-18 03:07:11*
{code:java}
2020-06-18 03:07:11,943 DEBUG
[org.apache.sshd.server.session.ServerSessionImpl]
(sshd-SshServer[6c96892e](port=8345)-nio2-thread-1)
exceptionCaught(ServerSessionImpl[clientNBI@/308.151.178.99:41480])[state=Opened]
details: java.nio.channels.InterruptedByTimeoutException {code}
if we can observe only 43 seconds gap b/w last time data sent and exception
caught,
i think its not due to "no traffic" issue
we have *tcp dump screen* for when we sent last time data to client and when
the connection is closed due to timeout
*Data sent to last time to client*
!image-2020-06-26-15-18-58-509.png!
*Closed the session due to time out*
!image-2020-06-26-15-22-17-259.png!
Note : forget about the time stamp in tcpdump screen, we have 4 hrs timestamp
difference in tcpdump screen
from the above information we can say its not due to "no traffic"
//Siva
> 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
