Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

"ClosedChannelException while shutting down output" after using remote port forwarding tunnel #420

Closed
gurka opened this issue Sep 27, 2023 · 3 comments · Fixed by #422
Closed

"ClosedChannelException while shutting down output" after using remote port forwarding tunnel #420

gurka opened this issue Sep 27, 2023 · 3 comments · Fixed by #422
Assignees
@tomaswolf
Labels
bug An issue describing a bug in the code
Milestone
2.11.0

Comments

@gurka
Copy link

gurka commented Sep 27, 2023

Version

2.9.2

Bug description

We have two applications, server and client. server has an Apache MINA SSHD server running and client connects to this using an Apache MINA SSHD client. The client also sets up remort port forwarding tunnel, so that server can connect to a REST service that is running on client via the ssh connection.

After upgrading Apache MINA SSHD from version 1.4.0.0 to 2.9.2 on both applications we started to see an INFO log entry on client about "ClosedChannelException while shutting down output" when a connection over the remote port forwarding tunnel is closed. It happens almost every time a connection is closed, but not always.

2023-09-27T10:23:01.257+02:00 INFO [131] org.apache.sshd.common.io.nio2.Nio2Session doCloseGracefully(Nio2Session[local=/[0:0:0:0:0:0:0:0]:52239, remote=localhost/127.0.0.1:8090]) ClosedChannelException while shutting down output: null

It seems to happen only when the connection is closed non-gracefully (RST instead of FIN). We are not sure why the connection is closed non-gracefully, it seems to be somehow related to HttpURLConnection and it's keep-alive functionality. It seems to close the connection non-gracefully if the connection has been idle for too long and is about to be removed from the keep-alive cache. This matches the timing (5 seconds, as that is the default keep-alive time) between connection creation and connection close.

As this is an INFO log entry it might not be a problem at all, maybe this is fully expected when the connection over the tunnel is closed non-gracefully? But in that case, maybe it should not be on log level INFO?

Actual behavior

ClosedChannelException INFO log entry when connection over remote port forwarding tunnel is closed non-gracefully.

Expected behavior

Either no ClosedChannelException at all, or log level changed to avoid flooding the log when there are many connections created and closed over the tunnel.

Relevant log output

2023-09-27T10:34:41.484+02:00 DEBUG [105] org.apache.sshd.common.io.nio2.Nio2Session Creating IoSession on /[0:0:0:0:0:0:0:0]:52813 from localhost/127.0.0.1:8090 via null
2023-09-27T10:34:41.484+02:00 DEBUG [105] org.apache.sshd.common.io.nio2.Nio2Session suspendRead(Nio2Session[local=/[0:0:0:0:0:0:0:0]:52813, remote=localhost/127.0.0.1:8090]) requesting read suspension
2023-09-27T10:34:41.484+02:00 DEBUG [105] org.apache.sshd.client.session.ClientConnectionService channelOpenSuccess(TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]) send SSH_MSG_CHANNEL_OPEN_CONFIRMATION recipient=87, sender=87, window-size=2097152, packet-size=32768
2023-09-27T10:34:41.484+02:00 DEBUG [105] org.apache.sshd.client.session.ClientSessionImpl encode(ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]) packet #361 sending command=91[SSH_MSG_CHANNEL_OPEN_CONFIRMATION] len=17
2023-09-27T10:34:41.485+02:00 DEBUG [105] org.apache.sshd.common.io.nio2.Nio2Session writeBuffer(Nio2Session[local=/[0:0:0:0:0:0:0:0]:52479, remote=/127.0.0.1:8183]) writing 80 bytes
2023-09-27T10:34:41.485+02:00 DEBUG [107] org.apache.sshd.client.session.ClientSessionImpl doHandleMessage(ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]) process #417 SSH_MSG_CHANNEL_DATA
2023-09-27T10:34:41.485+02:00 DEBUG [107] org.apache.sshd.common.channel.LocalWindow Consume LocalWindow[server](TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]) by 184 down to 2096968
2023-09-27T10:34:41.485+02:00 DEBUG [107] org.apache.sshd.server.forward.TcpipServerChannel handleData(TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]) SSH_MSG_CHANNEL_DATA len=184
2023-09-27T10:34:41.485+02:00 DEBUG [107] org.apache.sshd.common.io.nio2.Nio2Session writeBuffer(Nio2Session[local=/[0:0:0:0:0:0:0:0]:52813, remote=localhost/127.0.0.1:8090]) writing 184 bytes
2023-09-27T10:34:41.489+02:00 DEBUG [101] org.apache.sshd.common.io.nio2.Nio2Session suspendRead(Nio2Session[local=/[0:0:0:0:0:0:0:0]:52813, remote=localhost/127.0.0.1:8090]) requesting read suspension
2023-09-27T10:34:41.489+02:00 DEBUG [101] org.apache.sshd.common.channel.RemoteWindow Consume RemoteWindow[server](TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]) by 151 down to 2097001
2023-09-27T10:34:41.489+02:00 DEBUG [101] org.apache.sshd.client.session.ClientSessionImpl encode(ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]) packet #362 sending command=94[SSH_MSG_CHANNEL_DATA] len=160
2023-09-27T10:34:41.489+02:00 DEBUG [101] org.apache.sshd.common.io.nio2.Nio2Session writeBuffer(Nio2Session[local=/[0:0:0:0:0:0:0:0]:52479, remote=/127.0.0.1:8183]) writing 224 bytes
2023-09-27T10:34:41.490+02:00 DEBUG [101] org.apache.sshd.common.io.nio2.Nio2Session doReadCycle(Nio2Session[local=/[0:0:0:0:0:0:0:0]:52813, remote=localhost/127.0.0.1:8090]) suspending reading
2023-09-27T10:34:41.490+02:00 DEBUG [109] org.apache.sshd.common.io.nio2.Nio2Session resumeRead(Nio2Session[local=/[0:0:0:0:0:0:0:0]:52813, remote=localhost/127.0.0.1:8090]) resuming read
2023-09-27T10:34:41.494+02:00 DEBUG [110] org.apache.sshd.client.session.ClientSessionImpl doHandleMessage(ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]) process #418 SSH_MSG_CHANNEL_DATA
2023-09-27T10:34:41.494+02:00 DEBUG [110] org.apache.sshd.common.channel.LocalWindow Consume LocalWindow[server](TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]) by 201 down to 2096767
2023-09-27T10:34:41.494+02:00 DEBUG [110] org.apache.sshd.server.forward.TcpipServerChannel handleData(TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]) SSH_MSG_CHANNEL_DATA len=201
2023-09-27T10:34:41.494+02:00 DEBUG [110] org.apache.sshd.common.io.nio2.Nio2Session writeBuffer(Nio2Session[local=/[0:0:0:0:0:0:0:0]:52813, remote=localhost/127.0.0.1:8090]) writing 201 bytes
2023-09-27T10:34:41.495+02:00 DEBUG [103] org.apache.sshd.client.session.ClientSessionImpl doHandleMessage(ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]) process #419 SSH_MSG_CHANNEL_DATA
2023-09-27T10:34:41.496+02:00 DEBUG [103] org.apache.sshd.common.channel.LocalWindow Consume LocalWindow[server](TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]) by 6838 down to 2089929
2023-09-27T10:34:41.496+02:00 DEBUG [103] org.apache.sshd.server.forward.TcpipServerChannel handleData(TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]) SSH_MSG_CHANNEL_DATA len=6838
2023-09-27T10:34:41.496+02:00 DEBUG [103] org.apache.sshd.common.io.nio2.Nio2Session writeBuffer(Nio2Session[local=/[0:0:0:0:0:0:0:0]:52813, remote=localhost/127.0.0.1:8090]) writing 6838 bytes
2023-09-27T10:34:41.502+02:00 DEBUG [105] org.apache.sshd.common.io.nio2.Nio2Session suspendRead(Nio2Session[local=/[0:0:0:0:0:0:0:0]:52813, remote=localhost/127.0.0.1:8090]) requesting read suspension
2023-09-27T10:34:41.502+02:00 DEBUG [105] org.apache.sshd.common.channel.RemoteWindow Consume RemoteWindow[server](TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]) by 93 down to 2096908
2023-09-27T10:34:41.502+02:00 DEBUG [105] org.apache.sshd.client.session.ClientSessionImpl encode(ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]) packet #363 sending command=94[SSH_MSG_CHANNEL_DATA] len=102
2023-09-27T10:34:41.502+02:00 DEBUG [105] org.apache.sshd.common.io.nio2.Nio2Session writeBuffer(Nio2Session[local=/[0:0:0:0:0:0:0:0]:52479, remote=/127.0.0.1:8183]) writing 160 bytes
2023-09-27T10:34:41.502+02:00 DEBUG [105] org.apache.sshd.common.io.nio2.Nio2Session doReadCycle(Nio2Session[local=/[0:0:0:0:0:0:0:0]:52813, remote=localhost/127.0.0.1:8090]) suspending reading
2023-09-27T10:34:41.502+02:00 DEBUG [105] org.apache.sshd.common.io.nio2.Nio2Session resumeRead(Nio2Session[local=/[0:0:0:0:0:0:0:0]:52813, remote=localhost/127.0.0.1:8090]) resuming read
2023-09-27T10:34:46.494+02:00 DEBUG [107] org.apache.sshd.client.session.ClientSessionImpl doHandleMessage(ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]) process #420 SSH_MSG_CHANNEL_CLOSE
2023-09-27T10:34:46.494+02:00 DEBUG [107] org.apache.sshd.server.forward.TcpipServerChannel handleClose(TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]) SSH_MSG_CHANNEL_CLOSE
2023-09-27T10:34:46.494+02:00 DEBUG [107] org.apache.sshd.server.forward.TcpipServerChannel handleClose(TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]) prevent sending EOF
2023-09-27T10:34:46.494+02:00 DEBUG [107] org.apache.sshd.server.forward.TcpipServerChannel close(TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]) Closing gracefully
2023-09-27T10:34:46.494+02:00 DEBUG [107] org.apache.sshd.common.channel.LocalWindow Closing LocalWindow[server](TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183])
2023-09-27T10:34:46.494+02:00 DEBUG [107] org.apache.sshd.common.channel.RemoteWindow Closing RemoteWindow[server](TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183])
2023-09-27T10:34:46.495+02:00 DEBUG [107] org.apache.sshd.server.forward.TcpipServerChannel$1 close([TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]] cmd=SSH_MSG_CHANNEL_DATA) Closing gracefully
2023-09-27T10:34:46.495+02:00 DEBUG [107] org.apache.sshd.server.forward.TcpipServerChannel sendEof(TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]) already sent (state=Graceful)
2023-09-27T10:34:46.495+02:00 DEBUG [107] org.apache.sshd.server.forward.TcpipServerChannel$1 close([TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]] cmd=SSH_MSG_CHANNEL_DATA][Graceful] - operationComplete() closed
2023-09-27T10:34:46.495+02:00 DEBUG [107] org.apache.sshd.common.channel.AbstractChannel$GracefulChannelCloseable close(TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183])[immediately=false] processing
2023-09-27T10:34:46.495+02:00 DEBUG [107] org.apache.sshd.common.channel.AbstractChannel$GracefulChannelCloseable close(TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183])[immediately=false] send SSH_MSG_CHANNEL_CLOSE
2023-09-27T10:34:46.495+02:00 DEBUG [107] org.apache.sshd.client.session.ClientSessionImpl encode(ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]) packet #364 sending command=97[SSH_MSG_CHANNEL_CLOSE] len=5
2023-09-27T10:34:46.495+02:00 DEBUG [107] org.apache.sshd.common.io.nio2.Nio2Session writeBuffer(Nio2Session[local=/[0:0:0:0:0:0:0:0]:52479, remote=/127.0.0.1:8183]) writing 64 bytes
2023-09-27T10:34:46.496+02:00 DEBUG [107] org.apache.sshd.common.channel.AbstractChannel$GracefulChannelCloseable handleClosePacketWritten(TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183])[immediately=false] SSH_MSG_CHANNEL_CLOSE written on channel
2023-09-27T10:34:46.496+02:00 DEBUG [107] org.apache.sshd.client.session.ClientConnectionService unregisterChannel(TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]) result=TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]
2023-09-27T10:34:46.496+02:00 DEBUG [107] org.apache.sshd.common.util.closeable.SequentialCloseable doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@3b9592b1) signal close complete immediately=false
2023-09-27T10:34:46.496+02:00 DEBUG [107] org.apache.sshd.server.forward.TcpipServerChannel$2 close(org.apache.sshd.server.forward.TcpipServerChannel$2@73ee1629) Closing gracefully
2023-09-27T10:34:46.497+02:00 DEBUG [107] org.apache.sshd.server.forward.TcpipServerChannel$2 close(org.apache.sshd.server.forward.TcpipServerChannel$2@73ee1629)[Graceful] closed
2023-09-27T10:34:46.497+02:00 DEBUG [107] org.apache.sshd.common.util.closeable.SequentialCloseable doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@53e2317c) signal close complete immediately=false
2023-09-27T10:34:46.498+02:00 DEBUG [377] org.apache.sshd.common.io.nio2.Nio2Connector close(org.apache.sshd.common.io.nio2.Nio2Connector@641d6960) Closing gracefully
2023-09-27T10:34:46.498+02:00 DEBUG [378] org.apache.sshd.common.io.nio2.Nio2Connector close(org.apache.sshd.common.io.nio2.Nio2Connector@641d6960) Closing immediately
2023-09-27T10:34:46.498+02:00 DEBUG [377] org.apache.sshd.common.io.nio2.Nio2Session close(Nio2Session[local=/[0:0:0:0:0:0:0:0]:52813, remote=localhost/127.0.0.1:8090]) Closing gracefully
2023-09-27T10:34:46.498+02:00 DEBUG [378] org.apache.sshd.common.io.nio2.Nio2Session close(Nio2Session[local=/[0:0:0:0:0:0:0:0]:52813, remote=localhost/127.0.0.1:8090]) Closing immediately
2023-09-27T10:34:46.498+02:00 DEBUG [378] org.apache.sshd.common.io.nio2.Nio2Session doCloseImmediately(Nio2Session[local=/[0:0:0:0:0:0:0:0]:52813, remote=localhost/127.0.0.1:8090]) closing socket=sun.nio.ch.WindowsAsynchronousSocketChannelImpl[connected local=/[0:0:0:0:0:0:0:0]:52813 remote=localhost/127.0.0.1:8090]
2023-09-27T10:34:46.498+02:00 DEBUG [107] org.apache.sshd.server.forward.TcpipServerChannel$1 close([TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]] cmd=SSH_MSG_CHANNEL_DATA)[Immediately] state already Closed
2023-09-27T10:34:46.498+02:00 DEBUG [107] org.apache.sshd.common.channel.AbstractChannel$GracefulChannelCloseable close(TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183])[immediately=true] processing
2023-09-27T10:34:46.498+02:00 DEBUG [107] org.apache.sshd.client.session.ClientConnectionService unregisterChannel(TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]) result=null
2023-09-27T10:34:46.498+02:00 DEBUG [107] org.apache.sshd.common.util.closeable.SequentialCloseable doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@50be3a77) signal close complete immediately=true
2023-09-27T10:34:46.499+02:00 DEBUG [107] org.apache.sshd.server.forward.TcpipServerChannel$2 close(org.apache.sshd.server.forward.TcpipServerChannel$2@4b4ea763) Closing immediately
2023-09-27T10:34:46.499+02:00 DEBUG [109] org.apache.sshd.common.io.nio2.Nio2Session handleReadCycleFailure(Nio2Session[local=/[0:0:0:0:0:0:0:0]:52813, remote=localhost/127.0.0.1:8090]) AsynchronousCloseException after 4996733800 nanos at read cycle=3: null
2023-09-27T10:34:46.499+02:00 DEBUG [107] org.apache.sshd.server.forward.TcpipServerChannel$2 close(org.apache.sshd.server.forward.TcpipServerChannel$2@4b4ea763)[Immediately] closed
2023-09-27T10:34:46.499+02:00 DEBUG [378] org.apache.sshd.common.io.nio2.Nio2Session doCloseImmediately(Nio2Session[local=/[0:0:0:0:0:0:0:0]:52813, remote=localhost/127.0.0.1:8090]) socket=sun.nio.ch.WindowsAsynchronousSocketChannelImpl[closed] closed
2023-09-27T10:34:46.499+02:00 DEBUG [107] org.apache.sshd.common.util.closeable.SequentialCloseable doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@6467864c) signal close complete immediately=true
2023-09-27T10:34:46.499+02:00 DEBUG [109] org.apache.sshd.common.io.nio2.Nio2Session close(Nio2Session[local=/[0:0:0:0:0:0:0:0]:52813, remote=localhost/127.0.0.1:8090])[Immediately] state already Immediate
2023-09-27T10:34:46.499+02:00 DEBUG [378] org.apache.sshd.common.io.nio2.Nio2Connector unmapSession(id=188): Nio2Session[local=/[0:0:0:0:0:0:0:0]:52813, remote=localhost/127.0.0.1:8090]
2023-09-27T10:34:46.499+02:00 DEBUG [107] org.apache.sshd.server.forward.TcpipServerChannel close(TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183]][Graceful] - operationComplete() closed
2023-09-27T10:34:46.499+02:00 DEBUG [378] org.apache.sshd.server.forward.TcpipServerChannel close(TcpipServerChannel[id=87, recipient=87]-ClientSessionImpl[vsa-23.4-2e720007-c417-40b9-acac-df96359a9204@/127.0.0.1:8183])[Graceful] state already Closed
2023-09-27T10:34:46.499+02:00 DEBUG [378] org.apache.sshd.common.io.nio2.Nio2Session close(Nio2Session[local=/[0:0:0:0:0:0:0:0]:52813, remote=localhost/127.0.0.1:8090])[Immediately] closed
2023-09-27T10:34:46.499+02:00 DEBUG [378] org.apache.sshd.common.io.nio2.Nio2Connector close(org.apache.sshd.common.io.nio2.Nio2Connector@641d6960)[Immediately] closed
2023-09-27T10:34:46.499+02:00 INFO  [377] org.apache.sshd.common.io.nio2.Nio2Session doCloseGracefully(Nio2Session[local=/[0:0:0:0:0:0:0:0]:52813, remote=localhost/127.0.0.1:8090]) ClosedChannelException while shutting down output: null
java.nio.channels.ClosedChannelException: null
	at sun.nio.ch.AsynchronousSocketChannelImpl.begin(AsynchronousSocketChannelImpl.java:118) ~[?:?]
	at sun.nio.ch.AsynchronousSocketChannelImpl.shutdownOutput(AsynchronousSocketChannelImpl.java:554) ~[?:?]
	at org.apache.sshd.common.io.nio2.Nio2Session.lambda$doCloseGracefully$0(Nio2Session.java:227) ~[sshd-core-2.9.2.jar:2.9.2]
	at org.apache.sshd.common.util.closeable.Builder$1.doClose(Builder.java:47) ~[sshd-common-2.9.2.jar:2.9.2]
	at org.apache.sshd.common.util.closeable.SimpleCloseable.close(SimpleCloseable.java:63) ~[sshd-common-2.9.2.jar:2.9.2]
	at org.apache.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:56) ~[sshd-common-2.9.2.jar:2.9.2]
	at org.apache.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:45) ~[sshd-common-2.9.2.jar:2.9.2]
	at org.apache.sshd.common.future.AbstractSshFuture.lambda$notifyListener$2(AbstractSshFuture.java:162) ~[sshd-common-2.9.2.jar:2.9.2]
	at org.apache.sshd.common.util.threads.ThreadUtils.runAsInternal(ThreadUtils.java:68) ~[sshd-common-2.9.2.jar:2.9.2]
	at org.apache.sshd.common.future.AbstractSshFuture.notifyListener(AbstractSshFuture.java:161) ~[sshd-common-2.9.2.jar:2.9.2]
	at org.apache.sshd.common.future.DefaultSshFuture.addListener(DefaultSshFuture.java:166) ~[sshd-common-2.9.2.jar:2.9.2]
	at org.apache.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:57) ~[sshd-common-2.9.2.jar:2.9.2]
	at org.apache.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:45) ~[sshd-common-2.9.2.jar:2.9.2]
	at org.apache.sshd.common.util.closeable.SequentialCloseable.doClose(SequentialCloseable.java:69) ~[sshd-common-2.9.2.jar:2.9.2]
	at org.apache.sshd.common.util.closeable.SimpleCloseable.close(SimpleCloseable.java:63) ~[sshd-common-2.9.2.jar:2.9.2]
	at org.apache.sshd.common.io.nio2.Nio2Session.doCloseGracefully(Nio2Session.java:233) ~[sshd-core-2.9.2.jar:2.9.2]
	at org.apache.sshd.common.util.closeable.AbstractCloseable.close(AbstractCloseable.java:110) ~[sshd-common-2.9.2.jar:2.9.2]
	at org.apache.sshd.common.util.closeable.ParallelCloseable.doClose(ParallelCloseable.java:65) ~[sshd-common-2.9.2.jar:2.9.2]
	at org.apache.sshd.common.util.closeable.SimpleCloseable.close(SimpleCloseable.java:63) ~[sshd-common-2.9.2.jar:2.9.2]
	at org.apache.sshd.common.util.closeable.AbstractInnerCloseable.doCloseGracefully(AbstractInnerCloseable.java:41) ~[sshd-common-2.9.2.jar:2.9.2]
	at org.apache.sshd.common.util.closeable.AbstractCloseable.close(AbstractCloseable.java:110) ~[sshd-common-2.9.2.jar:2.9.2]
	at org.apache.sshd.server.forward.TcpipServerChannel$2.lambda$doCloseGracefully$0(TcpipServerChannel.java:304) ~[sshd-core-2.9.2.jar:2.9.2]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
	at java.lang.Thread.run(Thread.java:833) [?:?]

Other information

No response
@tomaswolf
Copy link
Member

Can you provide simple code to reproduce this?

@gurka
Copy link
Author

gurka commented Sep 27, 2023

Sort of, but it's not pretty. And I weren't able to reproduce it without also making the "http server" NOT close the socket after a read failure, which leads me to believe that the root issue is maybe something in our REST service not cleaning up keep-alive connections that are closed correctly.

Anyway, here is the code that can reproduce this. It's not 100%, but often after a "http server: read failed, closing connection" you also get the "ClosedChannelException while shutting down output" INFO log entry. (I used slf4j-api 2.0.7 and logback-classic 1.4.8 to get logs and be able to control the root logger level):

Server.java

package org.example;

import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.Logger;
import java.io.IOException;
import java.net.HttpURLConnection;
import java.net.URL;
import java.nio.charset.StandardCharsets;
import java.security.KeyPairGenerator;
import java.util.List;
import org.apache.sshd.common.util.security.SecurityUtils;
import org.apache.sshd.server.SshServer;
import org.apache.sshd.server.forward.AcceptAllForwardingFilter;
import org.slf4j.LoggerFactory;

public class Server {

    public static void main(String[] args) throws IOException, InterruptedException {
        Logger rootLogger = (Logger) LoggerFactory.getLogger(org.slf4j.Logger.ROOT_LOGGER_NAME);
        rootLogger.setLevel(Level.INFO);

        try (SshServer server = SshServer.setUpDefaultServer()) {
            server.setPort(8022);
            server.setKeyPairProvider(session -> {
                KeyPairGenerator kpg = SecurityUtils.getKeyPairGenerator("RSA");
                kpg.initialize(1024);
                return List.of(kpg.generateKeyPair());
            });
            server.setPasswordAuthenticator((username, password, session) -> true);
            server.setForwardingFilter(new AcceptAllForwardingFilter());
            server.start();

            while (true) {
                // Need to sleep at least 5s, otherwise HttpURLConnection will re-use the connection
                Thread.sleep(10000L);

                System.out.println("Connecting to http server via remote port forwarding tunnel");
                try {
                    HttpURLConnection con = (HttpURLConnection) new URL("http://localhost:8055/").openConnection();
                    con.connect();
                    System.out.println("Request sent");
                    String response = new String(con.getInputStream().readAllBytes(), StandardCharsets.UTF_8);
                    System.out.println("Received response: " + response);
                } catch (IOException e) {
                    System.err.println("Failed: " + e.getMessage());
                }
            }
        }
    }
}

Client.java

package org.example;

import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.Logger;
import java.io.IOException;
import java.io.InputStream;
import java.io.OutputStream;
import java.net.InetSocketAddress;
import java.net.ServerSocket;
import java.net.Socket;
import java.nio.charset.StandardCharsets;
import org.apache.sshd.client.SshClient;
import org.apache.sshd.client.session.ClientSession;
import org.apache.sshd.common.util.net.SshdSocketAddress;
import org.apache.sshd.server.forward.AcceptAllForwardingFilter;
import org.slf4j.LoggerFactory;

public class Client {

    public static void main(String[] args) throws IOException {
        Logger rootLogger = (Logger) LoggerFactory.getLogger(org.slf4j.Logger.ROOT_LOGGER_NAME);
        rootLogger.setLevel(Level.INFO);

        try (SshClient sshClient = SshClient.setUpDefaultClient()) {
            sshClient.setForwardingFilter(new AcceptAllForwardingFilter());
            sshClient.start();

            try (ClientSession session = sshClient.connect("test", "localhost", 8022).verify().getSession()) {
                session.addPasswordIdentity("test");
                session.auth().verify();
                session.startRemotePortForwarding(new SshdSocketAddress("localhost", 8055),
                        new SshdSocketAddress("localhost", 8066));

                try (ServerSocket ss = new ServerSocket()) {
                    ss.bind(new InetSocketAddress("localhost", 8066));
                    System.out.println("http server started");
                    while (true) {
                        Socket s = ss.accept();
                        s.setSoLinger(true, 0);
                        System.out.println("http server: new connection");
                        try {
                            while (true) {
                                InputStream is = s.getInputStream();
                                OutputStream os = s.getOutputStream();

                                // Read request (until two CRLFs)
                                int[] buffer = new int[4];
                                int offset = 0;
                                boolean ok = true;
                                while (true) {
                                    int read = is.read();
                                    if (read == -1) {
                                        ok = false;
                                        break;
                                    }
                                    buffer[offset % 4] = read;
                                    if (offset >= 4 &&
                                            buffer[offset % 4] == '\n' &&
                                            buffer[(offset - 1) % 4] == '\r' &&
                                            buffer[(offset - 2) % 4] == '\n' &&
                                            buffer[(offset - 3) % 4] == '\r') {
                                        break;
                                    }
                                    offset += 1;
                                }

                                if (!ok) {
                                    System.err.println("http server: read failed, closing connection");
                                    // Closing the socket here, which would be the correct action (?), makes the issue in sshd not appear
                                    //s.close();
                                    break;
                                }

                                System.out.println("http server: received request");

                                StringBuilder sb = new StringBuilder();
                                sb.append("HTTP/1.1 200 OK\r\n");
                                sb.append("Connection: Keep-Alive\r\n");
                                sb.append("Content-Length: 5\r\n");
                                sb.append("Content-Type: text/plain\r\n");
                                sb.append("\r\n");
                                sb.append("hello");

                                os.write(sb.toString().getBytes(StandardCharsets.UTF_8));
                                os.flush();

                                System.out.println("http server: response sent");
                            }
                        } catch (IOException e) {
                            System.err.println("Socket closed: " + e.getMessage());
                        }
                    }
                }
            }
        }
    }
}

@tomaswolf
Copy link
Member

tomaswolf commented Oct 6, 2023 •
edited
Loading

Thanks a lot for this code. I've rewritten this as a single JUnit test, (see PortForwardingHttpTest.java.txt) and I see the following things:

  1. The exception occurs sporadically, whether or not the HTTP server properly closes its socket.
  2. The exception is logged when the SSH server tries to shut down its connection to the HTTP server.
  3. It is harmless.
  4. The logging level should probably not be INFO but DEBUG or maybe even TRACE.

I suggest to fix (4) by checking in Nio2Session.doCloseGracefully() whether the socket is still open before calling socket.shutdownOutput();, and using TRACE logging instead of INFO logging. Basically the same as in Nio2Session.doShutdownOutputStream().

tomaswolf added a commit to tomaswolf/mina-sshd that referenced this issue Oct 6, 2023
@tomaswolf
apacheGH-420: avoid spurious exceptions on closing forwarded channel
9b485a7 
Fix Nio2Session.doCloseGracefully(): before calling
AsynchronousSocketChannel.shutdownOutput(), check that the socket is
still open, and if we get an IOException all the same, log it with
TRACE level. See also comments in doShutdownOutputStream().

Bug: apache#420
@tomaswolf tomaswolf mentioned this issue Oct 6, 2023
Merged
@tomaswolf tomaswolf added the bug An issue describing a bug in the code label Oct 6, 2023
@tomaswolf tomaswolf self-assigned this Oct 6, 2023
@tomaswolf tomaswolf added this to the 2.10.1 milestone Oct 6, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@tomaswolf tomaswolf

Labels
bug An issue describing a bug in the code
Projects
None yet
Milestone
2.11.0
Development

Successfully merging a pull request may close this issue.

GH-420: avoid spurious exceptions on closing forwarded channel tomaswolf/mina-sshd
2 participants
@gurka @tomaswolf