[
https://issues.apache.org/jira/browse/SSHD-894?focusedWorklogId=197508&page=com.atlassian.jira.plugin.system.issuetabpanels:worklog-tabpanel#worklog-197508
]
ASF GitHub Bot logged work on SSHD-894:
---------------------------------------
Author: ASF GitHub Bot
Created on: 12/Feb/19 11:46
Start Date: 12/Feb/19 11:46
Worklog Time Spent: 10m
Work Description: The-Yoda commented on issue #90: [SSHD-894] Fix Race
condition when doing async auth.
URL: https://github.com/apache/mina-sshd/pull/90#issuecomment-462727678
It is not intermittent. It is failing consistently. I tried with latest
master as well. Looks like I didn't paste correctly.
This is the actual error.
```
[ERROR] Errors:
[ERROR] CompressionTest.testCompression:146 » JSch Auth fail
[ERROR]
org.apache.sshd.common.forward.ApacheServerApacheClientTest.testHasLocalPortForwardingStarted(org.apache.sshd.common.forward.ApacheServerApacheClientTest)
[ERROR] Run 1: ApacheServerApacheClientTest.createClient:82 » IO
java.lang.IllegalArgumentExc...
[ERROR] Run 2: ApacheServerApacheClientTest.stopClient:93 NullPointer
```
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
[email protected]
Issue Time Tracking
-------------------
Worklog Id: (was: 197508)
Time Spent: 1.5h (was: 1h 20m)
> 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
> Assignee: Goldstein Lyor
> Priority: Minor
> Time Spent: 1.5h
> Remaining Estimate: 0h
>
> 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)
