I can confirm that my tests against the banner'd device work successfully with ClientUserAuthService patched to allow AuthFuture to be null in the process method [1]. I simply removed the not-null assertion and added null-checks to the first two if statements.
This implementation could allow #processUserAuth to be invoked while AuthFuture is null if some packets come in that are not banners or handled by ClientSession. However, #processUserAuth seems to also assert the presence of AuthFuture so I'm thinking the side effect would just be the assertion exception coming from that method instead of #process. I think this is something worth fixing/supporting, either with my code or something better suited to the edge-case, so I have submitted SSHD-695 [2]. [1] @Override public void process(int cmd, Buffer buffer) throws Exception { ClientSession session = getClientSession(); // let authFuture be null (not yet present) for handling packets coming in before // the client code has auth()'d AuthFuture authFuture = authFutureHolder.get(); if (authFuture != null && authFuture.isSuccess()) { throw new IllegalStateException("UserAuth message delivered to authenticated client"); } else if (authFuture != null && authFuture.isDone()) { if (log.isDebugEnabled()) { log.debug("process({}) Ignoring random message - cmd={}", session, SshConstants.getCommandMessageName(cmd)); } // ignore for now; TODO: random packets } else if (cmd == SshConstants.SSH_MSG_USERAUTH_BANNER) { String welcome = buffer.getString(); String lang = buffer.getString(); if (log.isDebugEnabled()) { log.debug("process({}) Welcome banner(lang={}): {}", session, lang, welcome); } UserInteraction ui = session.getUserInteraction(); try { if ((ui != null) && ui.isInteractionAllowed(session)) { ui.welcome(session, welcome, lang); } } catch (Error e) { log.warn("process({}) failed ({}) to consult interaction: {}", session, e.getClass().getSimpleName(), e.getMessage()); if (log.isDebugEnabled()) { log.debug("process(" + session + ") interaction consultation failure details", e); } throw new RuntimeSshException(e); } } else { buffer.rpos(buffer.rpos() - 1); processUserAuth(buffer); } } [2] https://issues.apache.org/jira/browse/SSHD-695 -----Original Message----- From: matthew.w.pi...@wellsfargo.com [mailto:matthew.w.pi...@wellsfargo.com] Sent: Tuesday, August 30, 2016 8:45 AM To: dev@mina.apache.org Subject: SSHD 1.2.0 Bug? - ClientUserAuthService asserts AuthFuture is non-null even for SSH_MSG_USERAUTH_BANNER packets. 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