Re: Hang in nonblocking ssh_connect

[Doug Judd <doug@xxxxxxxxxxxxxx>]

The attached patch resolves the problem.  It modifies
ssh_handle_packets_termination() to keep calling ssh_handle_packets(), when
in non-blocking mode, until it returns SSH_AGAIN.

On Tue, Mar 3, 2015 at 7:43 PM, Doug Judd <doug@xxxxxxxxxxxxxx> wrote:

> 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.
>



-- 
Doug Judd
CEO, Hypertable Inc.

Attachment: libssh-poll-fix.patch
Description: Binary data