Once in a while, the client needs an surprising amount of seconds to
connect to the server.
I'm wondering if anyone knows why this could be or help me debug it?
In a good case, the output is:
2015-02-13 20:49:27,791 [oller-127.0.0.1] DEBUG
org.apache.sshd.client.session.ClientUserAuthServiceNew 101 -
Start authentication
2015-02-13 20:49:27,791 [oller-127.0.0.1] DEBUG
org.apache.sshd.client.session.ClientUserAuthServiceNew 105 - Send
SSH_MSG_USERAUTH_REQUEST for none
2015-02-13 20:49:27,791 []-nio2-thread-1] INFO
org.apache.sshd.client.session.ClientSessionImpl 306 -
Server version string: SSH-2.0-SSHD-CORE-0.12.0
2015-02-13 20:49:27,791 [oller-127.0.0.1] INFO
org.apache.sshd.common.session.AbstractSession 485 -
Start flagging packets as pending until key exchange is done
2015-02-13 20:49:28,229 []-nio2-thread-1] DEBUG
org.apache.sshd.common.session.AbstractSession 845 - Send
SSH_MSG_KEXINIT
2015-02-13 20:49:28,229 []-nio2-thread-1] TRACE
org.apache.sshd.common.session.AbstractSession 597 -
Sending packet #0: 14 4f 3a f0 96 26 69 42 85 32 5d 76 55 a1 87 75 24 00
00 00 b7 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 65 63 64 68 2d 73 68 61 32 2d 6e 69 73 74 70 32 35 36 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 35 32 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 07 73 73
68 2d 64 73 73 00 00 00 2b 61 65 73 31 32 38 2d 63 74 72 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 00 00 00 2b 61 65 73 31 32 38 2d 63 74 72 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 00 00 00 47 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 2c 68 6d 61
63 2d 6d 64 35 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 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 2c
68 6d 61 63 2d 6d 64 35 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
2015-02-13 20:49:28,229 []-nio2-thread-1] DEBUG
org.apache.sshd.common.io.nio2.Nio2Session 105 -
Writing 504 bytes
2015-02-13 20:49:28,230 []-nio2-thread-1] DEBUG
org.apache.sshd.common.io.nio2.Nio2Session$2 223 -
Finished writing
2015-02-13 20:49:28,230 []-nio2-thread-1] DEBUG
org.apache.sshd.common.io.nio2.Nio2Session$1 177 - Read
538 bytes
2015-02-13 20:49:28,230 []-nio2-thread-1] DEBUG
org.apache.sshd.server.session.ServerSession 136 -
Client version string: SSH-2.0-SSHD-CORE-0.12.0
In a bad case, the output is:
2015-02-12 20:45:58,399 [oller-127.0.0.1] DEBUG
org.apache.sshd.client.session.ClientUserAuthServiceNew 101 -
Start authentication
2015-02-12 20:45:58,399 [oller-127.0.0.1] DEBUG
org.apache.sshd.client.session.ClientUserAuthServiceNew 105 - Send
SSH_MSG_USERAUTH_REQUEST for none
2015-02-12 20:45:58,400 [oller-127.0.0.1] INFO
org.apache.sshd.common.session.AbstractSession 485 -
Start flagging packets as pending until key exchange is done
2015-02-12 20:45:58,400 []-nio2-thread-1] INFO
org.apache.sshd.client.session.ClientSessionImpl 306 -
Server version string: SSH-2.0-SSHD-CORE-0.12.0
2015-02-12 20:46:03,030 []-nio2-thread-1] DEBUG
org.apache.sshd.common.session.AbstractSession 845 - Send
SSH_MSG_KEXINIT
2015-02-12 20:46:03,031 []-nio2-thread-1] TRACE
org.apache.sshd.common.session.AbstractSession 597 -
Sending packet #0: 14 96 d5 61 92 81 db f6 29 f1 1e f3 a9 2b 24 69 e1 00
00 00 b7 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 65 63 64 68 2d 73 68 61 32 2d 6e 69 73 74 70 32 35 36 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 35 32 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 07 73 73
68 2d 64 73 73 00 00 00 2b 61 65 73 31 32 38 2d 63 74 72 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 00 00 00 2b 61 65 73 31 32 38 2d 63 74 72 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 00 00 00 47 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 2c 68 6d 61
63 2d 6d 64 35 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 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 2c
68 6d 61 63 2d 6d 64 35 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
2015-02-12 20:46:03,031 []-nio2-thread-1] DEBUG
org.apache.sshd.common.io.nio2.Nio2Session 105 -
Writing 504 bytes
2015-02-12 20:46:03,031 []-nio2-thread-1] DEBUG
org.apache.sshd.common.io.nio2.Nio2Session$2 223 -
Finished writing
2015-02-12 20:46:03,031 []-nio2-thread-1] DEBUG
org.apache.sshd.common.io.nio2.Nio2Session$1 177 - Read
538 bytes
2015-02-12 20:46:03,032 []-nio2-thread-1] DEBUG
org.apache.sshd.server.session.ServerSession 136 -
Client version string: SSH-2.0-SSHD-CORE-0.12.0
Note the 5 seconds delay in the second case. Any ideas?
- Martin
