Ok, adding some context here as I may be getting closer to this problem... So the log/exception in [1] seems to indicate to me that the client/server are indeed starting the auth exchange properly. However, it seems as though this exchange is *starting* prior to calling session.auth() so there is no AuthFuture present. This seems to initiate from ClientSession's override of #sendSessionEvent where it calls #sendInitialServiceRequest for KeyEstablished events.
Could this be because I am specifying my authentication at the session level
rather than the client level? So, it's as if the Kex and initial service
request happen so fast, that my code hasn't called session#auth. Is this
possible and/or normal?
[1]
10:48:14.401 [sshd-SshClient[33a630fa]-nio2-thread-9] DEBUG
o.a.s.c.session.ClientSessionImpl -
sendInitialServiceRequest(ClientSessionImpl[xxxxx@/1.2.3.4:22]) Send
SSH_MSG_SERVICE_REQUEST for ssh-userauth
10:48:14.402 [sshd-SshClient[33a630fa]-nio2-thread-9] DEBUG
o.a.sshd.common.io.nio2.Nio2Session - Writing 68 bytes
10:48:14.402 [sshd-SshClient[33a630fa]-nio2-thread-2] DEBUG
o.a.sshd.common.io.nio2.Nio2Session -
handleCompletedWriteCycle(Nio2Session[local=/0:0:0:0:0:0:0:0:51883,
remote=/1.2.3.4:22]) finished writing len=68
10:48:14.474 [sshd-SshClient[33a630fa]-nio2-thread-1] DEBUG
o.a.sshd.common.io.nio2.Nio2Session -
handleReadCycleCompletion(Nio2Session[local=/0:0:0:0:0:0:0:0:51883,
remote=/1.2.3.4:22]) read 52 bytes
10:48:14.475 [sshd-SshClient[33a630fa]-nio2-thread-1] DEBUG
o.a.s.c.session.ClientSessionImpl -
handleServiceAccept(ClientSessionImpl[xxxxx@/1.2.3.4:22])
SSH_MSG_SERVICE_ACCEPT service=ssh-userauth
10:48:14.475 [sshd-SshClient[33a630fa]-nio2-thread-3] DEBUG
o.a.sshd.common.io.nio2.Nio2Session -
handleReadCycleCompletion(Nio2Session[local=/0:0:0:0:0:0:0:0:51883,
remote=/1.2.3.4:22]) read 196 bytes
10:48:14.476 [sshd-SshClient[33a630fa]-nio2-thread-3] DEBUG
o.a.sshd.common.io.nio2.Nio2Session -
exceptionCaught(Nio2Session[local=/0:0:0:0:0:0:0:0:51883,
remote=/1.2.3.4:22]) caught IllegalArgumentException[No current future] -
calling handler
10:48:14.477 [sshd-SshClient[33a630fa]-nio2-thread-3] DEBUG
o.a.s.c.session.ClientSessionImpl -
signalAuthFailure(ClientSessionImpl[xxxxx@/1.2.3.4:22])
type=IllegalArgumentException, signalled=false, message="No current future"
10:48:14.477 [sshd-SshClient[33a630fa]-nio2-thread-3] WARN
o.a.s.c.session.ClientSessionImpl -
exceptionCaught(ClientSessionImpl[xxxxx@/1.2.3.4:22])[state=Opened]
IllegalArgumentException: No current future
10:48:14.483 [sshd-SshClient[33a630fa]-nio2-thread-3] DEBUG
o.a.s.c.session.ClientSessionImpl -
exceptionCaught(ClientSessionImpl[xxxxx@/1.2.3.4:22])[state=Opened] details
java.lang.IllegalArgumentException: No current future
at
org.apache.sshd.common.util.ValidateUtils.throwIllegalArgumentException(Vali
dateUtils.java:138) ~[sshd-core-1.2.0.jar:1.2.0]
at
org.apache.sshd.common.util.ValidateUtils.checkTrue(ValidateUtils.java:115)
~[sshd-core-1.2.0.jar:1.2.0]
at
org.apache.sshd.common.util.ValidateUtils.checkNotNull(ValidateUtils.java:34
) ~[sshd-core-1.2.0.jar:1.2.0]
at
org.apache.sshd.client.session.ClientUserAuthService.process(ClientUserAuthS
ervice.java:167) ~[sshd-core-1.2.0.jar:1.2.0]
at
org.apache.sshd.common.session.helpers.AbstractSession.doHandleMessage(Abstr
actSession.java:530) ~[sshd-core-1.2.0.jar:1.2.0]
at
org.apache.sshd.common.session.helpers.AbstractSession.handleMessage(Abstrac
tSession.java:463) ~[sshd-core-1.2.0.jar:1.2.0]
at
org.apache.sshd.common.session.helpers.AbstractSession.decode(AbstractSessio
n.java:1325) ~[sshd-core-1.2.0.jar:1.2.0]
at
org.apache.sshd.common.session.helpers.AbstractSession.messageReceived(Abstr
actSession.java:424) ~[sshd-core-1.2.0.jar:1.2.0]
at
org.apache.sshd.common.session.helpers.AbstractSessionIoHandler.messageRecei
ved(AbstractSessionIoHandler.java:67) ~[sshd-core-1.2.0.jar:1.2.0]
at
org.apache.sshd.common.io.nio2.Nio2Session.handleReadCycleCompletion(Nio2Ses
sion.java:285) ~[sshd-core-1.2.0.jar:1.2.0]
at
org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:26
5) [sshd-core-1.2.0.jar:1.2.0]
at
org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:26
2) [sshd-core-1.2.0.jar:1.2.0]
at
org.apache.sshd.common.io.nio2.Nio2CompletionHandler$1.run(Nio2CompletionHan
dler.java:37) [sshd-core-1.2.0.jar:1.2.0]
at java.security.AccessController.doPrivileged(Native Method)
[na:1.8.0_92]
at
org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2Completio
nHandler.java:34) [sshd-core-1.2.0.jar:1.2.0]
at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
[na:1.8.0_92]
at sun.nio.ch.Invoker$2.run(Invoker.java:218) [na:1.8.0_92]
at
sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.j
ava:112) [na:1.8.0_92]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:11
42) [na:1.8.0_92]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:6
17) [na:1.8.0_92]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_92]
10:48:14.484 [sshd-SshClient[33a630fa]-nio2-thread-3] DEBUG
o.a.s.c.s.h.SessionTimeoutListener -
sessionException(ClientSessionImpl[xxxxx@/1.2.3.4:22])
IllegalArgumentException: No current future
10:48:14.484 [sshd-SshClient[33a630fa]-nio2-thread-3] DEBUG
o.a.s.c.s.h.SessionTimeoutListener -
sessionClosed(ClientSessionImpl[xxxxx@/1.2.3.4:22]) un-tracked
10:48:14.484 [sshd-SshClient[33a630fa]-nio2-thread-3] DEBUG
o.a.s.c.session.ClientSessionImpl -
close(ClientSessionImpl[xxxxx@/1.2.3.4:22]) Closing immediately
-----Original Message-----
From: [email protected] [mailto:[email protected]]
Sent: Monday, August 29, 2016 8:16 AM
To: [email protected]
Subject: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
I am testing sshd 1.2.0 against a bunch of devices that we are currently
accessing just fine using version 0.8.0. Im running into problems during
the authentication phase when logging into Cisco ASA devices. I am seeing
logs like [1] which appear to indicate that the SSHD library is sending the
SSH_MSG_USERAUTH_REQEUST packet under the ssh-connection service name
which I would expect to see as ssh-userauth. Im no SSH expert so I may
not understand this correctly, but the ASA devices simply dont respond to
this packet/request and my session login eventually times-out.
When testing the same device with v0.8.0 I see that the login process seems
to jump straight to 'ssh-userauth' after key exchange as indicated by the
logs at [2]. This works fine with the devices and the session executes
normally.
Any ideas here? Is it OK for SSH_MSG_USERAUTH_REQUEST packets to be sent
with service name 'ssh-connection'?
If this is normal, is there a way to work with devices that don't seem to
respond to these packets?
Thanks in advance for any help you can give on this.
[1]
07:51:08.022 [main] DEBUG o.a.s.c.s.ClientUserAuthService -
auth(ClientSessionImpl[[email protected]:22])[ssh-connection] send
SSH_MSG_USERAUTH_REQUEST for 'none'
[2]
07:43:54.266 [NioProcessor-2] INFO o.a.s.c.session.ClientSessionImpl -
Received SSH_MSG_NEWKEYS
07:43:54.277 [NioProcessor-2] INFO o.a.s.c.session.ClientSessionImpl - Send
SSH_MSG_SERVICE_REQUEST for ssh-userauth
07:43:54.490 [NioProcessor-2] DEBUG o.a.s.c.session.ClientSessionImpl -
Received packet SSH_MSG_SERVICE_ACCEPT
Matthew Pitts
Developer
Security Solutions Design & Automation
Wells Fargo Bank | Tel 336.608.3332 | Cell 336.202.3913 | Kernersville, NC |
MAC D9693-010
[email protected]
smime.p7s
Description: S/MIME cryptographic signature
