[jira] [Updated] (SSHD-1020) SSH connections getting closed abruptly with timeout exceptions. java.nio.channels.InterruptedByTimeoutException

Mon, 22 Jun 2020 07:02:08 -0700 


     [ 
https://issues.apache.org/jira/browse/SSHD-1020?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
 ]

Sivanagarajup updated SSHD-1020:
--------------------------------
    Description: 
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

  was:
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.22.2:8345, 
remote=/207.241.169.100: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.22.2:8345, 
remote=/207.241.169.100: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[TelsasoftNBI@/207.241.169.100: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[TelsasoftNBI@/207.241.169.100: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[TelsasoftNBI@/207.241.169.100: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[TelsasoftNBI@/207.241.169.100: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[TelsasoftNBI@/207.241.169.100: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[TelsasoftNBI@/207.241.169.100: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[TelsasoftNBI@/207.241.169.100: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[TelsasoftNBI@/207.241.169.100: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[TelsasoftNBI@/207.241.169.100: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[TelsasoftNBI@/207.241.169.100: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[TelsasoftNBI@/207.241.169.100: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[TelsasoftNBI@/207.241.169.100: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[TelsasoftNBI@/207.241.169.100: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[TelsasoftNBI@/207.241.169.100: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[TelsasoftNBI@/207.241.169.100:41480]) 
result=ChannelSession[id=0, 
recipient=0]-ServerSessionImpl[TelsasoftNBI@/207.241.169.100: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[TelsasoftNBI@/207.241.169.100: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[TelsasoftNBI@/207.241.169.100: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[TelsasoftNBI@/207.241.169.100: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[TelsasoftNBI@/207.241.169.100: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[TelsasoftNBI@/207.241.169.100:41480]) failed 
(SshChannelClosedException) to close resources: 
flush(ChannelOutputStream[ChannelSession[id=0, 
recipient=0]-ServerSessionImpl[TelsasoftNBI@/207.241.169.100: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[TelsasoftNBI@/207.241.169.100: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[TelsasoftNBI@/207.241.169.100:41480]: 
flush(ChannelOutputStream[ChannelSession[id=0, 
recipient=0]-ServerSessionImpl[TelsasoftNBI@/207.241.169.100: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


> 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: Question
>    Affects Versions: 2.2.0
>            Reporter: Sivanagarajup
>            Priority: Major
>
> 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: [email protected]
For additional commands, e-mail: [email protected]

Reply via email to