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([email protected]:22) => null
2016-08-29 17:03:28,999 DEBUG main [o.a.s.c.SshClient]
connect([email protected]: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
