Subramaniajeeva created SSHD-894:
------------------------------------
Summary: Race condition when doing async auth
Key: SSHD-894
URL: https://issues.apache.org/jira/browse/SSHD-894
Project: MINA SSHD
Issue Type: Bug
Affects Versions: 2.2.0
Reporter: Subramaniajeeva
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:
{noformat}
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
{noformat}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
