[
https://issues.apache.org/jira/browse/SSHD-1256?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17608910#comment-17608910
]
Thomas Wolf commented on SSHD-1256:
-----------------------------------
Here's the log from a failed GitHub CI run:
{code:java}
19:30:53.714 | INFO | main | ROOT |
org.apache.sshd.util.test.JUnitTestSupport 121 | Using
ch.qos.logback.classic.Logger logger(s) at level=INFO
19:30:53.722 | INFO | main | o.a.s.s.SshServer |
org.apache.sshd.server.SshServer 344 | start()
listen on auto-allocated port=33341
Starting
org.apache.sshd.common.forward.PortForwardingTest:testRemoteForwardingSecondTimeInSameSession...
Using default provider: org.apache.sshd.mina.MinaServiceFactoryFactory
19:30:53.784 | WARN | main | c.j.j.JSch |
org.apache.sshd.util.test.JSchLogger 60 |
Permanently added '127.0.0.1' (ECDSA) to the list of known hosts.
19:30:53.786 | INFO | MinaProcessor-9 | o.a.s.s.s.ServerSessionImpl |
org.apache.sshd.server.session.AbstractServerSession 334 | Session
testRemoteForwardingSecondTimeInSameSession@/127.0.0.1:42542 authenticated
19:30:53.787 | INFO | MinaProcessor-9 | .c.f.PortForwardingEventListener |
org.apache.sshd.common.forward.PortForwardingTest$1 110 |
establishingExplicitTunnel(session=ServerSessionImpl[testRemoteForwardingSecondTimeInSameSession@/127.0.0.1:42542],
local=localhost:42619, remote=null, localForwarding=true)
19:30:53.788 | INFO | MinaProcessor-9 | .c.f.PortForwardingEventListener |
org.apache.sshd.common.forward.PortForwardingTest$1 119 |
establishedExplicitTunnel(session=ServerSessionImpl[testRemoteForwardingSecondTimeInSameSession@/127.0.0.1:42542],
local=localhost:42619, remote=null, bound=127.0.0.1:42619,
localForwarding=true): null
19:30:53.789 | INFO | MinaProcessor-9 | o.a.s.c.f.Forwarder |
org.apache.sshd.common.forward.PortForwardingTest$2$1 229 | Signal
tcpip-forward
19:30:53.789 | INFO | MinaProcessor-9 | .c.f.PortForwardingEventListener |
org.apache.sshd.common.forward.PortForwardingTest$1 128 |
tearingDownExplicitTunnel(session=ServerSessionImpl[testRemoteForwardingSecondTimeInSameSession@/127.0.0.1:42542],
address=localhost:42619, localForwarding=true, remote=null)
19:30:53.789 | INFO | MinaProcessor-9 | .c.f.PortForwardingEventListener |
org.apache.sshd.common.forward.PortForwardingTest$1 137 |
tornDownExplicitTunnel(session=ServerSessionImpl[testRemoteForwardingSecondTimeInSameSession@/127.0.0.1:42542],
address=localhost:42619, localForwarding=true, remote=null, reason=null)
19:30:53.790 | INFO | MinaProcessor-9 | o.a.s.c.f.Forwarder |
org.apache.sshd.common.forward.PortForwardingTest$2$1 229 | Signal
cancel-tcpip-forward
19:30:53.790 | INFO | MinaProcessor-9 | .c.f.PortForwardingEventListener |
org.apache.sshd.common.forward.PortForwardingTest$1 110 |
establishingExplicitTunnel(session=ServerSessionImpl[testRemoteForwardingSecondTimeInSameSession@/127.0.0.1:42542],
local=localhost:42619, remote=null, localForwarding=true)
19:30:53.791 | INFO | MinaProcessor-9 | .c.f.PortForwardingEventListener |
org.apache.sshd.common.forward.PortForwardingTest$1 119 |
establishedExplicitTunnel(session=ServerSessionImpl[testRemoteForwardingSecondTimeInSameSession@/127.0.0.1:42542],
local=localhost:42619, remote=null, bound=null, localForwarding=true): {}
java.lang.IllegalStateException: Can't overwrite cause with a null
at java.base/java.lang.Throwable.initCause(Throwable.java:462)
at
org.apache.mina.transport.socket.nio.NioSocketAcceptor.open(NioSocketAcceptor.java:273)
at
org.apache.mina.transport.socket.nio.NioSocketAcceptor.open(NioSocketAcceptor.java:52)
at
org.apache.mina.core.polling.AbstractPollingIoAcceptor$Acceptor.registerHandles(AbstractPollingIoAcceptor.java:591)
at
org.apache.mina.core.polling.AbstractPollingIoAcceptor$Acceptor.run(AbstractPollingIoAcceptor.java:460)
at
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.io.IOException: Error while binding on localhost/127.0.0.1:42619
original message : Address already in use
at
org.apache.mina.transport.socket.nio.NioSocketAcceptor.open(NioSocketAcceptor.java:272)
... 7 common frames omitted
Caused by: java.net.BindException: Address already in use
at java.base/sun.nio.ch.Net.bind0(Native Method)
at java.base/sun.nio.ch.Net.bind(Net.java:459)
at java.base/sun.nio.ch.Net.bind(Net.java:448)
at
java.base/sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:227)
at
java.base/sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:80)
at
org.apache.mina.transport.socket.nio.NioSocketAcceptor.open(NioSocketAcceptor.java:266)
... 7 common frames omitted
19:30:53.791 | WARN | MinaProcessor-9 | .a.s.s.s.ServerConnectionService |
org.apache.sshd.common.util.logging.LoggingUtils 626 |
globalRequest(ServerConnectionService[ServerSessionImpl[testRemoteForwardingSecondTimeInSameSession@/127.0.0.1:42542]])[tcpip-forward,
want-reply=true] failed (IllegalStateException) to process: Can't overwrite
cause with a null
Finished
org.apache.sshd.common.forward.PortForwardingTest:testRemoteForwardingSecondTimeInSameSession
in 60 ms
{code}
The {{IllegalStateException}} is a bug in Apache MINA 2.0.23 in
{{NioSocketAcceptor}} at [line
273|https://github.com/apache/mina/blob/9a8d1da279dfbd4302678bfb0495bb3277a4b2ad/mina-core/src/main/java/org/apache/mina/transport/socket/nio/NioSocketAcceptor.java#L273],
but it is irrelevant here since it occurs in the second {{bind()}} attempt,
not during {{{}unbind(){}}}. That bug appears to be fixed in Apache MINA 2.1.X,
and except for the log entry appears to be harmless enough.
The log reports "localhost:42619" to have been bound as "127.0.0.1:42619". The
log entries relating to the cancellation are not really helpful since they
report a combined address (host name from the original tcpip-forward request),
but code analysis show that this implies that JSch did send a cancellation
request for 127.0.0.1:42619 and Apache MINA sshd found the right entry. Apache
MINA sshd then uses {{unbind()}} on "127.0.0.1:42619". This doesn't appear to
cause any error.
Yet apparently the port has not been unbound.
The Apache MINA {{bind()}} and {{unbind()}} calls are synchronous. They're
executed on a different thread, but the calling thread waits on a future. I
don't see a race condition in the MINA code.
Could it be that some GitHub nodes are dual stack (IPv4 and IPv6) machines, and
others aren't? Would binding "localhost:42619" bind both "127.0.0.1:42619"
_and_ "[::1]:42619" on a dual stack machine? Then the {{unbind()}} would unbind
only IPv4, and the subsequent {{bind()}} then fail because IPv6 was still
bound? Sounds a bit far-fetched, especially since the issue occurs apparently
only with the Apache MINA transport, but not with NIO2 or Netty.
> PortForwardingTest.testRemoteForwardingSecondTimeInSameSession sometimes
> fails in Github CI
> -------------------------------------------------------------------------------------------
>
> Key: SSHD-1256
> URL: https://issues.apache.org/jira/browse/SSHD-1256
> Project: MINA SSHD
> Issue Type: Bug
> Affects Versions: 2.9.0
> Reporter: Thomas Wolf
> Priority: Major
>
> Cannot reproduce locally. A timing issue?
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@mina.apache.org
For additional commands, e-mail: dev-h...@mina.apache.org
