[
https://issues.apache.org/jira/browse/SSHD-1020?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17162024#comment-17162024
]
Guillermo Grandes edited comment on SSHD-1020 at 7/21/20, 1:55 PM:
-------------------------------------------------------------------
{quote}[~lgoldstein]: AFAIK there is no standard way to force a response from a
server and thus keep the session alive.
{quote}
How openssh-client (ssh -oServerAliveInterval=10 192.168.X.SRV) can do this? we
dont have equivalent in sshd-core?
tcpdump (seem very diferent from [#comment-17160819]):
{code:none}
15:03:19.852635 length 118: 192.168.X.CLI.31868 > 192.168.X.SRV.22: Flags [P.],
seq 2311:2363, ack 2978, win 76, options [nop,nop,TS val 134325198 ecr
1736891045], length 52 << ping?
15:03:19.852885 length 94: 192.168.X.SRV.22 > 192.168.X.CLI.31868: Flags [P.],
seq 2978:3006, ack 2363, win 501, options [nop,nop,TS val 1736901057 ecr
134325198], length 28 >> pong!
15:03:19.853591 length 66: 192.168.X.CLI.31868 > 192.168.X.SRV.22: Flags [.],
ack 3006, win 76, options [nop,nop,TS val 134325198 ecr 1736901057], length 0
!! ok
---
15:03:29.864530 length 118: 192.168.X.CLI.31868 > 192.168.X.SRV.22: Flags [P.],
seq 2363:2415, ack 3006, win 76, options [nop,nop,TS val 134327701 ecr
1736901057], length 52 << ping?
15:03:29.864842 length 94: 192.168.X.SRV.22 > 192.168.X.CLI.31868: Flags [P.],
seq 3006:3034, ack 2415, win 501, options [nop,nop,TS val 1736911069 ecr
134327701], length 28 >> pong!
15:03:29.865579 length 66: 192.168.X.CLI.31868 > 192.168.X.SRV.22: Flags [.],
ack 3034, win 76, options [nop,nop,TS val 134327701 ecr 1736911069], length 0
!! ok
{code}
I only see in openssh-client (-vvv):
{code:none}
debug3: send packet: type 80 << ping?
debug3: receive packet: type 82 >> pong!
{code}
On openssh-server (DEBUG3), with openssh-client:
{code:none}
Jul 21 15:36:39 sshd[2621]: debug3: receive packet: type 80
Jul 21 15:36:39 sshd[2621]: debug1: server_input_global_request: rtype
[email protected] want_reply 1
Jul 21 15:36:39 sshd[2621]: debug3: send packet: type 82
{code}
Same server, with sshd-core client
([ClientFactoryManager.HEARTBEAT_INTERVAL|https://github.com/apache/mina-sshd/blob/master/docs/client-setup.md#keeping-the-session-alive-while-no-traffic]):
{code:none}
Jul 21 15:41:16 sshd[2751]: debug3: receive packet: type 80
Jul 21 15:41:16 sshd[2751]: debug1: server_input_global_request: rtype
[email protected] want_reply 0 << ping-ignore
{code}
Sorry (ignore-me like a ping ;)), We have a property to enable want_reply=1
([ClientFactoryManager.HEARTBEAT_REPLY_WAIT|https://github.com/apache/mina-sshd/blob/master/docs/client-setup.md#keeping-the-session-alive-while-no-traffic])
{code:none}
Jul 21 15:53:33 sshd[2828]: debug3: receive packet: type 80
Jul 21 15:53:33 sshd[2828]: debug1: server_input_global_request: rtype
[email protected] want_reply 1
Jul 21 15:53:33 sshd[2828]: debug3: send packet: type 82
{code}
My work-around for this issue:
{code:java}
PropertyResolverUtils.updateProperty(client,
ClientFactoryManager.HEARTBEAT_INTERVAL, TimeUnit.SECONDS.toMillis(10L));
PropertyResolverUtils.updateProperty(client,
ClientFactoryManager.HEARTBEAT_REPLY_WAIT, TimeUnit.SECONDS.toMillis(30L));
{code}
was (Author: technobcn):
{quote}[~lgoldstein]: AFAIK there is no standard way to force a response from a
server and thus keep the session alive.
{quote}
How openssh-client (ssh -oServerAliveInterval=10 192.168.X.SRV) can do this? we
dont have equivalent in sshd-core?
tcpdump (seem very diferent from [#comment-17160819]):
{code:none}
15:03:19.852635 length 118: 192.168.X.CLI.31868 > 192.168.X.SRV.22: Flags [P.],
seq 2311:2363, ack 2978, win 76, options [nop,nop,TS val 134325198 ecr
1736891045], length 52 << ping?
15:03:19.852885 length 94: 192.168.X.SRV.22 > 192.168.X.CLI.31868: Flags [P.],
seq 2978:3006, ack 2363, win 501, options [nop,nop,TS val 1736901057 ecr
134325198], length 28 >> pong!
15:03:19.853591 length 66: 192.168.X.CLI.31868 > 192.168.X.SRV.22: Flags [.],
ack 3006, win 76, options [nop,nop,TS val 134325198 ecr 1736901057], length 0
!! ok
---
15:03:29.864530 length 118: 192.168.X.CLI.31868 > 192.168.X.SRV.22: Flags [P.],
seq 2363:2415, ack 3006, win 76, options [nop,nop,TS val 134327701 ecr
1736901057], length 52 << ping?
15:03:29.864842 length 94: 192.168.X.SRV.22 > 192.168.X.CLI.31868: Flags [P.],
seq 3006:3034, ack 2415, win 501, options [nop,nop,TS val 1736911069 ecr
134327701], length 28 >> pong!
15:03:29.865579 length 66: 192.168.X.CLI.31868 > 192.168.X.SRV.22: Flags [.],
ack 3034, win 76, options [nop,nop,TS val 134327701 ecr 1736911069], length 0
!! ok
{code}
I only see in openssh-client (-vvv):
{code:none}
debug3: send packet: type 80 << ping?
debug3: receive packet: type 82 >> pong!
{code}
On openssh-server (DEBUG3), with openssh-client:
{code:none}
Jul 21 15:36:39 sshd[2621]: debug3: receive packet: type 80
Jul 21 15:36:39 sshd[2621]: debug1: server_input_global_request: rtype
[email protected] want_reply 1
Jul 21 15:36:39 sshd[2621]: debug3: send packet: type 82
{code}
Same server, with sshd-core client
([ClientFactoryManager.HEARTBEAT_INTERVAL|https://github.com/apache/mina-sshd/blob/master/docs/client-setup.md#keeping-the-session-alive-while-no-traffic]):
{code:none}
Jul 21 15:41:16 sshd[2751]: debug3: receive packet: type 80
Jul 21 15:41:16 sshd[2751]: debug1: server_input_global_request: rtype
[email protected] want_reply 0 << ping-ignore
{code}
Sorry (ignore-me like a ping ;)), We have a property to enable want_reply=1
([ClientFactoryManager.HEARTBEAT_REPLY_WAIT|https://github.com/apache/mina-sshd/blob/master/docs/client-setup.md#keeping-the-session-alive-while-no-traffic])
{code:none}
Jul 21 15:53:33 sshd[2828]: debug3: receive packet: type 80
Jul 21 15:53:33 sshd[2828]: debug1: server_input_global_request: rtype
[email protected] want_reply 1
Jul 21 15:53:33 sshd[2828]: debug3: send packet: type 82
{code}
> 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
> Assignee: Guillaume Nodet
> Priority: Blocker
> Fix For: 2.6.0
>
> Attachments: image-2020-06-26-15-18-58-509.png,
> image-2020-06-26-15-22-17-259.png, server.log
>
> Time Spent: 10m
> Remaining Estimate: 0h
>
> 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]
