I originally posted this under a separate subject, but as I dug into it I
believe I may have run across an edge-case or bug. Please review and advise...
When using basic SSHD client code [1] to talk to an SSH server that is
configured with a login banner...
- If the KEX is completed
*and*
- sendInitialServiceRequest+response is completed
*and*
- then the server sends the SSH_MSG_USERAUTH_BANNER packet
*and*
- it is processed in the client
And all this happens *before* the client code has invoked ClientSession#auth to
create the AuthFuture...
*then*
Since ClientUserAuthService#process expects the AuthFuture to be present on the
Session, it throws an exception which short-circuits auth and the whole session
exchange.
So, I'm thinking ClientUserAuthService#process 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.
As an aside, I think I'm seeing this with this particular device because it is
using older key algorithms which I believe are allowing the KEX process to
complete really quickly. With other devices/algorithms I imagine that the KEX
process would 'eat' up enough time to allow #auth() to be called before the
banner packet gets back to the client. But, it is still a timing issue that
could happen with any device if there is enough delay from connect() to auth().
Thoughts?
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, also
fails with more custom client code that has a few call-stacks between connect()
and auth()
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
