Details
-
Bug
-
Status: Resolved
-
Minor
-
Resolution: Fixed
-
2.2.0
-
None
Description
Currently, when doing async auth, the response is being sent to client
before starting the service with auth status set. When the client
responds back with next request, the request will reach auth service and
fail with `No current authentication mechanism for cmd=SSH_MSG_CHANNEL_OPEN`.
This happens mostly when the system starts (as, service initialization
might take time)
Here is the exception trace:
07:52:20.706 [sshd-SshServer[9225652]-nio2-thread-4] TRACE org.apache.sshd.server.session.ServerSessionImpl - doHandleMessage(ServerSessionImpl[null@/0:0:0:0:0:0:0:1:62743]) process SSH_MSG_USERAUTH_REQUEST 07:52:20.706 [sshd-SshServer[9225652]-nio2-thread-4] DEBUG org.apache.sshd.server.session.ServerUserAuthService - process(ServerSessionImpl[null@/0:0:0:0:0:0:0:1:62743]) Received SSH_MSG_USERAUTH_REQUEST user=xxx, service=ssh-connection, method=password 07:52:20.706 [sshd-SshServer[9225652]-nio2-thread-4] DEBUG org.apache.sshd.server.session.ServerUserAuthService - process(ServerSessionImpl[null@/0:0:0:0:0:0:0:1:62743]) Authenticating user 'xxx' with service 'ssh-connection' and method 'password' (attempt 1 / 20) password 07:52:21.712 [Thread-2] DEBUG org.apache.sshd.server.session.ServerUserAuthService - handleAuthenticationSuccess(xxx@ServerSessionImpl[null@/0:0:0:0:0:0:0:1:62743]) SSH_MSG_USERAUTH_REQUEST 07:52:21.712 [Thread-2] TRACE org.apache.sshd.server.session.ServerSessionImpl - encode(ServerSessionImpl[ull@/0:0:0:0:0:0:0:1:62743]) packet #5 [chunk #1](1/1) 34 07:52:21.712 [Thread-2] DEBUG org.apache.sshd.common.io.nio2.Nio2Session - writePacket(Nio2Session[local=/0:0:0:0:0:0:0:1:2000, remote=/0:0:0:0:0:0:0:1:62743]) Writing 64 bytes 07:52:21.712 [Thread-2] TRACE org.apache.sshd.common.util.threads.SshdThreadFactory - newThread(java.lang.ThreadGroup[name=main,maxpri=10])[sshd-SshServer[9225652]-nio2-thread-5] runnable=java.util.concurrent.ThreadPoolExecutor$Worker@447ad89c[State = -1, empty queue] 07:52:21.713 [sshd-SshServer[9225652]-nio2-thread-5] DEBUG org.apache.sshd.common.io.nio2.Nio2Session - handleCompletedWriteCycle(Nio2Session[local=/0:0:0:0:0:0:0:1:2000, remote=/0:0:0:0:0:0:0:1:62743]) finished writing len=64 07:52:21.713 [Thread-0] TRACE org.apache.sshd.common.util.threads.SshdThreadFactory - newThread(java.lang.ThreadGroup[name=main,maxpri=10])[sshd-SshServer[9225652]-nio2-thread-6] runnable=java.util.concurrent.ThreadPoolExecutor$Worker@337d9585[State = -1, empty queue] 07:52:21.714 [sshd-SshServer[9225652]-nio2-thread-6] DEBUG org.apache.sshd.common.io.nio2.Nio2Session - handleReadCycleCompletion(Nio2Session[local=/0:0:0:0:0:0:0:1:2000, remote=/0:0:0:0:0:0:0:1:62743]) read 80 bytes 07:52:21.714 [sshd-SshServer[9225652]-nio2-thread-6] TRACE org.apache.sshd.server.session.ServerSessionImpl - decode(ServerSessionImpl[xxx@/0:0:0:0:0:0:0:1:62743]) packet #7 [chunk #1](24/24) 5a 00 00 00 07 73 65 73 73 69 6f 6e 00 00 00 01 00 20 00 00 00 00 80 00 Z....session............ 07:52:21.714 [sshd-SshServer[9225652]-nio2-thread-6] TRACE org.apache.sshd.server.session.ServerSessionImpl - doHandleMessage(ServerSessionImpl[xxx@/0:0:0:0:0:0:0:1:62743]) process SSH_MSG_CHANNEL_OPEN 07:52:21.716 [Thread-2] INFO org.apache.sshd.server.session.ServerUserAuthService - Session xxx@/0:0:0:0:0:0:0:1:62743 authenticated 07:52:21.717 [sshd-SshServer[9225652]-nio2-thread-6] DEBUG org.apache.sshd.common.io.nio2.Nio2Session - exceptionCaught(Nio2Session[local=/0:0:0:0:0:0:0:1:2000, remote=/0:0:0:0:0:0:0:1:62743]) caught IllegalStateException[No current authentication mechanism for cmd=SSH_MSG_CHANNEL_OPEN] - calling handler 07:52:21.717 [sshd-SshServer[9225652]-nio2-thread-6] WARN org.apache.sshd.server.session.ServerSessionImpl - exceptionCaught(ServerSessionImpl[xxx@/0:0:0:0:0:0:0:1:62743])[state=Opened] IllegalStateException: No current authentication mechanism for cmd=SSH_MSG_CHANNEL_OPEN 07:52:21.718 [sshd-SshServer[9225652]-nio2-thread-6] DEBUG org.apache.sshd.server.session.ServerSessionImpl - exceptionCaught(ServerSessionImpl[xxx@/0:0:0:0:0:0:0:1:62743])[state=Opened] details java.lang.IllegalStateException: No current authentication mechanism for cmd=SSH_MSG_CHANNEL_OPEN at org.apache.sshd.server.session.ServerUserAuthService.process(ServerUserAuthService.java:224) at org.apache.sshd.common.session.helpers.AbstractSession.doHandleMessage(AbstractSession.java:626) at org.apache.sshd.common.session.helpers.AbstractSession.handleMessage(AbstractSession.java:559) at org.apache.sshd.common.session.helpers.AbstractSession.decode(AbstractSession.java:1542) at org.apache.sshd.common.session.helpers.AbstractSession.messageReceived(AbstractSession.java:520) at org.apache.sshd.common.session.helpers.AbstractSessionIoHandler.messageReceived(AbstractSessionIoHandler.java:63) at org.apache.sshd.common.io.nio2.Nio2Session.handleReadCycleCompletion(Nio2Session.java:339) at org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:318) at org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:315) at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.lambda$completed$0(Nio2CompletionHandler.java:38) at java.security.AccessController.doPrivileged(Native Method) at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:37) at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126) at sun.nio.ch.Invoker$2.run(Invoker.java:218) at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) 07:52:21.719 [sshd-SshServer[9225652]-nio2-thread-6] DEBUG org.apache.sshd.common.session.helpers.SessionTimeoutListener - sessionException(ServerSessionImpl[xxx@/0:0:0:0:0:0:0:1:62743]) IllegalStateException: No current authentication mechanism for cmd=SSH_MSG_CHANNEL_OPEN
