You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mina.apache.org by "gurka (via GitHub)" <gi...@apache.org> on 2023/09/27 08:40:57 UTC
[GitHub] [mina-sshd] gurka opened a new issue, #420: "ClosedChannelException while shutting down output" after using remote port forwarding tunnel
gurka opened a new issue, #420:
URL: https://github.com/apache/mina-sshd/issues/420
### 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
```Shell
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_
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: dev-unsubscribe@mina.apache.org.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@mina.apache.org
For additional commands, e-mail: dev-help@mina.apache.org
Re: [I] "ClosedChannelException while shutting down output" after using remote port forwarding tunnel [mina-sshd]
Posted by "tomaswolf (via GitHub)" <gi...@apache.org>.
tomaswolf closed issue #420: "ClosedChannelException while shutting down output" after using remote port forwarding tunnel
URL: https://github.com/apache/mina-sshd/issues/420
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: dev-unsubscribe@mina.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@mina.apache.org
For additional commands, e-mail: dev-help@mina.apache.org
[GitHub] [mina-sshd] tomaswolf commented on issue #420: "ClosedChannelException while shutting down output" after using remote port forwarding tunnel
Posted by "tomaswolf (via GitHub)" <gi...@apache.org>.
tomaswolf commented on issue #420:
URL: https://github.com/apache/mina-sshd/issues/420#issuecomment-1737082491
Can you provide simple code to reproduce this?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: dev-unsubscribe@mina.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@mina.apache.org
For additional commands, e-mail: dev-help@mina.apache.org
Re: [I] "ClosedChannelException while shutting down output" after using remote port forwarding tunnel [mina-sshd]
Posted by "tomaswolf (via GitHub)" <gi...@apache.org>.
tomaswolf commented on issue #420:
URL: https://github.com/apache/mina-sshd/issues/420#issuecomment-1751387982
Thanks a lot for this code. I've rewritten this as a single JUnit test, (see [PortForwardingHttpTest.java.txt](https://github.com/apache/mina-sshd/files/12835353/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 DEBUG logging instead of INFO logging.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: dev-unsubscribe@mina.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@mina.apache.org
For additional commands, e-mail: dev-help@mina.apache.org
[GitHub] [mina-sshd] gurka commented on issue #420: "ClosedChannelException while shutting down output" after using remote port forwarding tunnel
Posted by "gurka (via GitHub)" <gi...@apache.org>.
gurka commented on issue #420:
URL: https://github.com/apache/mina-sshd/issues/420#issuecomment-1737355131
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());
}
}
}
}
}
}
}
```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: dev-unsubscribe@mina.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@mina.apache.org
For additional commands, e-mail: dev-help@mina.apache.org