Re: Hang in nonblocking ssh_connect

[Doug Judd <doug@xxxxxxxxxxxxxx>]

Below is verbose logging output from a run of my application when it
hangs.  The application is trying to connect to four hosts (master, slave1,
slave2, slave3) and is run on the master.  Connections are established
beforehand and then registered with:

ssh_options_set(m_ssh_session, SSH_OPTIONS_FD, &m_sd);
As I mentioned before, the session is set to non-blocking mode and I use
edge-triggered epoll for socket event notification.  The problem is easily
reproducible on these machines.

[master] === SshSocketHandler.cc:216 === Entering handler (events=WRITE,
state=INITIAL)
[master] ssh_connect: libssh 0.6.3 (c) 2003-2014 Aris Adamantiadis, Andreas
Schneider, and libssh contributors. Distributed under the LGPL, please
refer to COPYING file for information about your rights, using threading
threads_cpp
[master] === SshSocketHandler.cc:550 === connect_status_callback 20%
[master] ssh_connect: Socket connecting, now waiting for the callbacks to
work
[master] ssh_socket_pollcallback: Received POLLOUT in connecting state
[master] socket_callback_connected: Wrong state in
socket_callback_connected : 2
[master] ssh_connect: ssh_connect: Actual state : 2
[master] === SshSocketHandler.cc:499 === Leaving handler
(poll_interest=READ|WRITE, state=COMPLETE_CONNECTION)
[slave1] === SshSocketHandler.cc:216 === Entering handler (events=WRITE,
state=INITIAL)
[master] ssh_connect: libssh 0.6.3 (c) 2003-2014 Aris Adamantiadis, Andreas
Schneider, and libssh contributors. Distributed under the LGPL, please
refer to COPYING file for information about your rights, using threading
threads_cpp
[slave1] === SshSocketHandler.cc:550 === connect_status_callback 20%
[master] ssh_connect: Socket connecting, now waiting for the callbacks to
work
[master] ssh_socket_pollcallback: Received POLLOUT in connecting state
[master] socket_callback_connected: Wrong state in
socket_callback_connected : 2
[master] ssh_connect: ssh_connect: Actual state : 2
[slave1] === SshSocketHandler.cc:499 === Leaving handler
(poll_interest=READ|WRITE, state=COMPLETE_CONNECTION)
[slave2] === SshSocketHandler.cc:216 === Entering handler
(events=READ|WRITE, state=INITIAL)
[master] ssh_connect: libssh 0.6.3 (c) 2003-2014 Aris Adamantiadis, Andreas
Schneider, and libssh contributors. Distributed under the LGPL, please
refer to COPYING file for information about your rights, using threading
threads_cpp
[slave2] === SshSocketHandler.cc:550 === connect_status_callback 20%
[master] ssh_connect: Socket connecting, now waiting for the callbacks to
work
[master] ssh_socket_pollcallback: Received POLLOUT in connecting state
[master] socket_callback_connected: Wrong state in
socket_callback_connected : 2
[master] ssh_connect: ssh_connect: Actual state : 2
[slave2] === SshSocketHandler.cc:499 === Leaving handler
(poll_interest=READ|WRITE, state=COMPLETE_CONNECTION)
[slave3] === SshSocketHandler.cc:216 === Entering handler (events=WRITE,
state=INITIAL)
[master] ssh_connect: libssh 0.6.3 (c) 2003-2014 Aris Adamantiadis, Andreas
Schneider, and libssh contributors. Distributed under the LGPL, please
refer to COPYING file for information about your rights, using threading
threads_cpp
[slave3] === SshSocketHandler.cc:550 === connect_status_callback 20%
[master] ssh_connect: Socket connecting, now waiting for the callbacks to
work
[master] ssh_socket_pollcallback: Received POLLOUT in connecting state
[master] socket_callback_connected: Wrong state in
socket_callback_connected : 2
[master] ssh_connect: ssh_connect: Actual state : 2
[slave3] === SshSocketHandler.cc:499 === Leaving handler
(poll_interest=READ|WRITE, state=COMPLETE_CONNECTION)
[slave1] === SshSocketHandler.cc:216 === Entering handler
(events=READ|WRITE, state=COMPLETE_CONNECTION)
[master] callback_receive_banner: Received banner: SSH-2.0-OpenSSH_6.2
[slave1] === SshSocketHandler.cc:550 === connect_status_callback 40%
[master] ssh_client_connection_callback: SSH server banner:
SSH-2.0-OpenSSH_6.2
[master] ssh_analyze_banner: Analyzing banner: SSH-2.0-OpenSSH_6.2
[master] ssh_analyze_banner: We are talking to an OpenSSH client version:
6.2 (60200)
[slave1] === SshSocketHandler.cc:550 === connect_status_callback 50%
[master] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[master] ssh_connect: ssh_connect: Actual state : 4
[slave1] === SshSocketHandler.cc:499 === Leaving handler
(poll_interest=WRITE, state=COMPLETE_CONNECTION)
[slave3] === SshSocketHandler.cc:216 === Entering handler
(events=READ|WRITE, state=COMPLETE_CONNECTION)
[master] callback_receive_banner: Received banner: SSH-2.0-OpenSSH_6.2
[slave3] === SshSocketHandler.cc:550 === connect_status_callback 40%
[master] ssh_client_connection_callback: SSH server banner:
SSH-2.0-OpenSSH_6.2
[master] ssh_analyze_banner: Analyzing banner: SSH-2.0-OpenSSH_6.2
[master] ssh_analyze_banner: We are talking to an OpenSSH client version:
6.2 (60200)
[slave3] === SshSocketHandler.cc:550 === connect_status_callback 50%
[master] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[master] ssh_connect: ssh_connect: Actual state : 4
[slave3] === SshSocketHandler.cc:499 === Leaving handler
(poll_interest=WRITE, state=COMPLETE_CONNECTION)
[slave1] === SshSocketHandler.cc:216 === Entering handler
(events=READ|WRITE, state=COMPLETE_CONNECTION)
[master] ssh_packet_socket_callback: packet: read type 20
[len=1540,padding=7,comp=1532,payload=1532]
[master] ssh_packet_process: Dispatching handler for packet type 20
[slave1] === SshSocketHandler.cc:550 === connect_status_callback 60%
[master] ssh_list_kex: kex algos:
ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
[master] ssh_list_kex: server host key algo:
ssh-rsa,ssh-dss,ecdsa-sha2-nistp256
[master] ssh_list_kex: encryption client->server:
aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,
aes128-gcm@xxxxxxxxxxx,aes256-gcm@xxxxxxxxxxx
,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,
rijndael-cbc@xxxxxxxxxxxxxx
[master] ssh_list_kex: encryption server->client:
aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,
aes128-gcm@xxxxxxxxxxx,aes256-gcm@xxxxxxxxxxx
,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,
rijndael-cbc@xxxxxxxxxxxxxx
[master] ssh_list_kex: mac algo client->server: hmac-md5-etm@xxxxxxxxxxx,
hmac-sha1-etm@xxxxxxxxxxx,umac-64-etm@xxxxxxxxxxx,umac-128-etm@xxxxxxxxxxx,
hmac-sha2-256-etm@xxxxxxxxxxx,hmac-sha2-512-etm@xxxxxxxxxxx,
hmac-ripemd160-etm@xxxxxxxxxxx,hmac-sha1-96-etm@xxxxxxxxxxx,
hmac-md5-96-etm@xxxxxxxxxxx,hmac-md5,hmac-sha1,umac-64@xxxxxxxxxxx,
umac-128@xxxxxxxxxxx,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,
hmac-ripemd160@xxxxxxxxxxx,hmac-sha1-96,hmac-md5-96
[master] ssh_list_kex: mac algo server->client: hmac-md5-etm@xxxxxxxxxxx,
hmac-sha1-etm@xxxxxxxxxxx,umac-64-etm@xxxxxxxxxxx,umac-128-etm@xxxxxxxxxxx,
hmac-sha2-256-etm@xxxxxxxxxxx,hmac-sha2-512-etm@xxxxxxxxxxx,
hmac-ripemd160-etm@xxxxxxxxxxx,hmac-sha1-96-etm@xxxxxxxxxxx,
hmac-md5-96-etm@xxxxxxxxxxx,hmac-md5,hmac-sha1,umac-64@xxxxxxxxxxx,
umac-128@xxxxxxxxxxx,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,
hmac-ripemd160@xxxxxxxxxxx,hmac-sha1-96,hmac-md5-96
[master] ssh_list_kex: compression algo client->server: none,
zlib@xxxxxxxxxxx
[master] ssh_list_kex: compression algo server->client: none,
zlib@xxxxxxxxxxx
[master] ssh_list_kex: languages client->server:
[master] ssh_list_kex: languages server->client:
[master] ssh_knownhosts_algorithms: server slave1:22 has
ecdsa-sha2-nistp256 in known_hosts
[master] match_hashed_host: Matching a hashed host: slave1 match=0
[master] match_hashed_host: Matching a hashed host: [slave1]:22 match=0
[master] match_hashed_host: Matching a hashed host: slave1 match=0
[master] match_hashed_host: Matching a hashed host: [slave1]:22 match=0
[master] match_hashed_host: Matching a hashed host: slave1 match=0
[master] match_hashed_host: Matching a hashed host: [slave1]:22 match=0
[master] match_hashed_host: Matching a hashed host: slave1 match=0
[master] match_hashed_host: Matching a hashed host: [slave1]:22 match=0
[master] ssh_knownhosts_algorithms: server slave1:22 has ssh-rsa in
known_hosts
[master] ssh_client_select_hostkeys: Changing host key method to
"ecdsa-sha2-nistp256,ssh-rsa"
[master] ssh_list_kex: kex algos: curve25519-sha256@xxxxxxxxxx
,ecdh-sha2-nistp256,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
[master] ssh_list_kex: server host key algo: ecdsa-sha2-nistp256,ssh-rsa
[master] ssh_list_kex: encryption client->server:
aes256-ctr,aes192-ctr,aes128-ctr,aes256-cbc,aes192-cbc,aes128-cbc,blowfish-cbc,3des-cbc,des-cbc-ssh1
[master] ssh_list_kex: encryption server->client:
aes256-ctr,aes192-ctr,aes128-ctr,aes256-cbc,aes192-cbc,aes128-cbc,blowfish-cbc,3des-cbc,des-cbc-ssh1
[master] ssh_list_kex: mac algo client->server: hmac-sha1
[master] ssh_list_kex: mac algo server->client: hmac-sha1
[master] ssh_list_kex: compression algo client->server: none
[master] ssh_list_kex: compression algo server->client: none
[master] ssh_list_kex: languages client->server:
[master] ssh_list_kex: languages server->client:
[master] packet_send2: packet: wrote
[len=428,padding=10,comp=417,payload=417]
[slave1] === SshSocketHandler.cc:550 === connect_status_callback 80%
[master] packet_send2: packet: wrote [len=76,padding=5,comp=70,payload=70]
[master] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[master] ssh_connect: ssh_connect: Actual state : 6
[slave1] === SshSocketHandler.cc:499 === Leaving handler
(poll_interest=WRITE, state=COMPLETE_CONNECTION)
[slave1] === SshSocketHandler.cc:216 === Entering handler (events=WRITE,
state=COMPLETE_CONNECTION)
[master] ssh_connect: ssh_connect: Actual state : 6
[slave1] === SshSocketHandler.cc:499 === Leaving handler
(poll_interest=WRITE, state=COMPLETE_CONNECTION)
[slave3] === SshSocketHandler.cc:216 === Entering handler
(events=READ|WRITE, state=COMPLETE_CONNECTION)
[master] ssh_packet_socket_callback: packet: read type 20
[len=1540,padding=7,comp=1532,payload=1532]
[master] ssh_packet_process: Dispatching handler for packet type 20
[slave3] === SshSocketHandler.cc:550 === connect_status_callback 60%
[master] ssh_list_kex: kex algos:
ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
[master] ssh_list_kex: server host key algo:
ssh-rsa,ssh-dss,ecdsa-sha2-nistp256
[master] ssh_list_kex: encryption client->server:
aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,
aes128-gcm@xxxxxxxxxxx,aes256-gcm@xxxxxxxxxxx
,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,
rijndael-cbc@xxxxxxxxxxxxxx
[master] ssh_list_kex: encryption server->client:
aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,
aes128-gcm@xxxxxxxxxxx,aes256-gcm@xxxxxxxxxxx
,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,
rijndael-cbc@xxxxxxxxxxxxxx
[master] ssh_list_kex: mac algo client->server: hmac-md5-etm@xxxxxxxxxxx,
hmac-sha1-etm@xxxxxxxxxxx,umac-64-etm@xxxxxxxxxxx,umac-128-etm@xxxxxxxxxxx,
hmac-sha2-256-etm@xxxxxxxxxxx,hmac-sha2-512-etm@xxxxxxxxxxx,
hmac-ripemd160-etm@xxxxxxxxxxx,hmac-sha1-96-etm@xxxxxxxxxxx,
hmac-md5-96-etm@xxxxxxxxxxx,hmac-md5,hmac-sha1,umac-64@xxxxxxxxxxx,
umac-128@xxxxxxxxxxx,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,
hmac-ripemd160@xxxxxxxxxxx,hmac-sha1-96,hmac-md5-96
[master] ssh_list_kex: mac algo server->client: hmac-md5-etm@xxxxxxxxxxx,
hmac-sha1-etm@xxxxxxxxxxx,umac-64-etm@xxxxxxxxxxx,umac-128-etm@xxxxxxxxxxx,
hmac-sha2-256-etm@xxxxxxxxxxx,hmac-sha2-512-etm@xxxxxxxxxxx,
hmac-ripemd160-etm@xxxxxxxxxxx,hmac-sha1-96-etm@xxxxxxxxxxx,
hmac-md5-96-etm@xxxxxxxxxxx,hmac-md5,hmac-sha1,umac-64@xxxxxxxxxxx,
umac-128@xxxxxxxxxxx,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,
hmac-ripemd160@xxxxxxxxxxx,hmac-sha1-96,hmac-md5-96
[master] ssh_list_kex: compression algo client->server: none,
zlib@xxxxxxxxxxx
[master] ssh_list_kex: compression algo server->client: none,
zlib@xxxxxxxxxxx
[master] ssh_list_kex: languages client->server:
[master] ssh_list_kex: languages server->client:
[master] ssh_knownhosts_algorithms: server slave3:22 has
ecdsa-sha2-nistp256 in known_hosts
[master] match_hashed_host: Matching a hashed host: slave3 match=0
[master] match_hashed_host: Matching a hashed host: [slave3]:22 match=0
[master] match_hashed_host: Matching a hashed host: slave3 match=0
[master] match_hashed_host: Matching a hashed host: [slave3]:22 match=0
[master] match_hashed_host: Matching a hashed host: slave3 match=0
[master] match_hashed_host: Matching a hashed host: [slave3]:22 match=0
[master] match_hashed_host: Matching a hashed host: slave3 match=0
[master] match_hashed_host: Matching a hashed host: [slave3]:22 match=0
[master] ssh_knownhosts_algorithms: server slave3:22 has ssh-rsa in
known_hosts
[master] ssh_client_select_hostkeys: Changing host key method to
"ecdsa-sha2-nistp256,ssh-rsa"
[master] ssh_list_kex: kex algos: curve25519-sha256@xxxxxxxxxx
,ecdh-sha2-nistp256,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
[master] ssh_list_kex: server host key algo: ecdsa-sha2-nistp256,ssh-rsa
[master] ssh_list_kex: encryption client->server:
aes256-ctr,aes192-ctr,aes128-ctr,aes256-cbc,aes192-cbc,aes128-cbc,blowfish-cbc,3des-cbc,des-cbc-ssh1
[master] ssh_list_kex: encryption server->client:
aes256-ctr,aes192-ctr,aes128-ctr,aes256-cbc,aes192-cbc,aes128-cbc,blowfish-cbc,3des-cbc,des-cbc-ssh1
[master] ssh_list_kex: mac algo client->server: hmac-sha1
[master] ssh_list_kex: mac algo server->client: hmac-sha1
[master] ssh_list_kex: compression algo client->server: none
[master] ssh_list_kex: compression algo server->client: none
[master] ssh_list_kex: languages client->server:
[master] ssh_list_kex: languages server->client:
[master] packet_send2: packet: wrote
[len=428,padding=10,comp=417,payload=417]
[slave3] === SshSocketHandler.cc:550 === connect_status_callback 80%
[master] packet_send2: packet: wrote [len=76,padding=5,comp=70,payload=70]
[master] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[master] ssh_connect: ssh_connect: Actual state : 6
[slave3] === SshSocketHandler.cc:499 === Leaving handler
(poll_interest=WRITE, state=COMPLETE_CONNECTION)
[slave1] === SshSocketHandler.cc:216 === Entering handler
(events=READ|WRITE, state=COMPLETE_CONNECTION)
[master] ssh_packet_socket_callback: packet: read type 31
[len=292,padding=9,comp=282,payload=282]
[master] ssh_packet_process: Dispatching handler for packet type 31
[master] ssh_packet_dh_reply: Received SSH_KEXDH_REPLY
[master] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[master] packet_send2: packet: wrote [len=12,padding=10,comp=1,payload=1]
[master] ssh_client_ecdh_reply: SSH_MSG_NEWKEYS sent
[master] ssh_packet_socket_callback: Processing 16 bytes left in socket
buffer
[master] ssh_packet_socket_callback: packet: read type 21
[len=12,padding=10,comp=1,payload=1]
[master] ssh_packet_process: Dispatching handler for packet type 21
[master] ssh_packet_newkeys: Received SSH_MSG_NEWKEYS
[master] crypt_set_algorithms2: Set output algorithm to aes256-ctr
[master] crypt_set_algorithms2: Set input algorithm to aes256-ctr
[master] ssh_pki_signature_verify_blob: Going to verify a
ecdsa-sha2-nistp256 type signature
[master] ssh_packet_newkeys: Signature verified and valid
[slave1] === SshSocketHandler.cc:550 === connect_status_callback 100%
[master] ssh_connect: ssh_connect: Actual state : 7
[master] ssh_userauth_publickey_auto: Trying to authenticate with
/root/.ssh/id_ecdsa
[master] ssh_userauth_publickey_auto: Private key /root/.ssh/id_ecdsa
doesn't exist.
[master] ssh_userauth_publickey_auto: Trying to authenticate with
/root/.ssh/id_rsa
[master] packet_send2: packet: wrote [len=28,padding=10,comp=17,payload=17]
[master] ssh_service_request: Sent SSH_MSG_SERVICE_REQUEST (service
ssh-userauth)
[master] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[master] ssh_userauth_request_service: Failed to request "ssh-userauth"
service
[slave1] === SshSocketHandler.cc:499 === Leaving handler
(poll_interest=READ, state=AUTHENTICATE)
[slave3] === SshSocketHandler.cc:216 === Entering handler
(events=READ|WRITE, state=COMPLETE_CONNECTION)
[master] ssh_packet_socket_callback: packet: read type 31
[len=292,padding=10,comp=281,payload=281]
[master] ssh_packet_process: Dispatching handler for packet type 31
[master] ssh_packet_dh_reply: Received SSH_KEXDH_REPLY
[master] packet_send2: packet: wrote [len=12,padding=10,comp=1,payload=1]
[master] ssh_client_ecdh_reply: SSH_MSG_NEWKEYS sent
[master] ssh_packet_socket_callback: Processing 16 bytes left in socket
buffer
[master] ssh_packet_socket_callback: packet: read type 21
[len=12,padding=10,comp=1,payload=1]
[master] ssh_packet_process: Dispatching handler for packet type 21
[master] ssh_packet_newkeys: Received SSH_MSG_NEWKEYS
[master] crypt_set_algorithms2: Set output algorithm to aes256-ctr
[master] crypt_set_algorithms2: Set input algorithm to aes256-ctr
[master] ssh_pki_signature_verify_blob: Going to verify a
ecdsa-sha2-nistp256 type signature
[master] ssh_packet_newkeys: Signature verified and valid
[slave3] === SshSocketHandler.cc:550 === connect_status_callback 100%
[master] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[master] ssh_connect: ssh_connect: Actual state : 7
[master] ssh_userauth_publickey_auto: Trying to authenticate with
/root/.ssh/id_ecdsa
[master] ssh_userauth_publickey_auto: Private key /root/.ssh/id_ecdsa
doesn't exist.
[master] ssh_userauth_publickey_auto: Trying to authenticate with
/root/.ssh/id_rsa
[master] packet_send2: packet: wrote [len=28,padding=10,comp=17,payload=17]
[master] ssh_service_request: Sent SSH_MSG_SERVICE_REQUEST (service
ssh-userauth)
[master] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[master] ssh_userauth_request_service: Failed to request "ssh-userauth"
service
[slave3] === SshSocketHandler.cc:499 === Leaving handler
(poll_interest=READ, state=AUTHENTICATE)
[master] === SshSocketHandler.cc:216 === Entering handler
(events=READ|WRITE, state=COMPLETE_CONNECTION)
[master] callback_receive_banner: Received banner: SSH-2.0-OpenSSH_6.2
[master] === SshSocketHandler.cc:550 === connect_status_callback 40%
[master] ssh_client_connection_callback: SSH server banner:
SSH-2.0-OpenSSH_6.2
[master] ssh_analyze_banner: Analyzing banner: SSH-2.0-OpenSSH_6.2
[master] ssh_analyze_banner: We are talking to an OpenSSH client version:
6.2 (60200)
[master] === SshSocketHandler.cc:550 === connect_status_callback 50%
[master] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[master] ssh_connect: ssh_connect: Actual state : 4
[master] === SshSocketHandler.cc:499 === Leaving handler
(poll_interest=WRITE, state=COMPLETE_CONNECTION)
[master] === SshSocketHandler.cc:216 === Entering handler
(events=READ|WRITE, state=COMPLETE_CONNECTION)
[master] ssh_packet_socket_callback: packet: read type 20
[len=1540,padding=7,comp=1532,payload=1532]
[master] ssh_packet_process: Dispatching handler for packet type 20
[master] === SshSocketHandler.cc:550 === connect_status_callback 60%
[master] ssh_list_kex: kex algos:
ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
[master] ssh_list_kex: server host key algo:
ssh-rsa,ssh-dss,ecdsa-sha2-nistp256
[master] ssh_list_kex: encryption client->server:
aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,
aes128-gcm@xxxxxxxxxxx,aes256-gcm@xxxxxxxxxxx
,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,
rijndael-cbc@xxxxxxxxxxxxxx
[master] ssh_list_kex: encryption server->client:
aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,
aes128-gcm@xxxxxxxxxxx,aes256-gcm@xxxxxxxxxxx
,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,
rijndael-cbc@xxxxxxxxxxxxxx
[master] ssh_list_kex: mac algo client->server: hmac-md5-etm@xxxxxxxxxxx,
hmac-sha1-etm@xxxxxxxxxxx,umac-64-etm@xxxxxxxxxxx,umac-128-etm@xxxxxxxxxxx,
hmac-sha2-256-etm@xxxxxxxxxxx,hmac-sha2-512-etm@xxxxxxxxxxx,
hmac-ripemd160-etm@xxxxxxxxxxx,hmac-sha1-96-etm@xxxxxxxxxxx,
hmac-md5-96-etm@xxxxxxxxxxx,hmac-md5,hmac-sha1,umac-64@xxxxxxxxxxx,
umac-128@xxxxxxxxxxx,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,
hmac-ripemd160@xxxxxxxxxxx,hmac-sha1-96,hmac-md5-96
[master] ssh_list_kex: mac algo server->client: hmac-md5-etm@xxxxxxxxxxx,
hmac-sha1-etm@xxxxxxxxxxx,umac-64-etm@xxxxxxxxxxx,umac-128-etm@xxxxxxxxxxx,
hmac-sha2-256-etm@xxxxxxxxxxx,hmac-sha2-512-etm@xxxxxxxxxxx,
hmac-ripemd160-etm@xxxxxxxxxxx,hmac-sha1-96-etm@xxxxxxxxxxx,
hmac-md5-96-etm@xxxxxxxxxxx,hmac-md5,hmac-sha1,umac-64@xxxxxxxxxxx,
umac-128@xxxxxxxxxxx,hmac-sha2-256,hmac-sha2-512,hmac-ripemd160,
hmac-ripemd160@xxxxxxxxxxx,hmac-sha1-96,hmac-md5-96
[master] ssh_list_kex: compression algo client->server: none,
zlib@xxxxxxxxxxx
[master] ssh_list_kex: compression algo server->client: none,
zlib@xxxxxxxxxxx
[master] ssh_list_kex: languages client->server:
[master] ssh_list_kex: languages server->client:
[master] ssh_knownhosts_algorithms: server master:22 has
ecdsa-sha2-nistp256 in known_hosts
[master] match_hashed_host: Matching a hashed host: master match=0
[master] match_hashed_host: Matching a hashed host: [master]:22 match=0
[master] match_hashed_host: Matching a hashed host: master match=0
[master] match_hashed_host: Matching a hashed host: [master]:22 match=0
[master] match_hashed_host: Matching a hashed host: master match=0
[master] match_hashed_host: Matching a hashed host: [master]:22 match=0
[master] match_hashed_host: Matching a hashed host: master match=0
[master] match_hashed_host: Matching a hashed host: [master]:22 match=0
[master] ssh_knownhosts_algorithms: server master:22 has ssh-rsa in
known_hosts
[master] ssh_client_select_hostkeys: Changing host key method to
"ecdsa-sha2-nistp256,ssh-rsa"
[master] ssh_list_kex: kex algos: curve25519-sha256@xxxxxxxxxx
,ecdh-sha2-nistp256,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
[master] ssh_list_kex: server host key algo: ecdsa-sha2-nistp256,ssh-rsa
[master] ssh_list_kex: encryption client->server:
aes256-ctr,aes192-ctr,aes128-ctr,aes256-cbc,aes192-cbc,aes128-cbc,blowfish-cbc,3des-cbc,des-cbc-ssh1
[master] ssh_list_kex: encryption server->client:
aes256-ctr,aes192-ctr,aes128-ctr,aes256-cbc,aes192-cbc,aes128-cbc,blowfish-cbc,3des-cbc,des-cbc-ssh1
[master] ssh_list_kex: mac algo client->server: hmac-sha1
[master] ssh_list_kex: mac algo server->client: hmac-sha1
[master] ssh_list_kex: compression algo client->server: none
[master] ssh_list_kex: compression algo server->client: none
[master] ssh_list_kex: languages client->server:
[master] ssh_list_kex: languages server->client:
[master] packet_send2: packet: wrote
[len=428,padding=10,comp=417,payload=417]
[master] === SshSocketHandler.cc:550 === connect_status_callback 80%
[master] packet_send2: packet: wrote [len=76,padding=5,comp=70,payload=70]
[master] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[master] ssh_connect: ssh_connect: Actual state : 6
[master] === SshSocketHandler.cc:499 === Leaving handler
(poll_interest=WRITE, state=COMPLETE_CONNECTION)
[master] === SshSocketHandler.cc:216 === Entering handler
(events=READ|WRITE, state=COMPLETE_CONNECTION)
[master] ssh_packet_socket_callback: packet: read type 31
[len=292,padding=10,comp=281,payload=281]
[master] ssh_packet_process: Dispatching handler for packet type 31
[master] ssh_packet_dh_reply: Received SSH_KEXDH_REPLY
[master] packet_send2: packet: wrote [len=12,padding=10,comp=1,payload=1]
[master] ssh_client_ecdh_reply: SSH_MSG_NEWKEYS sent
[master] ssh_packet_socket_callback: Processing 16 bytes left in socket
buffer
[master] ssh_packet_socket_callback: packet: read type 21
[len=12,padding=10,comp=1,payload=1]
[master] ssh_packet_process: Dispatching handler for packet type 21
[master] ssh_packet_newkeys: Received SSH_MSG_NEWKEYS
[master] crypt_set_algorithms2: Set output algorithm to aes256-ctr
[master] crypt_set_algorithms2: Set input algorithm to aes256-ctr
[master] ssh_pki_signature_verify_blob: Going to verify a
ecdsa-sha2-nistp256 type signature
[master] ssh_packet_newkeys: Signature verified and valid
[master] === SshSocketHandler.cc:550 === connect_status_callback 100%
[master] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[master] ssh_connect: ssh_connect: Actual state : 7
[master] ssh_userauth_publickey_auto: Trying to authenticate with
/root/.ssh/id_ecdsa
[master] ssh_userauth_publickey_auto: Private key /root/.ssh/id_ecdsa
doesn't exist.
[master] ssh_userauth_publickey_auto: Trying to authenticate with
/root/.ssh/id_rsa
[master] packet_send2: packet: wrote [len=28,padding=10,comp=17,payload=17]
[master] ssh_service_request: Sent SSH_MSG_SERVICE_REQUEST (service
ssh-userauth)
[master] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[master] ssh_userauth_request_service: Failed to request "ssh-userauth"
service
[master] === SshSocketHandler.cc:499 === Leaving handler
(poll_interest=READ, state=AUTHENTICATE)
[slave1] === SshSocketHandler.cc:216 === Entering handler
(events=READ|WRITE, state=AUTHENTICATE)
[master] ssh_packet_socket_callback: packet: read type 6
[len=28,padding=10,comp=17,payload=17]
[master] ssh_packet_process: Dispatching handler for packet type 6
[master] ssh_packet_service_accept: Received SSH_MSG_SERVICE_ACCEPT
[master] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[master] packet_send2: packet: wrote
[len=348,padding=14,comp=333,payload=333]
[slave1] === SshSocketHandler.cc:499 === Leaving handler
(poll_interest=READ, state=AUTHENTICATE)
[slave3] === SshSocketHandler.cc:216 === Entering handler
(events=READ|WRITE, state=AUTHENTICATE)
[master] ssh_packet_socket_callback: packet: read type 6
[len=28,padding=10,comp=17,payload=17]
[master] ssh_packet_process: Dispatching handler for packet type 6
[master] ssh_packet_service_accept: Received SSH_MSG_SERVICE_ACCEPT
[master] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[master] packet_send2: packet: wrote
[len=348,padding=14,comp=333,payload=333]
[slave3] === SshSocketHandler.cc:499 === Leaving handler
(poll_interest=READ, state=AUTHENTICATE)
[slave1] === SshSocketHandler.cc:216 === Entering handler
(events=READ|WRITE, state=AUTHENTICATE)
[master] ssh_packet_socket_callback: packet: read type 60
[len=300,padding=6,comp=293,payload=293]
[master] ssh_packet_process: Dispatching handler for packet type 60
[master] ssh_packet_userauth_pk_ok: Received
SSH_USERAUTH_PK_OK/INFO_REQUEST/GSSAPI_RESPONSE
[master] ssh_packet_userauth_pk_ok: Assuming SSH_USERAUTH_PK_OK
[master] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[master] packet_send2: packet: wrote
[len=620,padding=11,comp=608,payload=608]
[slave1] === SshSocketHandler.cc:499 === Leaving handler
(poll_interest=READ, state=AUTHENTICATE)
[slave3] === SshSocketHandler.cc:216 === Entering handler
(events=READ|WRITE, state=AUTHENTICATE)
[master] ssh_packet_socket_callback: packet: read type 60
[len=300,padding=6,comp=293,payload=293]
[master] ssh_packet_process: Dispatching handler for packet type 60
[master] ssh_packet_userauth_pk_ok: Received
SSH_USERAUTH_PK_OK/INFO_REQUEST/GSSAPI_RESPONSE
[master] ssh_packet_userauth_pk_ok: Assuming SSH_USERAUTH_PK_OK
[master] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[master] packet_send2: packet: wrote
[len=620,padding=11,comp=608,payload=608]
[slave3] === SshSocketHandler.cc:499 === Leaving handler
(poll_interest=READ, state=AUTHENTICATE)
[slave1] === SshSocketHandler.cc:216 === Entering handler
(events=READ|WRITE, state=AUTHENTICATE)
[master] ssh_packet_socket_callback: packet: read type 52
[len=12,padding=10,comp=1,payload=1]
[master] ssh_packet_process: Dispatching handler for packet type 52
[master] ssh_packet_userauth_success: Authentication successful
[master] ssh_packet_userauth_success: Received SSH_USERAUTH_SUCCESS
[master] ssh_userauth_publickey_auto: Successfully authenticated using
/root/.ssh/id_rsa
[slave1] === SshSocketHandler.cc:499 === Leaving handler
(poll_interest=READ, state=CONNECTED)
[slave3] === SshSocketHandler.cc:216 === Entering handler
(events=READ|WRITE, state=AUTHENTICATE)
[master] ssh_packet_socket_callback: packet: read type 52
[len=12,padding=10,comp=1,payload=1]
[master] ssh_packet_process: Dispatching handler for packet type 52
[master] ssh_packet_userauth_success: Authentication successful
[master] ssh_packet_userauth_success: Received SSH_USERAUTH_SUCCESS
[master] ssh_userauth_publickey_auto: Successfully authenticated using
/root/.ssh/id_rsa
[slave3] === SshSocketHandler.cc:499 === Leaving handler
(poll_interest=READ, state=CONNECTED)
[master] === SshSocketHandler.cc:216 === Entering handler
(events=READ|WRITE, state=AUTHENTICATE)
[master] ssh_packet_socket_callback: packet: read type 6
[len=28,padding=10,comp=17,payload=17]
[master] ssh_packet_process: Dispatching handler for packet type 6
[master] ssh_packet_service_accept: Received SSH_MSG_SERVICE_ACCEPT
[master] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[master] packet_send2: packet: wrote
[len=348,padding=14,comp=333,payload=333]
[master] ssh_packet_socket_callback: packet: read type 60
[len=300,padding=6,comp=293,payload=293]
[master] ssh_packet_process: Dispatching handler for packet type 60
[master] ssh_packet_userauth_pk_ok: Received
SSH_USERAUTH_PK_OK/INFO_REQUEST/GSSAPI_RESPONSE
[master] ssh_packet_userauth_pk_ok: Assuming SSH_USERAUTH_PK_OK
[master] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[master] packet_send2: packet: wrote
[len=620,padding=11,comp=608,payload=608]
[master] ssh_packet_socket_callback: packet: read type 52
[len=12,padding=10,comp=1,payload=1]
[master] ssh_packet_process: Dispatching handler for packet type 52
[master] ssh_packet_userauth_success: Authentication successful
[master] ssh_packet_userauth_success: Received SSH_USERAUTH_SUCCESS
[master] ssh_userauth_publickey_auto: Successfully authenticated using
/root/.ssh/id_rsa
[master] === SshSocketHandler.cc:499 === Leaving handler
(poll_interest=READ, state=CONNECTED)
[master] === SshSocketHandler.cc:216 === Entering handler (events=WRITE,
state=CONNECTED)
[master] === SshSocketHandler.cc:499 === Leaving handler
(poll_interest=READ, state=CONNECTED)
[slave2] ERROR timeout


On Mon, Mar 2, 2015 at 10:51 PM, Doug Judd <doug@xxxxxxxxxxxxxx> wrote:

> I've developed an application that establishes ssh connections and issues
> commands asynchronously with libssh (0.6.3).  My application uses
> edge-triggered epoll on Linux to respond to network events.  Periodically,
> my application will hang while trying to establish ssh connections.
> Intermittently, calls to ssh_connect() will return SSH_AGAIN and the
> progress reported will be 20% (0.2f), however no events on the
> corresponding socket occur after that.  I've tried setting the polling
> interest to WRITE as well as READ+WRITE, but to no avail.  Setting the
> session to non-blocking mode resolves the problem.
>
> - Doug
>



-- 
Doug Judd
CEO, Hypertable Inc.