You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mina.apache.org by Ma...@wellsfargo.com on 2016/08/29 12:16:04 UTC
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[xxxx@1.2.3.4: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
matthew.w.pitts@wellsfargo.com
RE: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
Posted by Ma...@wellsfargo.com.
Ok... I'm back :)... and I think I'm on to something. I was able to replicate the problem I'm seeing using basic/manual SshClient code [1] by introducing a sleep between connect().verify() and calling any auth methods. After enabling TRACE logging and weeding through it here's where I think the problem is...
The ASA I'm working with is configured with a login banner. This is coming back from the server as a SSH_MSG_USERAUTH_BANNER packet right after the client does sendInitialServiceRequest and receives the response, but *before* the auth() method has been called. Now, handling the banner packet goes to AbstractSession#doHandleMessage which does *not* have a switch block for SSH_MSG_USERAUTH_BANNER, so it falls back to calling #process on currentService. currentService at this point is a ClientUserAuthService and its #process method does handle the banner packets, but it also expects the AuthFuture to be present on the Session. So, when it fails to validate that AuthFuture is set, it throws an exception which short-circuits auth and the whole session exchange.
So, I'm thinking this is now a bug in ClientUserAuthService... I think it should allow AuthFuture to be null if the packet is a SSH_MSG_USERAUTH_BANNER. I don't think there is anything within the banner handling logic that requires the auth future to be present.
I've included the entire TRACE log [2] for reference.
Thoughts? Maybe I'm crazy?
Thanks,
-matt
[1]
try (SshClient client = SshClient.setUpDefaultClient())
{
client.start();
try (ClientSession session = client.connect(user, host, 22).verify(10, TimeUnit.SECONDS).getSession())
{
Thread.sleep(1000); // works without this line, fails with it
session.addPasswordIdentity(currentPassword);
session.auth().verify(10, TimeUnit.SECONDS);
// ... my custom code below
[2]
TRACE main [o.a.s.c.SshClient] addSessionListener(SshClient[5c41d037])[org.apache.sshd.common.session.helpers.SessionTimeoutListener@5f78de22] registered
2016-08-29 17:03:28,975 TRACE main [o.a.s.c.u.t.ThreadUtils$SshdThreadFactory] newThread(java.lang.ThreadGroup[name=main,maxpri=10])[sshd-SshClient[5c41d037]-timer-thread-1] runnable=java.util.concurrent.ThreadPoolExecutor$Worker@4d8539de[State = -1, empty queue]
2016-08-29 17:03:28,994 TRACE main [o.a.s.c.i.n.Nio2Connector] Creating Nio2Connector
2016-08-29 17:03:28,999 DEBUG main [o.a.s.c.c.h.DefaultConfigFileHostEntryResolver] resolveEffectiveHost(xxxxx@1.2.3.4:22) => null
2016-08-29 17:03:28,999 DEBUG main [o.a.s.c.SshClient] connect(xxxxx@1.2.3.4:22) no overrides
2016-08-29 17:03:29,002 DEBUG main [o.a.s.c.i.n.Nio2Connector] Connecting to /1.2.3.4:22
2016-08-29 17:03:29,006 DEBUG main [o.a.s.c.i.n.Nio2Connector] setOption(SO_REUSEADDR)[true] from property=socket-reuseaddr
2016-08-29 17:03:29,073 TRACE Thread-0 [o.a.s.c.u.t.ThreadUtils$SshdThreadFactory] newThread(java.lang.ThreadGroup[name=main,maxpri=10])[sshd-SshClient[5c41d037]-nio2-thread-1] runnable=java.util.concurrent.ThreadPoolExecutor$Worker@238cff73[State = -1, empty queue]
2016-08-29 17:03:29,078 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.i.n.Nio2Session] Creating IoSession on /0:0:0:0:0:0:0:0:59509 from /1.2.3.4:22
2016-08-29 17:03:29,095 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] calculateNextIgnorePacketCount(ClientSessionImpl[null@/1.2.3.4:22]) count=1033
2016-08-29 17:03:29,095 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] addSessionListener(ClientSessionImpl[null@/1.2.3.4:22])[null] registered
2016-08-29 17:03:29,096 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] addChannelListener(ClientSessionImpl[null@/1.2.3.4:22])[null] registered
2016-08-29 17:03:29,096 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] Client session created: Nio2Session[local=/0:0:0:0:0:0:0:0:59509, remote=/1.2.3.4:22]
2016-08-29 17:03:29,098 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientUserAuthService] ClientUserAuthService(ClientSessionImpl[null@/1.2.3.4:22]) client methods: [publickey, keyboard-interactive, password]
2016-08-29 17:03:29,104 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.h.SessionTimeoutListener] sessionCreated(ClientSessionImpl[null@/1.2.3.4:22]) tracking
2016-08-29 17:03:29,107 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] sendIdentification(ClientSessionImpl[null@/1.2.3.4:22]): SSH-2.0-SSHD-CORE-1.2.0
2016-08-29 17:03:29,107 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.i.n.Nio2Session] Writing 25 bytes
2016-08-29 17:03:29,109 TRACE Thread-0 [o.a.s.c.u.t.ThreadUtils$SshdThreadFactory] newThread(java.lang.ThreadGroup[name=main,maxpri=10])[sshd-SshClient[5c41d037]-nio2-thread-2] runnable=java.util.concurrent.ThreadPoolExecutor$Worker@2d4b1572[State = -1, empty queue]
2016-08-29 17:03:29,109 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] sendKexInit(ClientSessionImpl[null@/1.2.3.4:22]) Send SSH_MSG_KEXINIT
2016-08-29 17:03:29,109 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] sendKexInit(ClientSessionImpl[null@/1.2.3.4:22]) cookie=2e:18:d0:cf:30:47:d7:f8:b0:6a:d3:9b:6d:e6:c9:f3
2016-08-29 17:03:29,109 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] sendKexInit(}|)[ClientSessionImpl[null@/1.2.3.4:22]] kex algorithms
2016-08-29 17:03:29,109 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] sendKexInit(}|)[ClientSessionImpl[null@/1.2.3.4:22]] server host key algorithms
2016-08-29 17:03:29,109 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] sendKexInit(}|)[ClientSessionImpl[null@/1.2.3.4:22]] encryption algorithms (client to server)
2016-08-29 17:03:29,109 DEBUG sshd-SshClient[5c41d037]-nio2-thread-2 [o.a.s.c.i.n.Nio2Session] handleCompletedWriteCycle(Nio2Session[local=/0:0:0:0:0:0:0:0:59509, remote=/1.2.3.4:22]) finished writing len=25
2016-08-29 17:03:29,110 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] sendKexInit(}|)[ClientSessionImpl[null@/1.2.3.4:22]] encryption algorithms (server to client)
2016-08-29 17:03:29,110 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] sendKexInit(}|)[ClientSessionImpl[null@/1.2.3.4:22]] mac algorithms (client to server)
2016-08-29 17:03:29,110 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] sendKexInit(}|)[ClientSessionImpl[null@/1.2.3.4:22]] mac algorithms (server to client)
2016-08-29 17:03:29,110 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] sendKexInit(}|)[ClientSessionImpl[null@/1.2.3.4:22]] compression algorithms (client to server)
2016-08-29 17:03:29,110 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] sendKexInit(}|)[ClientSessionImpl[null@/1.2.3.4:22]] compression algorithms (server to client)
2016-08-29 17:03:29,110 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] sendKexInit(}|)[ClientSessionImpl[null@/1.2.3.4:22]] languages (client to server)
2016-08-29 17:03:29,110 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] sendKexInit(}|)[ClientSessionImpl[null@/1.2.3.4:22]] languages (server to client)
2016-08-29 17:03:29,113 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] encode(ClientSessionImpl[null@/1.2.3.4:22]) packet #0 [chunk #1](64/688) 14 2e 18 d0 cf 30 47 d7 f8 b0 6a d3 9b 6d e6 c9 f3 00 00 00 b7 65 63 64 68 2d 73 68 61 32 2d 6e 69 73 74 70 35 32 31 2c 65 63 64 68 2d 73 68 61 32 2d 6e 69 73 74 70 33 38 34 2c 65 63 64 68 2d
2016-08-29 17:03:29,113 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] encode(ClientSessionImpl[null@/1.2.3.4:22]) packet #0 [chunk #2](128/688) 73 68 61 32 2d 6e 69 73 74 70 32 35 36 2c 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 2d 65 78 63 68 61 6e 67 65 2d 73 68 61 32 35 36 2c 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61
2016-08-29 17:03:29,113 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] encode(ClientSessionImpl[null@/1.2.3.4:22]) packet #0 [chunk #3](192/688) 6e 2d 67 72 6f 75 70 2d 65 78 63 68 61 6e 67 65 2d 73 68 61 31 2c 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 31 34 2d 73 68 61 31 2c 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e
2016-08-29 17:03:29,114 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] encode(ClientSessionImpl[null@/1.2.3.4:22]) packet #0 [chunk #4](256/688) 2d 67 72 6f 75 70 31 2d 73 68 61 31 00 00 00 4b 65 63 64 73 61 2d 73 68 61 32 2d 6e 69 73 74 70 32 35 36 2c 65 63 64 73 61 2d 73 68 61 32 2d 6e 69 73 74 70 33 38 34 2c 65 63 64 73 61 2d 73 68
2016-08-29 17:03:29,114 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] encode(ClientSessionImpl[null@/1.2.3.4:22]) packet #0 [chunk #5](320/688) 61 32 2d 6e 69 73 74 70 35 32 31 2c 73 73 68 2d 72 73 61 2c 73 73 68 2d 64 73 73 00 00 00 6d 61 65 73 31 32 38 2d 63 74 72 2c 61 65 73 31 39 32 2d 63 74 72 2c 61 65 73 32 35 36 2d 63 74 72 2c
2016-08-29 17:03:29,114 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] encode(ClientSessionImpl[null@/1.2.3.4:22]) packet #0 [chunk #6](384/688) 61 72 63 66 6f 75 72 32 35 36 2c 61 72 63 66 6f 75 72 31 32 38 2c 61 65 73 31 32 38 2d 63 62 63 2c 33 64 65 73 2d 63 62 63 2c 62 6c 6f 77 66 69 73 68 2d 63 62 63 2c 61 65 73 31 39 32 2d 63 62
2016-08-29 17:03:29,114 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] encode(ClientSessionImpl[null@/1.2.3.4:22]) packet #0 [chunk #7](448/688) 63 2c 61 65 73 32 35 36 2d 63 62 63 00 00 00 6d 61 65 73 31 32 38 2d 63 74 72 2c 61 65 73 31 39 32 2d 63 74 72 2c 61 65 73 32 35 36 2d 63 74 72 2c 61 72 63 66 6f 75 72 32 35 36 2c 61 72 63 66
2016-08-29 17:03:29,114 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] encode(ClientSessionImpl[null@/1.2.3.4:22]) packet #0 [chunk #8](512/688) 6f 75 72 31 32 38 2c 61 65 73 31 32 38 2d 63 62 63 2c 33 64 65 73 2d 63 62 63 2c 62 6c 6f 77 66 69 73 68 2d 63 62 63 2c 61 65 73 31 39 32 2d 63 62 63 2c 61 65 73 32 35 36 2d 63 62 63 00 00 00
2016-08-29 17:03:29,114 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] encode(ClientSessionImpl[null@/1.2.3.4:22]) packet #0 [chunk #9](576/688) 47 68 6d 61 63 2d 6d 64 35 2c 68 6d 61 63 2d 73 68 61 31 2c 68 6d 61 63 2d 73 68 61 32 2d 32 35 36 2c 68 6d 61 63 2d 73 68 61 32 2d 35 31 32 2c 68 6d 61 63 2d 73 68 61 31 2d 39 36 2c 68 6d 61
2016-08-29 17:03:29,114 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] encode(ClientSessionImpl[null@/1.2.3.4:22]) packet #0 [chunk #10](640/688) 63 2d 6d 64 35 2d 39 36 00 00 00 47 68 6d 61 63 2d 6d 64 35 2c 68 6d 61 63 2d 73 68 61 31 2c 68 6d 61 63 2d 73 68 61 32 2d 32 35 36 2c 68 6d 61 63 2d 73 68 61 32 2d 35 31 32 2c 68 6d 61 63 2d
2016-08-29 17:03:29,114 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] encode(ClientSessionImpl[null@/1.2.3.4:22]) packet #0 [chunk #11](688/688) 73 68 61 31 2d 39 36 2c 68 6d 61 63 2d 6d 64 35 2d 39 36 00 00 00 04 6e 6f 6e 65 00 00 00 04 6e 6f 6e 65 00 00 00 00 00 00 00 00 00 00 00 00 00
2016-08-29 17:03:29,114 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.i.n.Nio2Session] Writing 704 bytes
2016-08-29 17:03:29,114 TRACE Thread-0 [o.a.s.c.u.t.ThreadUtils$SshdThreadFactory] newThread(java.lang.ThreadGroup[name=main,maxpri=10])[sshd-SshClient[5c41d037]-nio2-thread-3] runnable=java.util.concurrent.ThreadPoolExecutor$Worker@29749403[State = -1, empty queue]
2016-08-29 17:03:29,115 DEBUG sshd-SshClient[5c41d037]-nio2-thread-3 [o.a.s.c.i.n.Nio2Session] handleCompletedWriteCycle(Nio2Session[local=/0:0:0:0:0:0:0:0:59509, remote=/1.2.3.4:22]) finished writing len=704
2016-08-29 17:03:29,115 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] sendKexInit(ClientSessionImpl[null@/1.2.3.4:22]) proposal={ALGORITHMS=ecdh-sha2-nistp521,ecdh-sha2-nistp384,ecdh-sha2-nistp256,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1, SERVERKEYS=ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-rsa,ssh-dss, C2SENC=aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,aes192-cbc,aes256-cbc, S2CENC=aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,aes192-cbc,aes256-cbc, C2SMAC=hmac-md5,hmac-sha1,hmac-sha2-256,hmac-sha2-512,hmac-sha1-96,hmac-md5-96, S2CMAC=hmac-md5,hmac-sha1,hmac-sha2-256,hmac-sha2-512,hmac-sha1-96,hmac-md5-96, C2SCOMP=none, S2CCOMP=none, C2SLANG=, S2CLANG=} seed: 14:2e:18:d0:cf:30:47:d7:f8:b0:6a:d3:9b:6d:e6:c9:f3:00:00:00:b7:65:63:64:68:2d:73:68:61:32:2d:6e:69:73:74:70:35:32:31:2c:65:63:64:68:2d:73:68:61:32:2d:6e:69:73:74:70:33:38:34:2c:65:63:64:68:2d:73:68:61:32:2d:6e:69:73:74:70:32:35:36:2c:64:69:66:66:69:65:2d:68:65:6c:6c:6d:61:6e:2d:67:72:6f:75:70:2d:65:78:63:68:61:6e:67:65:2d:73:68:61:32:35:36:2c:64:69:66:66:69:65:2d:68:65:6c:6c:6d:61:6e:2d:67:72:6f:75:70:2d:65:78:63:68:61:6e:67:65:2d:73:68:61:31:2c:64:69:66:66:69:65:2d:68:65:6c:6c:6d:61:6e:2d:67:72:6f:75:70:31:34:2d:73:68:61:31:2c:64:69:66:66:69:65:2d:68:65:6c:6c:6d:61:6e:2d:67:72:6f:75:70:31:2d:73:68:61:31:00:00:00:4b:65:63:64:73:61:2d:73:68:61:32:2d:6e:69:73:74:70:32:35:36:2c:65:63:64:73:61:2d:73:68:61:32:2d:6e:69:73:74:70:33:38:34:2c:65:63:64:73:61:2d:73:68:61:32:2d:6e:69:73:74:70:35:32:31:2c:73:73:68:2d:72:73:61:2c:73:73:68:2d:64:73:73:00:00:00:6d:61:65:73:31:32:38:2d:63:74:72:2c:61:65:73:31:39:32:2d:63:74:72:2c:61:65:73:32:35:36:2d:63:74:72:2c:61:72:63:66:6f:75:72:32:35:36:2c:61:72:63:66:6f:75:72:31:32:38:2c:61:65:73:31:32:38:2d:63:62:63:2c:33:64:65:73:2d:63:62:63:2c:62:6c:6f:77:66:69:73:68:2d:63:62:63:2c:61:65:73:31:39:32:2d:63:62:63:2c:61:65:73:32:35:36:2d:63:62:63:00:00:00:6d:61:65:73:31:32:38:2d:63:74:72:2c:61:65:73:31:39:32:2d:63:74:72:2c:61:65:73:32:35:36:2d:63:74:72:2c:61:72:63:66:6f:75:72:32:35:36:2c:61:72:63:66:6f:75:72:31:32:38:2c:61:65:73:31:32:38:2d:63:62:63:2c:33:64:65:73:2d:63:62:63:2c:62:6c:6f:77:66:69:73:68:2d:63:62:63:2c:61:65:73:31:39:32:2d:63:62:63:2c:61:65:73:32:35:36:2d:63:62:63:00:00:00:47:68:6d:61:63:2d:6d:64:35:2c:68:6d:61:63:2d:73:68:61:31:2c:68:6d:61:63:2d:73:68:61:32:2d:32:35:36:2c:68:6d:61:63:2d:73:68:61:32:2d:35:31:32:2c:68:6d:61:63:2d:73:68:61:31:2d:39:36:2c:68:6d:61:63:2d:6d:64:35:2d:39:36:00:00:00:47:68:6d:61:63:2d:6d:64:35:2c:68:6d:61:63:2d:73:68:61:31:2c:68:6d:61:63:2d:73:68:61:32:2d:32:35:36:2c:68:6d:61:63:2d:73:68:61:32:2d:35:31:32:2c:68:6d:61:63:2d:73:68:61:31:2d:39:36:2c:68:6d:61:63:2d:6d:64:35:2d:39:36:00:00:00:04:6e:6f:6e:65:00:00:00:04:6e:6f:6e:65:00:00:00:00:00:00:00:00:00:00:00:00:00
2016-08-29 17:03:29,116 DEBUG main [o.a.s.c.f.DefaultConnectFuture] Connected to /1.2.3.4:22 after 106241321 nanos
2016-08-29 17:03:29,163 TRACE Thread-0 [o.a.s.c.u.t.ThreadUtils$SshdThreadFactory] newThread(java.lang.ThreadGroup[name=main,maxpri=10])[sshd-SshClient[5c41d037]-nio2-thread-4] runnable=java.util.concurrent.ThreadPoolExecutor$Worker@6c761f49[State = -1, empty queue]
2016-08-29 17:03:29,163 DEBUG sshd-SshClient[5c41d037]-nio2-thread-4 [o.a.s.c.i.n.Nio2Session] handleReadCycleCompletion(Nio2Session[local=/0:0:0:0:0:0:0:0:59509, remote=/1.2.3.4:22]) read 19 bytes
2016-08-29 17:03:29,164 DEBUG sshd-SshClient[5c41d037]-nio2-thread-4 [o.a.s.c.s.ClientSessionImpl] doReadIdentification(ClientSessionImpl[xxxxx@/1.2.3.4:22]) line='SSH-2.0-Cisco-1.25'
2016-08-29 17:03:29,164 DEBUG sshd-SshClient[5c41d037]-nio2-thread-4 [o.a.s.c.s.ClientSessionImpl] readIdentification(ClientSessionImpl[xxxxx@/1.2.3.4:22]) Server version string: SSH-2.0-Cisco-1.25
2016-08-29 17:03:29,169 TRACE Thread-0 [o.a.s.c.u.t.ThreadUtils$SshdThreadFactory] newThread(java.lang.ThreadGroup[name=main,maxpri=10])[sshd-SshClient[5c41d037]-nio2-thread-5] runnable=java.util.concurrent.ThreadPoolExecutor$Worker@28c502d3[State = -1, empty queue]
2016-08-29 17:03:29,170 DEBUG sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.i.n.Nio2Session] handleReadCycleCompletion(Nio2Session[local=/0:0:0:0:0:0:0:0:59509, remote=/1.2.3.4:22]) read 240 bytes
2016-08-29 17:03:29,170 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] decode(ClientSessionImpl[xxxxx@/1.2.3.4:22]) packet #1 [chunk #1](64/229) 14 99 92 08 a5 4c ab cc 06 bc 41 c0 fe b2 5a a4 2c 00 00 00 1a 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 31 2d 73 68 61 31 00 00 00 07 73 73 68 2d 72 73 61 00 00 00 29 61 65
2016-08-29 17:03:29,170 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] decode(ClientSessionImpl[xxxxx@/1.2.3.4:22]) packet #1 [chunk #2](128/229) 73 31 32 38 2d 63 62 63 2c 33 64 65 73 2d 63 62 63 2c 61 65 73 31 39 32 2d 63 62 63 2c 61 65 73 32 35 36 2d 63 62 63 00 00 00 29 61 65 73 31 32 38 2d 63 62 63 2c 33 64 65 73 2d 63 62 63 2c 61
2016-08-29 17:03:29,171 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] decode(ClientSessionImpl[xxxxx@/1.2.3.4:22]) packet #1 [chunk #3](192/229) 65 73 31 39 32 2d 63 62 63 2c 61 65 73 32 35 36 2d 63 62 63 00 00 00 16 68 6d 61 63 2d 73 68 61 31 2c 68 6d 61 63 2d 73 68 61 31 2d 39 36 00 00 00 16 68 6d 61 63 2d 73 68 61 31 2c 68 6d 61 63
2016-08-29 17:03:29,171 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] decode(ClientSessionImpl[xxxxx@/1.2.3.4:22]) packet #1 [chunk #4](229/229) 2d 73 68 61 31 2d 39 36 00 00 00 04 6e 6f 6e 65 00 00 00 04 6e 6f 6e 65 00 00 00 00 00 00 00 00 00 00 00 00 00
2016-08-29 17:03:29,177 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] doHandleMessage(ClientSessionImpl[xxxxx@/1.2.3.4:22]) process SSH_MSG_KEXINIT
2016-08-29 17:03:29,178 DEBUG sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] handleKexInit(ClientSessionImpl[xxxxx@/1.2.3.4:22]) SSH_MSG_KEXINIT
2016-08-29 17:03:29,178 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] receiveKexInit(ClientSessionImpl[xxxxx@/1.2.3.4:22]) cookie=99:92:08:a5:4c:ab:cc:06:bc:41:c0:fe:b2:5a:a4:2c
2016-08-29 17:03:29,178 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] receiveKexInit(ClientSessionImpl[xxxxx@/1.2.3.4:22])[kex algorithms] diffie-hellman-group1-sha1
2016-08-29 17:03:29,178 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] receiveKexInit(ClientSessionImpl[xxxxx@/1.2.3.4:22])[server host key algorithms] ssh-rsa
2016-08-29 17:03:29,178 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] receiveKexInit(ClientSessionImpl[xxxxx@/1.2.3.4:22])[encryption algorithms (client to server)] aes128-cbc,3des-cbc,aes192-cbc,aes256-cbc
2016-08-29 17:03:29,178 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] receiveKexInit(ClientSessionImpl[xxxxx@/1.2.3.4:22])[encryption algorithms (server to client)] aes128-cbc,3des-cbc,aes192-cbc,aes256-cbc
2016-08-29 17:03:29,178 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] receiveKexInit(ClientSessionImpl[xxxxx@/1.2.3.4:22])[mac algorithms (client to server)] hmac-sha1,hmac-sha1-96
2016-08-29 17:03:29,178 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] receiveKexInit(ClientSessionImpl[xxxxx@/1.2.3.4:22])[mac algorithms (server to client)] hmac-sha1,hmac-sha1-96
2016-08-29 17:03:29,178 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] receiveKexInit(ClientSessionImpl[xxxxx@/1.2.3.4:22])[compression algorithms (client to server)] none
2016-08-29 17:03:29,178 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] receiveKexInit(ClientSessionImpl[xxxxx@/1.2.3.4:22])[compression algorithms (server to client)] none
2016-08-29 17:03:29,178 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] receiveKexInit(ClientSessionImpl[xxxxx@/1.2.3.4:22])[languages (client to server)]
2016-08-29 17:03:29,178 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] receiveKexInit(ClientSessionImpl[xxxxx@/1.2.3.4:22])[languages (server to client)]
2016-08-29 17:03:29,178 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] receiveKexInit(ClientSessionImpl[xxxxx@/1.2.3.4:22]) first kex packet follows: false
2016-08-29 17:03:29,179 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] negotiate(ClientSessionImpl[xxxxx@/1.2.3.4:22])[kex algorithms] guess=diffie-hellman-group1-sha1 (client: ecdh-sha2-nistp521,ecdh-sha2-nistp384,ecdh-sha2-nistp256,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1 / server: diffie-hellman-group1-sha1)
2016-08-29 17:03:29,179 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] negotiate(ClientSessionImpl[xxxxx@/1.2.3.4:22])[server host key algorithms] guess=ssh-rsa (client: ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-rsa,ssh-dss / server: ssh-rsa)
2016-08-29 17:03:29,179 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] negotiate(ClientSessionImpl[xxxxx@/1.2.3.4:22])[encryption algorithms (client to server)] guess=aes128-cbc (client: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,aes192-cbc,aes256-cbc / server: aes128-cbc,3des-cbc,aes192-cbc,aes256-cbc)
2016-08-29 17:03:29,179 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] negotiate(ClientSessionImpl[xxxxx@/1.2.3.4:22])[encryption algorithms (server to client)] guess=aes128-cbc (client: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,aes192-cbc,aes256-cbc / server: aes128-cbc,3des-cbc,aes192-cbc,aes256-cbc)
2016-08-29 17:03:29,179 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] negotiate(ClientSessionImpl[xxxxx@/1.2.3.4:22])[mac algorithms (client to server)] guess=hmac-sha1 (client: hmac-md5,hmac-sha1,hmac-sha2-256,hmac-sha2-512,hmac-sha1-96,hmac-md5-96 / server: hmac-sha1,hmac-sha1-96)
2016-08-29 17:03:29,179 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] negotiate(ClientSessionImpl[xxxxx@/1.2.3.4:22])[mac algorithms (server to client)] guess=hmac-sha1 (client: hmac-md5,hmac-sha1,hmac-sha2-256,hmac-sha2-512,hmac-sha1-96,hmac-md5-96 / server: hmac-sha1,hmac-sha1-96)
2016-08-29 17:03:29,179 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] negotiate(ClientSessionImpl[xxxxx@/1.2.3.4:22])[compression algorithms (client to server)] guess=none (client: none / server: none)
2016-08-29 17:03:29,179 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] negotiate(ClientSessionImpl[xxxxx@/1.2.3.4:22])[compression algorithms (server to client)] guess=none (client: none / server: none)
2016-08-29 17:03:29,179 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] negotiate(ClientSessionImpl[xxxxx@/1.2.3.4:22]) Unable to negotiate key exchange for languages (client to server) (client: / server: )
2016-08-29 17:03:29,179 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] negotiate(ClientSessionImpl[xxxxx@/1.2.3.4:22]) Unable to negotiate key exchange for languages (server to client) (client: / server: )
2016-08-29 17:03:29,179 DEBUG sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] setNegotiationResult(ClientSessionImpl[xxxxx@/1.2.3.4:22]) Kex: server->client aes128-cbc hmac-sha1 none
2016-08-29 17:03:29,179 DEBUG sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] setNegotiationResult(ClientSessionImpl[xxxxx@/1.2.3.4:22]) Kex: client->server aes128-cbc hmac-sha1 none
2016-08-29 17:03:29,414 DEBUG sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.k.DHGClient] init(DHGClient[diffie-hellman-group1-sha1])[ClientSessionImpl[xxxxx@/1.2.3.4:22]] Send SSH_MSG_KEXDH_INIT
2016-08-29 17:03:29,414 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] encode(ClientSessionImpl[xxxxx@/1.2.3.4:22]) packet #1 [chunk #1](64/133) 1e 00 00 00 80 3b e9 b1 3a 93 ae 0b 7b f0 cb 45 78 1e e4 19 c3 a0 b5 fe 2e 8a b2 5c 6f 52 78 6d 1a 3e 7f 5e 7e 05 eb 32 8a b0 0d 0b e8 e8 2e 8d 3c 59 13 c5 1d 11 89 48 bc 83 32 98 11 9d bc 57
2016-08-29 17:03:29,414 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] encode(ClientSessionImpl[xxxxx@/1.2.3.4:22]) packet #1 [chunk #2](128/133) 56 24 e8 4d 7b 5f d0 1f a4 bc ba 09 a2 aa 96 aa e9 1f 8d 61 80 d1 ac fe ff 2b 87 d7 e8 e3 06 75 b4 a1 20 d6 0c a2 d2 75 5a db c9 68 c4 d2 6b 73 84 82 17 94 a1 f0 66 b9 21 7e 68 e2 11 c3 55 78
2016-08-29 17:03:29,414 TRACE sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.s.ClientSessionImpl] encode(ClientSessionImpl[xxxxx@/1.2.3.4:22]) packet #1 [chunk #3](133/133) 2e ad 76 0e e7
2016-08-29 17:03:29,415 DEBUG sshd-SshClient[5c41d037]-nio2-thread-5 [o.a.s.c.i.n.Nio2Session] Writing 152 bytes
2016-08-29 17:03:29,415 TRACE Thread-0 [o.a.s.c.u.t.ThreadUtils$SshdThreadFactory] newThread(java.lang.ThreadGroup[name=main,maxpri=10])[sshd-SshClient[5c41d037]-nio2-thread-6] runnable=java.util.concurrent.ThreadPoolExecutor$Worker@5d50723c[State = -1, empty queue]
2016-08-29 17:03:29,415 DEBUG sshd-SshClient[5c41d037]-nio2-thread-6 [o.a.s.c.i.n.Nio2Session] handleCompletedWriteCycle(Nio2Session[local=/0:0:0:0:0:0:0:0:59509, remote=/1.2.3.4:22]) finished writing len=152
2016-08-29 17:03:29,496 TRACE Thread-0 [o.a.s.c.u.t.ThreadUtils$SshdThreadFactory] newThread(java.lang.ThreadGroup[name=main,maxpri=10])[sshd-SshClient[5c41d037]-nio2-thread-7] runnable=java.util.concurrent.ThreadPoolExecutor$Worker@50093119[State = -1, empty queue]
2016-08-29 17:03:29,496 DEBUG sshd-SshClient[5c41d037]-nio2-thread-7 [o.a.s.c.i.n.Nio2Session] handleReadCycleCompletion(Nio2Session[local=/0:0:0:0:0:0:0:0:59509, remote=/1.2.3.4:22]) read 448 bytes
2016-08-29 17:03:29,497 TRACE sshd-SshClient[5c41d037]-nio2-thread-7 [o.a.s.c.s.ClientSessionImpl] decode(ClientSessionImpl[xxxxx@/1.2.3.4:22]) packet #2 [chunk #1](64/435) 1f 00 00 00 97 00 00 00 07 73 73 68 2d 72 73 61 00 00 00 03 01 00 01 00 00 00 81 00 9f f3 67 2c 42 d4 da f0 0b 06 6d f0 11 0a 4c d8 ca 2c 26 4f 97 e5 8f 0b e1 4e 6e d1 57 3f 6a 20 cc cd 51 c0
2016-08-29 17:03:29,497 TRACE sshd-SshClient[5c41d037]-nio2-thread-7 [o.a.s.c.s.ClientSessionImpl] decode(ClientSessionImpl[xxxxx@/1.2.3.4:22]) packet #2 [chunk #2](128/435) f4 9a 4b 40 08 f7 07 c3 3e 56 95 18 d6 ad 9a bf ee 0b 75 78 c4 2b 40 f6 4c 03 45 b5 59 69 12 13 f2 11 c0 1f 62 e0 97 a3 b6 2d 7f bf d5 77 47 a6 bd 7d 81 7a 93 5e 9b 5d 8d ed a4 55 7a e6 bd ba
2016-08-29 17:03:29,497 TRACE sshd-SshClient[5c41d037]-nio2-thread-7 [o.a.s.c.s.ClientSessionImpl] decode(ClientSessionImpl[xxxxx@/1.2.3.4:22]) packet #2 [chunk #3](192/435) 4e 0f 00 d4 53 e8 04 39 d3 04 b8 1a 27 19 93 02 c9 6b 1a c4 64 78 85 67 83 33 6d cd 00 00 00 80 3f f3 12 20 4d 6c 23 63 88 c0 18 19 ba f5 d5 fd 29 75 01 c1 b1 c9 95 2d 13 db f9 60 6e ba c7 5a
2016-08-29 17:03:29,497 TRACE sshd-SshClient[5c41d037]-nio2-thread-7 [o.a.s.c.s.ClientSessionImpl] decode(ClientSessionImpl[xxxxx@/1.2.3.4:22]) packet #2 [chunk #4](256/435) dd d8 76 f6 00 65 7b 59 31 a4 fb bf 7f 4e 25 8a 7c 89 b8 1d e6 b0 76 7f e2 af 6f 1f 81 df bc 4d 46 eb a2 c7 29 e1 74 26 a7 ce c0 4e f8 2d f0 7f 17 5d 63 db 54 54 b4 db 21 92 65 59 f6 fa 18 fa
2016-08-29 17:03:29,497 TRACE sshd-SshClient[5c41d037]-nio2-thread-7 [o.a.s.c.s.ClientSessionImpl] decode(ClientSessionImpl[xxxxx@/1.2.3.4:22]) packet #2 [chunk #5](320/435) be 36 b7 c7 99 9a 4d 96 37 07 1b c9 30 b8 ec 56 ff 1a 94 53 0c c8 0a 78 89 86 09 03 bb 0d 9e 22 00 00 00 8f 00 00 00 07 73 73 68 2d 72 73 61 00 00 00 80 33 4c 44 d6 04 a4 a6 bb 9f c2 bf 78 95
2016-08-29 17:03:29,497 TRACE sshd-SshClient[5c41d037]-nio2-thread-7 [o.a.s.c.s.ClientSessionImpl] decode(ClientSessionImpl[xxxxx@/1.2.3.4:22]) packet #2 [chunk #6](384/435) 8b a9 05 da 63 51 d2 04 ea 9b 39 bd 15 c1 5e 11 a8 5b 72 4e f0 e6 a4 3a f8 cf e4 90 ed e3 67 9f 5d 0a 18 40 10 70 53 61 57 ed 4f 16 f8 75 07 de 76 b8 40 fd 68 00 58 e6 22 a9 e0 17 c2 7f 95 5c
2016-08-29 17:03:29,497 TRACE sshd-SshClient[5c41d037]-nio2-thread-7 [o.a.s.c.s.ClientSessionImpl] decode(ClientSessionImpl[xxxxx@/1.2.3.4:22]) packet #2 [chunk #7](435/435) ec 03 70 0d 90 75 ba e8 7d 91 82 70 fd 86 00 00 a1 19 14 02 86 01 51 6a 2b 98 45 02 e0 41 00 f3 6b 71 3e e1 63 cc 49 ad 2b 4e 2b 6b 23 ba 91 f7 2a 18 82
2016-08-29 17:03:29,497 TRACE sshd-SshClient[5c41d037]-nio2-thread-7 [o.a.s.c.s.ClientSessionImpl] doHandleMessage(ClientSessionImpl[xxxxx@/1.2.3.4:22]) process 31
2016-08-29 17:03:29,514 DEBUG sshd-SshClient[5c41d037]-nio2-thread-7 [o.a.s.c.k.DHGClient] next(DHGClient[diffie-hellman-group1-sha1])[ClientSessionImpl[xxxxx@/1.2.3.4:22]] process command=SSH_MSG_KEXDH_REPLY
2016-08-29 17:03:29,547 DEBUG sshd-SshClient[5c41d037]-nio2-thread-7 [o.a.s.c.s.ClientSessionImpl] handleKexMessage(ClientSessionImpl[xxxxx@/1.2.3.4:22])[diffie-hellman-group1-sha1] KEX processing complete after cmd=31
2016-08-29 17:03:29,549 WARN sshd-SshClient[5c41d037]-nio2-thread-7 [o.a.s.c.k.AcceptAllServerKeyVerifier] Server at /1.2.3.4:22 presented unverified RSA key: SHA256:aC6qzQrtuiLhjXZZBV9ZcOiWYVx721xHbvxMQEkzChg
2016-08-29 17:03:29,549 DEBUG sshd-SshClient[5c41d037]-nio2-thread-7 [o.a.s.c.s.ClientSessionImpl] checkKeys(ClientSessionImpl[xxxxx@/1.2.3.4:22]) key=ssh-rsa-SHA256:aC6qzQrtuiLhjXZZBV9ZcOiWYVx721xHbvxMQEkzChg, verified=true
2016-08-29 17:03:29,549 DEBUG sshd-SshClient[5c41d037]-nio2-thread-7 [o.a.s.c.s.ClientSessionImpl] sendNewKeys(ClientSessionImpl[xxxxx@/1.2.3.4:22]) Send SSH_MSG_NEWKEYS
2016-08-29 17:03:29,549 TRACE sshd-SshClient[5c41d037]-nio2-thread-7 [o.a.s.c.s.ClientSessionImpl] encode(ClientSessionImpl[xxxxx@/1.2.3.4:22]) packet #2 [chunk #1](1/1) 15
2016-08-29 17:03:29,549 DEBUG sshd-SshClient[5c41d037]-nio2-thread-7 [o.a.s.c.i.n.Nio2Session] Writing 16 bytes
2016-08-29 17:03:29,550 TRACE Thread-0 [o.a.s.c.u.t.ThreadUtils$SshdThreadFactory] newThread(java.lang.ThreadGroup[name=main,maxpri=10])[sshd-SshClient[5c41d037]-nio2-thread-8] runnable=java.util.concurrent.ThreadPoolExecutor$Worker@c59e006[State = -1, empty queue]
2016-08-29 17:03:29,550 TRACE Thread-0 [o.a.s.c.u.t.ThreadUtils$SshdThreadFactory] newThread(java.lang.ThreadGroup[name=main,maxpri=10])[sshd-SshClient[5c41d037]-nio2-thread-9] runnable=java.util.concurrent.ThreadPoolExecutor$Worker@c0ab8c4[State = -1, empty queue]
2016-08-29 17:03:29,550 DEBUG sshd-SshClient[5c41d037]-nio2-thread-8 [o.a.s.c.i.n.Nio2Session] handleCompletedWriteCycle(Nio2Session[local=/0:0:0:0:0:0:0:0:59509, remote=/1.2.3.4:22]) finished writing len=16
2016-08-29 17:03:29,550 DEBUG sshd-SshClient[5c41d037]-nio2-thread-9 [o.a.s.c.i.n.Nio2Session] handleReadCycleCompletion(Nio2Session[local=/0:0:0:0:0:0:0:0:59509, remote=/1.2.3.4:22]) read 16 bytes
2016-08-29 17:03:29,551 TRACE sshd-SshClient[5c41d037]-nio2-thread-9 [o.a.s.c.s.ClientSessionImpl] decode(ClientSessionImpl[xxxxx@/1.2.3.4:22]) packet #3 [chunk #1](1/1) 15
2016-08-29 17:03:29,551 TRACE sshd-SshClient[5c41d037]-nio2-thread-9 [o.a.s.c.s.ClientSessionImpl] doHandleMessage(ClientSessionImpl[xxxxx@/1.2.3.4:22]) process SSH_MSG_NEWKEYS
2016-08-29 17:03:29,551 DEBUG sshd-SshClient[5c41d037]-nio2-thread-9 [o.a.s.c.s.ClientSessionImpl] handleNewKeys(ClientSessionImpl[xxxxx@/1.2.3.4:22]) SSH_MSG_NEWKEYS command=SSH_MSG_NEWKEYS
2016-08-29 17:03:29,551 DEBUG sshd-SshClient[5c41d037]-nio2-thread-9 [o.a.s.c.s.ClientSessionImpl] receiveNewKeys(ClientSessionImpl[xxxxx@/1.2.3.4:22]) session ID=66:cc:e2:04:82:b5:a1:66:99:8d:f7:25:eb:05:11:bb:b3:1a:c3:f6
2016-08-29 17:03:29,578 DEBUG sshd-SshClient[5c41d037]-nio2-thread-9 [o.a.s.c.s.ClientSessionImpl] receiveNewKeys(ClientSessionImpl[xxxxx@/1.2.3.4:22]) inCipher=BaseCipher[AES,16,16,AES/CBC/NoPadding], outCipher=BaseCipher[AES,16,16,AES/CBC/NoPadding], recommended blocks limit=4294967296, actual=4294967296
2016-08-29 17:03:29,579 DEBUG sshd-SshClient[5c41d037]-nio2-thread-9 [o.a.s.c.s.ClientSessionImpl] sendInitialServiceRequest(ClientSessionImpl[xxxxx@/1.2.3.4:22]) Send SSH_MSG_SERVICE_REQUEST for ssh-userauth
2016-08-29 17:03:29,579 TRACE sshd-SshClient[5c41d037]-nio2-thread-9 [o.a.s.c.s.ClientSessionImpl] encode(ClientSessionImpl[xxxxx@/1.2.3.4:22]) packet #3 [chunk #1](17/17) 05 00 00 00 0c 73 73 68 2d 75 73 65 72 61 75 74 68
2016-08-29 17:03:29,579 DEBUG sshd-SshClient[5c41d037]-nio2-thread-9 [o.a.s.c.i.n.Nio2Session] Writing 68 bytes
2016-08-29 17:03:29,579 DEBUG sshd-SshClient[5c41d037]-nio2-thread-9 [o.a.s.c.i.n.Nio2Session] handleCompletedWriteCycle(Nio2Session[local=/0:0:0:0:0:0:0:0:59509, remote=/1.2.3.4:22]) finished writing len=68
2016-08-29 17:03:29,674 DEBUG sshd-SshClient[5c41d037]-nio2-thread-3 [o.a.s.c.i.n.Nio2Session] handleReadCycleCompletion(Nio2Session[local=/0:0:0:0:0:0:0:0:59509, remote=/1.2.3.4:22]) read 52 bytes
2016-08-29 17:03:29,675 TRACE sshd-SshClient[5c41d037]-nio2-thread-3 [o.a.s.c.s.ClientSessionImpl] decode(ClientSessionImpl[xxxxx@/1.2.3.4:22]) packet #4 [chunk #1](17/17) 06 00 00 00 0c 73 73 68 2d 75 73 65 72 61 75 74 68
2016-08-29 17:03:29,675 TRACE sshd-SshClient[5c41d037]-nio2-thread-3 [o.a.s.c.s.ClientSessionImpl] doHandleMessage(ClientSessionImpl[xxxxx@/1.2.3.4:22]) process SSH_MSG_SERVICE_ACCEPT
2016-08-29 17:03:29,675 DEBUG sshd-SshClient[5c41d037]-nio2-thread-3 [o.a.s.c.s.ClientSessionImpl] handleServiceAccept(ClientSessionImpl[xxxxx@/1.2.3.4:22]) SSH_MSG_SERVICE_ACCEPT service=ssh-userauth
2016-08-29 17:03:29,676 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.i.n.Nio2Session] handleReadCycleCompletion(Nio2Session[local=/0:0:0:0:0:0:0:0:59509, remote=/1.2.3.4:22]) read 196 bytes
2016-08-29 17:03:29,677 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] decode(ClientSessionImpl[xxxxx@/1.2.3.4:22]) packet #5 [chunk #1](64/162) 35 00 00 00 99 4c 61 62 20 4d 4e 20 20 50 6c 65 61 73 65 20 65 6e 74 65 72 20 79 6f 75 72 20 6c 61 62 20 41 43 53 20 63 72 65 64 65 6e 74 69 61 6c 73 2e 20 20 59 6f 75 20 61 72 65 20 61 74 74
2016-08-29 17:03:29,677 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] decode(ClientSessionImpl[xxxxx@/1.2.3.4:22]) packet #5 [chunk #2](128/162) 65 6d 70 74 69 6e 67 20 74 6f 20 61 63 63 65 73 73 20 61 20 70 72 69 76 61 74 65 6c 79 20 6f 77 6e 65 64 20 6e 65 74 77 6f 72 6b 2e 20 20 41 6e 79 20 75 6e 61 75 74 68 6f 72 69 7a 65 64 20 61
2016-08-29 17:03:29,677 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] decode(ClientSessionImpl[xxxxx@/1.2.3.4:22]) packet #5 [chunk #3](162/162) 63 63 65 73 73 20 69 73 20 73 74 72 69 63 74 6c 79 20 70 72 6f 68 69 62 69 74 65 64 2e 0a 00 00 00 00
2016-08-29 17:03:29,677 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] doHandleMessage(ClientSessionImpl[xxxxx@/1.2.3.4:22]) process SSH_MSG_USERAUTH_BANNER
2016-08-29 17:03:29,679 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.i.n.Nio2Session] exceptionCaught(Nio2Session[local=/0:0:0:0:0:0:0:0:59509, remote=/1.2.3.4:22]) caught IllegalArgumentException[No current future] - calling handler
2016-08-29 17:03:29,680 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] signalAuthFailure(ClientSessionImpl[xxxxx@/1.2.3.4:22]) type=IllegalArgumentException, signalled=false, message="No current future"
2016-08-29 17:03:29,680 WARN sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] exceptionCaught(ClientSessionImpl[xxxxx@/1.2.3.4:22])[state=Opened] IllegalArgumentException: No current future
2016-08-29 17:03:29,685 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.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(ValidateUtils.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(ClientUserAuthService.java:167) ~[sshd-core-1.2.0.jar:1.2.0]
at org.apache.sshd.common.session.helpers.AbstractSession.doHandleMessage(AbstractSession.java:530) ~[sshd-core-1.2.0.jar:1.2.0]
at org.apache.sshd.common.session.helpers.AbstractSession.handleMessage(AbstractSession.java:463) ~[sshd-core-1.2.0.jar:1.2.0]
at org.apache.sshd.common.session.helpers.AbstractSession.decode(AbstractSession.java:1325) ~[sshd-core-1.2.0.jar:1.2.0]
at org.apache.sshd.common.session.helpers.AbstractSession.messageReceived(AbstractSession.java:424) ~[sshd-core-1.2.0.jar:1.2.0]
at org.apache.sshd.common.session.helpers.AbstractSessionIoHandler.messageReceived(AbstractSessionIoHandler.java:67) ~[sshd-core-1.2.0.jar:1.2.0]
at org.apache.sshd.common.io.nio2.Nio2Session.handleReadCycleCompletion(Nio2Session.java:285) ~[sshd-core-1.2.0.jar:1.2.0]
at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:265) [sshd-core-1.2.0.jar:1.2.0]
at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:262) [sshd-core-1.2.0.jar:1.2.0]
at org.apache.sshd.common.io.nio2.Nio2CompletionHandler$1.run(Nio2CompletionHandler.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(Nio2CompletionHandler.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.java:112) [na:1.8.0_92]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_92]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_92]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_92]
2016-08-29 17:03:29,685 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.h.SessionTimeoutListener] sessionException(ClientSessionImpl[xxxxx@/1.2.3.4:22]) IllegalArgumentException: No current future
2016-08-29 17:03:29,686 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.h.SessionTimeoutListener] sessionException(ClientSessionImpl[xxxxx@/1.2.3.4:22]) details
java.lang.IllegalArgumentException: No current future
at org.apache.sshd.common.util.ValidateUtils.throwIllegalArgumentException(ValidateUtils.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(ClientUserAuthService.java:167) ~[sshd-core-1.2.0.jar:1.2.0]
at org.apache.sshd.common.session.helpers.AbstractSession.doHandleMessage(AbstractSession.java:530) ~[sshd-core-1.2.0.jar:1.2.0]
at org.apache.sshd.common.session.helpers.AbstractSession.handleMessage(AbstractSession.java:463) ~[sshd-core-1.2.0.jar:1.2.0]
at org.apache.sshd.common.session.helpers.AbstractSession.decode(AbstractSession.java:1325) ~[sshd-core-1.2.0.jar:1.2.0]
at org.apache.sshd.common.session.helpers.AbstractSession.messageReceived(AbstractSession.java:424) ~[sshd-core-1.2.0.jar:1.2.0]
at org.apache.sshd.common.session.helpers.AbstractSessionIoHandler.messageReceived(AbstractSessionIoHandler.java:67) ~[sshd-core-1.2.0.jar:1.2.0]
at org.apache.sshd.common.io.nio2.Nio2Session.handleReadCycleCompletion(Nio2Session.java:285) ~[sshd-core-1.2.0.jar:1.2.0]
at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:265) ~[sshd-core-1.2.0.jar:1.2.0]
at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:262) ~[sshd-core-1.2.0.jar:1.2.0]
at org.apache.sshd.common.io.nio2.Nio2CompletionHandler$1.run(Nio2CompletionHandler.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(Nio2CompletionHandler.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.java:112) ~[na:1.8.0_92]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_92]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_92]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_92]
2016-08-29 17:03:29,686 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.h.SessionTimeoutListener] sessionClosed(ClientSessionImpl[xxxxx@/1.2.3.4:22]) un-tracked
2016-08-29 17:03:29,686 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] close(ClientSessionImpl[xxxxx@/1.2.3.4:22]) Closing immediately
2016-08-29 17:03:29,686 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] signalAuthFailure(ClientSessionImpl[xxxxx@/1.2.3.4:22]) type=SshException, signalled=false, message="Session is being closed"
2016-08-29 17:03:29,686 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.h.SessionTimeoutListener] sessionClosed(ClientSessionImpl[xxxxx@/1.2.3.4:22]) not tracked
2016-08-29 17:03:29,689 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.u.c.SequentialCloseable] doClose(true) closing org.apache.sshd.common.util.closeable.ParallelCloseable@2412268a
2016-08-29 17:03:29,690 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.u.c.ParallelCloseable] doClose(true) pending closeables: 2
2016-08-29 17:03:29,690 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientUserAuthService] close(org.apache.sshd.client.session.ClientUserAuthService@5644fedb) Closing immediately
2016-08-29 17:03:29,690 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientUserAuthService] close(org.apache.sshd.client.session.ClientUserAuthService@5644fedb)[Immediately] closed
2016-08-29 17:03:29,690 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.u.c.ParallelCloseable] doClose(true) completed pending: 1
2016-08-29 17:03:29,690 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.u.c.ParallelCloseable] doClose(true) pending closeables: 2
2016-08-29 17:03:29,690 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientConnectionService] close(ClientConnectionService[ClientSessionImpl[xxxxx@/1.2.3.4:22]]) Closing immediately
2016-08-29 17:03:29,691 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.u.c.ParallelCloseable] doClose(true) completed pending: 0
2016-08-29 17:03:29,691 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientConnectionService] close(ClientConnectionService[ClientSessionImpl[xxxxx@/1.2.3.4:22]])[Immediately] closed
2016-08-29 17:03:29,691 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.u.c.ParallelCloseable] doClose(true) completed pending: 1
2016-08-29 17:03:29,691 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.u.c.ParallelCloseable] doClose(true) completed pending: 0
2016-08-29 17:03:29,691 TRACE sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.u.c.SequentialCloseable] doClose(true) closing Nio2Session[local=/0:0:0:0:0:0:0:0:59509, remote=/1.2.3.4:22]
2016-08-29 17:03:29,691 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.i.n.Nio2Session] close(Nio2Session[local=/0:0:0:0:0:0:0:0:59509, remote=/1.2.3.4:22]) Closing immediately
2016-08-29 17:03:29,692 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] close(ClientSessionImpl[xxxxx@/1.2.3.4:22])[Immediately] state already Immediate
2016-08-29 17:03:29,692 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.i.n.Nio2Session] close(Nio2Session[local=/0:0:0:0:0:0:0:0:59509, remote=/1.2.3.4:22])[Immediately] closed
2016-08-29 17:03:29,692 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.u.c.SequentialCloseable] doClose(true) signal close complete
2016-08-29 17:03:29,692 DEBUG sshd-SshClient[5c41d037]-nio2-thread-1 [o.a.s.c.s.ClientSessionImpl] close(ClientSessionImpl[xxxxx@/1.2.3.4:22])[Immediately] closed
2016-08-29 17:03:34,117 DEBUG main [o.a.s.c.s.ClientSessionImpl] addPasswordIdentity(ClientSessionImpl[xxxxx@/1.2.3.4:22]) SHA256:OWW8NRwvizIDrXitYsiyPXnU2t1t5ugtTD2rbl8ycT8
2016-08-29 17:03:34,117 DEBUG main [o.a.s.c.s.ClientUserAuthService] auth(ClientSessionImpl[xxxxx@/1.2.3.4:22])[ssh-connection] send SSH_MSG_USERAUTH_REQUEST for 'none'
2016-08-29 17:03:34,118 TRACE main [o.a.s.c.s.ClientSessionImpl] encode(ClientSessionImpl[xxxxx@/1.2.3.4:22]) packet #4 [chunk #1](37/37) 32 00 00 00 06 6e 73 61 75 74 6f 00 00 00 0e 73 73 68 2d 63 6f 6e 6e 65 63 74 69 6f 6e 00 00 00 04 6e 6f 6e 65
2016-08-29 17:03:34,118 DEBUG main [o.a.s.c.i.n.Nio2Session] Writing 84 bytes
2016-08-29 17:03:44,121 DEBUG main [o.a.s.c.SshClient] close(SshClient[5c41d037]) Closing immediately
2016-08-29 17:03:44,123 TRACE main [o.a.s.c.u.c.SequentialCloseable] doClose(true) closing org.apache.sshd.common.util.closeable.Builder$1@710d7aff
2016-08-29 17:03:44,123 TRACE main [o.a.s.c.SshClient] removeSessionListener(SshClient[5c41d037])[org.apache.sshd.common.session.helpers.SessionTimeoutListener@5f78de22] removed
2016-08-29 17:03:44,123 TRACE main [o.a.s.c.u.c.SequentialCloseable] doClose(true) closing org.apache.sshd.common.io.nio2.Nio2Connector@2d7e1102
2016-08-29 17:03:44,123 DEBUG main [o.a.s.c.i.n.Nio2Connector] close(org.apache.sshd.common.io.nio2.Nio2Connector@2d7e1102) Closing immediately
2016-08-29 17:03:44,123 TRACE main [o.a.s.c.u.c.ParallelCloseable] doClose(true) completed pending: 0
2016-08-29 17:03:44,123 DEBUG main [o.a.s.c.i.n.Nio2Connector] close(org.apache.sshd.common.io.nio2.Nio2Connector@2d7e1102)[Immediately] closed
2016-08-29 17:03:44,123 TRACE main [o.a.s.c.u.c.SequentialCloseable] doClose(true) closing org.apache.sshd.common.io.nio2.Nio2ServiceFactory@65327f5
2016-08-29 17:03:44,123 DEBUG main [o.a.s.c.i.n.Nio2ServiceFactory] close(org.apache.sshd.common.io.nio2.Nio2ServiceFactory@65327f5) Closing immediately
2016-08-29 17:03:44,123 DEBUG main [o.a.s.c.i.n.Nio2ServiceFactory] Shutdown group
2016-08-29 17:03:44,125 DEBUG main [o.a.s.c.i.n.Nio2ServiceFactory] Group successfully shut down
2016-08-29 17:03:44,125 DEBUG main [o.a.s.c.i.n.Nio2ServiceFactory] close(org.apache.sshd.common.io.nio2.Nio2ServiceFactory@65327f5)[Immediately] closed
2016-08-29 17:03:44,125 TRACE main [o.a.s.c.u.c.SequentialCloseable] doClose(true) closing org.apache.sshd.common.util.closeable.Builder$1@2adddc06
2016-08-29 17:03:44,125 DEBUG main [o.a.s.c.u.c.SequentialCloseable] doClose(true) signal close complete
2016-08-29 17:03:44,125 DEBUG main [o.a.s.c.SshClient] close(SshClient[5c41d037])[Immediately] closed
RE: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
Posted by Ma...@wellsfargo.com.
Ok, makes sense... I have managed to simplify my test down to raw
SshClient/session creation and it appears to get past the auth phase on the
ASAs. It must be something with how my code is doing the client/session
setup/management but it's interesting that it is only showing on the ASAs...
maybe just a timing issue.
I'll post more details if I can't get past it.
Thanks for the help!
-matt
-----Original Message-----
From: elijah baley [mailto:e_baley@outlook.com]
Sent: Monday, August 29, 2016 3:43 PM
To: dev@mina.apache.org
Subject: Re: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
Hard to say without seeing the code and debugging it
________________________________
From: Matthew.W.Pitts@wellsfargo.com <Ma...@wellsfargo.com>
Sent: Monday, August 29, 2016 10:41 PM
To: dev@mina.apache.org
Subject: RE: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
Ok, thanks. This helps me understand the context better.
So is the java.lang.IllegalArgumentException I detailed not an issue?
-----Original Message-----
From: elijah baley [mailto:e_baley@outlook.com]
Sent: Monday, August 29, 2016 2:10 PM
To: dev@mina.apache.org
Subject: Re: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
" seems to break the authentication due to how the
SSHD client sends auth_request right after KEX even if ClientSession#auth
has not been called yet. "
As far as I can tell this is entirely according to the standard + should
pose no problem to the server - all it does is indicate to the server that
authentication is shortly about to follow - which is true since after
connect one must authenticate...
________________________________
From: Matthew.W.Pitts@wellsfargo.com <Ma...@wellsfargo.com>
Sent: Monday, August 29, 2016 8:30 PM
To: dev@mina.apache.org
Subject: RE: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
I thought there was API at both the SshClient and ClientSession levels to
specific authentication information... both inherit from
org.apache.sshd.client.ClientAuthenticationManager which would seem to
indicate you can do things like #addPasswordIdentity at either level.
I will try to develop a unit test straight from your sample code, but I have
existing code that works with v0.8.0 on these devices and upgrading to 1.2.0
(with some refactoring) seems to break the authentication due to how the
SSHD client sends auth_request right after KEX even if ClientSession#auth
has not been called yet. This is only happening on the Cisco ASA devices...
I have several other devices that are working fine with 1.2.0 and my
existing code, so I'm wondering too if it is something with Cisco's SSH
implementation.
Thanks for the input
-matt
-----Original Message-----
From: elijah baley [mailto:e_baley@outlook.com]
Sent: Monday, August 29, 2016 1:03 PM
To: dev@mina.apache.org
Subject: Re: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
Can you post some code that shows the client side ? My concern is with
"Could this be because I am specifying my authentication at the session
level rather than the client level?"
In order to do that correctly one needs to use a
SessionListener#sessionCreated and modify the KEX:
@Override
public void sessionCreated(Session s) {
s.setXXX... - e.g., s.setUserAuthFactories(...);
}
Anyway, some code snippet showing what you are trying to do and how you set
up the client, connect the session and then authenticate would help diagnose
the issue.
________________________________
From: Matthew.W.Pitts@wellsfargo.com <Ma...@wellsfargo.com>
Sent: Monday, August 29, 2016 6:14 PM
To: dev@mina.apache.org
Subject: RE: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
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: Matthew.W.Pitts@wellsfargo.com [mailto:Matthew.W.Pitts@wellsfargo.com]
Sent: Monday, August 29, 2016 8:16 AM
To: dev@mina.apache.org
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. I'm 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'. I'm no SSH expert so I may
not understand this correctly, but the ASA devices simply don't 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[xxxx@1.2.3.4: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
matthew.w.pitts@wellsfargo.com
Re: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
Posted by elijah baley <e_...@outlook.com>.
Hard to say without seeing the code and debugging it
________________________________
From: Matthew.W.Pitts@wellsfargo.com <Ma...@wellsfargo.com>
Sent: Monday, August 29, 2016 10:41 PM
To: dev@mina.apache.org
Subject: RE: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as service name 'ssh-connection'?
Ok, thanks. This helps me understand the context better.
So is the java.lang.IllegalArgumentException I detailed not an issue?
-----Original Message-----
From: elijah baley [mailto:e_baley@outlook.com]
Sent: Monday, August 29, 2016 2:10 PM
To: dev@mina.apache.org
Subject: Re: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as service name 'ssh-connection'?
" seems to break the authentication due to how the
SSHD client sends auth_request right after KEX even if ClientSession#auth
has not been called yet. "
As far as I can tell this is entirely according to the standard + should pose no problem to the server - all it does is indicate to the server that authentication is shortly about to follow - which is true since after connect one must authenticate...
________________________________
From: Matthew.W.Pitts@wellsfargo.com <Ma...@wellsfargo.com>
Sent: Monday, August 29, 2016 8:30 PM
To: dev@mina.apache.org
Subject: RE: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as service name 'ssh-connection'?
I thought there was API at both the SshClient and ClientSession levels to
specific authentication information... both inherit from
org.apache.sshd.client.ClientAuthenticationManager which would seem to
indicate you can do things like #addPasswordIdentity at either level.
I will try to develop a unit test straight from your sample code, but I have
existing code that works with v0.8.0 on these devices and upgrading to 1.2.0
(with some refactoring) seems to break the authentication due to how the
SSHD client sends auth_request right after KEX even if ClientSession#auth
has not been called yet. This is only happening on the Cisco ASA devices...
I have several other devices that are working fine with 1.2.0 and my
existing code, so I'm wondering too if it is something with Cisco's SSH
implementation.
Thanks for the input
-matt
-----Original Message-----
From: elijah baley [mailto:e_baley@outlook.com]
Sent: Monday, August 29, 2016 1:03 PM
To: dev@mina.apache.org
Subject: Re: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
Can you post some code that shows the client side ? My concern is with
"Could this be because I am specifying my authentication at the session
level rather than the client level?"
In order to do that correctly one needs to use a
SessionListener#sessionCreated and modify the KEX:
@Override
public void sessionCreated(Session s) {
s.setXXX... - e.g., s.setUserAuthFactories(...);
}
Anyway, some code snippet showing what you are trying to do and how you set
up the client, connect the session and then authenticate would help diagnose
the issue.
________________________________
From: Matthew.W.Pitts@wellsfargo.com <Ma...@wellsfargo.com>
Sent: Monday, August 29, 2016 6:14 PM
To: dev@mina.apache.org
Subject: RE: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
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: Matthew.W.Pitts@wellsfargo.com [mailto:Matthew.W.Pitts@wellsfargo.com]
Sent: Monday, August 29, 2016 8:16 AM
To: dev@mina.apache.org
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. I'm 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'. I'm no SSH expert so I may
not understand this correctly, but the ASA devices simply don't 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[xxxx@1.2.3.4: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
matthew.w.pitts@wellsfargo.com
RE: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
Posted by Ma...@wellsfargo.com.
Ok, thanks. This helps me understand the context better.
So is the java.lang.IllegalArgumentException I detailed not an issue?
-----Original Message-----
From: elijah baley [mailto:e_baley@outlook.com]
Sent: Monday, August 29, 2016 2:10 PM
To: dev@mina.apache.org
Subject: Re: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as service name 'ssh-connection'?
" seems to break the authentication due to how the
SSHD client sends auth_request right after KEX even if ClientSession#auth
has not been called yet. "
As far as I can tell this is entirely according to the standard + should pose no problem to the server - all it does is indicate to the server that authentication is shortly about to follow - which is true since after connect one must authenticate...
________________________________
From: Matthew.W.Pitts@wellsfargo.com <Ma...@wellsfargo.com>
Sent: Monday, August 29, 2016 8:30 PM
To: dev@mina.apache.org
Subject: RE: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as service name 'ssh-connection'?
I thought there was API at both the SshClient and ClientSession levels to
specific authentication information... both inherit from
org.apache.sshd.client.ClientAuthenticationManager which would seem to
indicate you can do things like #addPasswordIdentity at either level.
I will try to develop a unit test straight from your sample code, but I have
existing code that works with v0.8.0 on these devices and upgrading to 1.2.0
(with some refactoring) seems to break the authentication due to how the
SSHD client sends auth_request right after KEX even if ClientSession#auth
has not been called yet. This is only happening on the Cisco ASA devices...
I have several other devices that are working fine with 1.2.0 and my
existing code, so I'm wondering too if it is something with Cisco's SSH
implementation.
Thanks for the input
-matt
-----Original Message-----
From: elijah baley [mailto:e_baley@outlook.com]
Sent: Monday, August 29, 2016 1:03 PM
To: dev@mina.apache.org
Subject: Re: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
Can you post some code that shows the client side ? My concern is with
"Could this be because I am specifying my authentication at the session
level rather than the client level?"
In order to do that correctly one needs to use a
SessionListener#sessionCreated and modify the KEX:
@Override
public void sessionCreated(Session s) {
s.setXXX... - e.g., s.setUserAuthFactories(...);
}
Anyway, some code snippet showing what you are trying to do and how you set
up the client, connect the session and then authenticate would help diagnose
the issue.
________________________________
From: Matthew.W.Pitts@wellsfargo.com <Ma...@wellsfargo.com>
Sent: Monday, August 29, 2016 6:14 PM
To: dev@mina.apache.org
Subject: RE: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
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: Matthew.W.Pitts@wellsfargo.com [mailto:Matthew.W.Pitts@wellsfargo.com]
Sent: Monday, August 29, 2016 8:16 AM
To: dev@mina.apache.org
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. I'm 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'. I'm no SSH expert so I may
not understand this correctly, but the ASA devices simply don't 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[xxxx@1.2.3.4: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
matthew.w.pitts@wellsfargo.com
Re: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
Posted by elijah baley <e_...@outlook.com>.
" seems to break the authentication due to how the
SSHD client sends auth_request right after KEX even if ClientSession#auth
has not been called yet. "
As far as I can tell this is entirely according to the standard + should pose no problem to the server - all it does is indicate to the server that authentication is shortly about to follow - which is true since after connect one must authenticate...
________________________________
From: Matthew.W.Pitts@wellsfargo.com <Ma...@wellsfargo.com>
Sent: Monday, August 29, 2016 8:30 PM
To: dev@mina.apache.org
Subject: RE: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as service name 'ssh-connection'?
I thought there was API at both the SshClient and ClientSession levels to
specific authentication information... both inherit from
org.apache.sshd.client.ClientAuthenticationManager which would seem to
indicate you can do things like #addPasswordIdentity at either level.
I will try to develop a unit test straight from your sample code, but I have
existing code that works with v0.8.0 on these devices and upgrading to 1.2.0
(with some refactoring) seems to break the authentication due to how the
SSHD client sends auth_request right after KEX even if ClientSession#auth
has not been called yet. This is only happening on the Cisco ASA devices...
I have several other devices that are working fine with 1.2.0 and my
existing code, so I'm wondering too if it is something with Cisco's SSH
implementation.
Thanks for the input
-matt
-----Original Message-----
From: elijah baley [mailto:e_baley@outlook.com]
Sent: Monday, August 29, 2016 1:03 PM
To: dev@mina.apache.org
Subject: Re: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
Can you post some code that shows the client side ? My concern is with
"Could this be because I am specifying my authentication at the session
level rather than the client level?"
In order to do that correctly one needs to use a
SessionListener#sessionCreated and modify the KEX:
@Override
public void sessionCreated(Session s) {
s.setXXX... - e.g., s.setUserAuthFactories(...);
}
Anyway, some code snippet showing what you are trying to do and how you set
up the client, connect the session and then authenticate would help diagnose
the issue.
________________________________
From: Matthew.W.Pitts@wellsfargo.com <Ma...@wellsfargo.com>
Sent: Monday, August 29, 2016 6:14 PM
To: dev@mina.apache.org
Subject: RE: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
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: Matthew.W.Pitts@wellsfargo.com [mailto:Matthew.W.Pitts@wellsfargo.com]
Sent: Monday, August 29, 2016 8:16 AM
To: dev@mina.apache.org
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. I'm 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'. I'm no SSH expert so I may
not understand this correctly, but the ASA devices simply don't 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[xxxx@1.2.3.4: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
matthew.w.pitts@wellsfargo.com
Re: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
Posted by elijah baley <e_...@outlook.com>.
Indeed one can use the client and/or the session for authentication details. If placing the authentication details on the client, then all sessions will use the same password for all users - which is not what is usually meant. The use-case for placing authentication data on the client rather than the session is intended more for public key authentication where some code want to use the same public key identity for all users and all sessions.
In any case, the code flow that I have shown is the recommended one - unless special program requirements. As far as CISCO's implementation of SSH - we have tested the SSH client interoperability with OpenSSH and to some extent DropBear. If the code I recommended still poses problems, please (a) post the client setup code you are using and (b) open a JIRA issue on https://issues.apache.org/jira - preferably with some way to reproduce CISCO's SSH server...
________________________________
From: Matthew.W.Pitts@wellsfargo.com <Ma...@wellsfargo.com>
Sent: Monday, August 29, 2016 8:30 PM
To: dev@mina.apache.org
Subject: RE: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as service name 'ssh-connection'?
I thought there was API at both the SshClient and ClientSession levels to
specific authentication information... both inherit from
org.apache.sshd.client.ClientAuthenticationManager which would seem to
indicate you can do things like #addPasswordIdentity at either level.
I will try to develop a unit test straight from your sample code, but I have
existing code that works with v0.8.0 on these devices and upgrading to 1.2.0
(with some refactoring) seems to break the authentication due to how the
SSHD client sends auth_request right after KEX even if ClientSession#auth
has not been called yet. This is only happening on the Cisco ASA devices...
I have several other devices that are working fine with 1.2.0 and my
existing code, so I'm wondering too if it is something with Cisco's SSH
implementation.
Thanks for the input
-matt
-----Original Message-----
From: elijah baley [mailto:e_baley@outlook.com]
Sent: Monday, August 29, 2016 1:03 PM
To: dev@mina.apache.org
Subject: Re: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
Can you post some code that shows the client side ? My concern is with
"Could this be because I am specifying my authentication at the session
level rather than the client level?"
In order to do that correctly one needs to use a
SessionListener#sessionCreated and modify the KEX:
@Override
public void sessionCreated(Session s) {
s.setXXX... - e.g., s.setUserAuthFactories(...);
}
Anyway, some code snippet showing what you are trying to do and how you set
up the client, connect the session and then authenticate would help diagnose
the issue.
________________________________
From: Matthew.W.Pitts@wellsfargo.com <Ma...@wellsfargo.com>
Sent: Monday, August 29, 2016 6:14 PM
To: dev@mina.apache.org
Subject: RE: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
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: Matthew.W.Pitts@wellsfargo.com [mailto:Matthew.W.Pitts@wellsfargo.com]
Sent: Monday, August 29, 2016 8:16 AM
To: dev@mina.apache.org
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. I'm 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'. I'm no SSH expert so I may
not understand this correctly, but the ASA devices simply don't 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[xxxx@1.2.3.4: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
matthew.w.pitts@wellsfargo.com
RE: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
Posted by Ma...@wellsfargo.com.
I thought there was API at both the SshClient and ClientSession levels to
specific authentication information... both inherit from
org.apache.sshd.client.ClientAuthenticationManager which would seem to
indicate you can do things like #addPasswordIdentity at either level.
I will try to develop a unit test straight from your sample code, but I have
existing code that works with v0.8.0 on these devices and upgrading to 1.2.0
(with some refactoring) seems to break the authentication due to how the
SSHD client sends auth_request right after KEX even if ClientSession#auth
has not been called yet. This is only happening on the Cisco ASA devices...
I have several other devices that are working fine with 1.2.0 and my
existing code, so I'm wondering too if it is something with Cisco's SSH
implementation.
Thanks for the input
-matt
-----Original Message-----
From: elijah baley [mailto:e_baley@outlook.com]
Sent: Monday, August 29, 2016 1:03 PM
To: dev@mina.apache.org
Subject: Re: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
Can you post some code that shows the client side ? My concern is with
"Could this be because I am specifying my authentication at the session
level rather than the client level?"
In order to do that correctly one needs to use a
SessionListener#sessionCreated and modify the KEX:
@Override
public void sessionCreated(Session s) {
s.setXXX... - e.g., s.setUserAuthFactories(...);
}
Anyway, some code snippet showing what you are trying to do and how you set
up the client, connect the session and then authenticate would help diagnose
the issue.
________________________________
From: Matthew.W.Pitts@wellsfargo.com <Ma...@wellsfargo.com>
Sent: Monday, August 29, 2016 6:14 PM
To: dev@mina.apache.org
Subject: RE: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
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: Matthew.W.Pitts@wellsfargo.com [mailto:Matthew.W.Pitts@wellsfargo.com]
Sent: Monday, August 29, 2016 8:16 AM
To: dev@mina.apache.org
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. I'm 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'. I'm no SSH expert so I may
not understand this correctly, but the ASA devices simply don't 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[xxxx@1.2.3.4: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
matthew.w.pitts@wellsfargo.com
Re: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
Posted by elijah baley <e_...@outlook.com>.
Can you post some code that shows the client side ? My concern is with
"Could this be because I am specifying my authentication at the session level rather than the client level?"
In order to do that correctly one needs to use a SessionListener#sessionCreated and modify the KEX:
@Override
public void sessionCreated(Session s) {
s.setXXX... - e.g., s.setUserAuthFactories(...);
}
Anyway, some code snippet showing what you are trying to do and how you set up the client, connect the session and then authenticate would help diagnose the issue.
________________________________
From: Matthew.W.Pitts@wellsfargo.com <Ma...@wellsfargo.com>
Sent: Monday, August 29, 2016 6:14 PM
To: dev@mina.apache.org
Subject: RE: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as service name 'ssh-connection'?
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: Matthew.W.Pitts@wellsfargo.com [mailto:Matthew.W.Pitts@wellsfargo.com]
Sent: Monday, August 29, 2016 8:16 AM
To: dev@mina.apache.org
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. I’m 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’. I’m no SSH expert so I may
not understand this correctly, but the ASA devices simply don’t 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[xxxx@1.2.3.4: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
matthew.w.pitts@wellsfargo.com
Re: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
Posted by elijah baley <e_...@outlook.com>.
Here is how the code should work (there are other options but this is the simplest):
SshClient client = SshClient.setupDefaultClient();
client.set... - override if needed some defaults
try (ClientSession session = client.connect(user, host, port).verify(...timeout...).getSession()) {
session.addPasswordIdentity(...password...);
or
session.addPublicKeyIdentity(...keypair...);
session.auth().verify(...timeout...);
...session is ready to be used...
}
________________________________
From: Matthew.W.Pitts@wellsfargo.com <Ma...@wellsfargo.com>
Sent: Monday, August 29, 2016 7:48 PM
To: dev@mina.apache.org
Subject: RE: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as service name 'ssh-connection'?
More of my own discoveries...
I can confirm that by simply applying my authentication credentials at the SshClient-level rather than the session level that the login and session execute normally. So, why does sendInitialServiceRequest seem to prevent session-level authentication from working on these devices?
Thanks
-matt
-----Original Message-----
From: Matthew.W.Pitts@wellsfargo.com [mailto:Matthew.W.Pitts@wellsfargo.com]
Sent: Monday, August 29, 2016 11:15 AM
To: dev@mina.apache.org
Subject: RE: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as service name 'ssh-connection'?
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: Matthew.W.Pitts@wellsfargo.com [mailto:Matthew.W.Pitts@wellsfargo.com]
Sent: Monday, August 29, 2016 8:16 AM
To: dev@mina.apache.org
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. I'm 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'. I'm no SSH expert so I may
not understand this correctly, but the ASA devices simply don't 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[xxxx@1.2.3.4: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
matthew.w.pitts@wellsfargo.com
RE: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
Posted by Ma...@wellsfargo.com.
More of my own discoveries...
I can confirm that by simply applying my authentication credentials at the SshClient-level rather than the session level that the login and session execute normally. So, why does sendInitialServiceRequest seem to prevent session-level authentication from working on these devices?
Thanks
-matt
-----Original Message-----
From: Matthew.W.Pitts@wellsfargo.com [mailto:Matthew.W.Pitts@wellsfargo.com]
Sent: Monday, August 29, 2016 11:15 AM
To: dev@mina.apache.org
Subject: RE: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as service name 'ssh-connection'?
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: Matthew.W.Pitts@wellsfargo.com [mailto:Matthew.W.Pitts@wellsfargo.com]
Sent: Monday, August 29, 2016 8:16 AM
To: dev@mina.apache.org
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. I'm 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'. I'm no SSH expert so I may
not understand this correctly, but the ASA devices simply don't 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[xxxx@1.2.3.4: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
matthew.w.pitts@wellsfargo.com
RE: SSHD v1.2.0 client sending SSH_MSG_USERAUTH_REQUEST packet as
service name 'ssh-connection'?
Posted by Ma...@wellsfargo.com.
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: Matthew.W.Pitts@wellsfargo.com [mailto:Matthew.W.Pitts@wellsfargo.com]
Sent: Monday, August 29, 2016 8:16 AM
To: dev@mina.apache.org
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[xxxx@1.2.3.4: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
matthew.w.pitts@wellsfargo.com