libssh2_sftp_init hangs when connecting to OpenWRT with Dropbear SSH server

[allanrbo]

libssh2_sftp_init hangs when connecting to OpenWRT with Dropbear SSH server.

Seems to be a libssh2 issue, because the same happens with the examples included with libsssh, such as this one: https://github.com/libssh2/libssh2/blob/libssh2-1.10.0/example/sftp.c .

I tried compiling libssh2 with cmake ... -DENABLE_DEBUG_LOGGING=ON , and adding this to sftp.c:

libssh2_trace(session, LIBSSH2_TRACE_KEX | LIBSSH2_TRACE_AUTH | LIBSSH2_TRACE_CONN | LIBSSH2_TRACE_SCP | LIBSSH2_TRACE_SFTP | LIBSSH2_TRACE_ERROR | LIBSSH2_TRACE_PUBLICKEY);

It resulted in the following trace when connecting to an OpenWRT server with Dropbear:

[libssh2] 0.158452 Conn: Setting blocking mode ON
[libssh2] 0.171709 Key Ex: Sent KEX: curve25519-sha256,[email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1,diffie-hellman-group-exchange-sha1
[libssh2] 0.171755 Key Ex: Sent HOSTKEY: ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,[email protected],[email protected],[email protected],ssh-ed25519,ssh-rsa,ssh-dss
[libssh2] 0.171767 Key Ex: Sent CRYPT_CS: aes128-ctr,aes192-ctr,aes256-ctr,aes256-cbc,[email protected],aes192-cbc,aes128-cbc,blowfish-cbc,arcfour128,arcfour,cast128-cbc,3des-cbc
[libssh2] 0.171776 Key Ex: Sent CRYPT_SC: aes128-ctr,aes192-ctr,aes256-ctr,aes256-cbc,[email protected],aes192-cbc,aes128-cbc,blowfish-cbc,arcfour128,arcfour,cast128-cbc,3des-cbc
[libssh2] 0.171785 Key Ex: Sent MAC_CS: hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-sha1-96,hmac-md5,hmac-md5-96,hmac-ripemd160,[email protected]
[libssh2] 0.171794 Key Ex: Sent MAC_SC: hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-sha1-96,hmac-md5,hmac-md5-96,hmac-ripemd160,[email protected]
[libssh2] 0.171802 Key Ex: Sent COMP_CS: none
[libssh2] 0.171811 Key Ex: Sent COMP_SC: none
[libssh2] 0.171820 Key Ex: Sent LANG_CS: 
[libssh2] 0.171828 Key Ex: Sent LANG_SC: 
[libssh2] 0.171902 Key Ex: Agreed on KEX method: curve25519-sha256
[libssh2] 0.171916 Key Ex: Agreed on HOSTKEY method: ssh-ed25519
[libssh2] 0.171925 Key Ex: Agreed on CRYPT_CS method: aes128-ctr
[libssh2] 0.171933 Key Ex: Agreed on CRYPT_SC method: aes128-ctr
[libssh2] 0.171942 Key Ex: Agreed on MAC_CS method: hmac-sha2-256
[libssh2] 0.171951 Key Ex: Agreed on MAC_SC method: hmac-sha2-256
[libssh2] 0.171959 Key Ex: Agreed on COMP_CS method: none
[libssh2] 0.171968 Key Ex: Agreed on COMP_SC method: none
[libssh2] 0.172468 Key Ex: Initiating curve25519 SHA2
[libssh2] 0.450752 Key Ex: Server's MD5 Fingerprint: ea:8d:76:7b:2b:0d:5f:c7:60:0f:92:5c:01:e5:7a:40
[libssh2] 0.450836 Key Ex: Server's SHA1 Fingerprint: ed:db:ad:f2:bc:e7:3d:8d:eb:47:0c:d3:6a:8c:71:25:07:1c:61:17
[libssh2] 0.450887 Key Ex: Server's SHA256 Fingerprint: TZbN1TCE4+9l3PwTFJgUF5F0+kVfsdCSlJdwBQkk8xQ=
[libssh2] 0.452479 Key Ex: Received NEWKEYS message
[libssh2] 0.452597 Key Ex: session_id calculated
[libssh2] 0.452647 Key Ex: Client to Server IV and Key calculated
[libssh2] 0.452679 Key Ex: Server to Client IV and Key calculated
[libssh2] 0.452707 Key Ex: Client to Server HMAC Key calculated
[libssh2] 0.452727 Key Ex: Server to Client HMAC Key calculated
[libssh2] 0.452740 Key Ex: Client to Server compression initialized
[libssh2] 0.452752 Key Ex: Server to Client compression initialized
Fingerprint: ED DB AD F2 BC E7 3D 8D EB 47 0C D3 6A 8C 71 25 07 1C 61 17 
[libssh2] 0.456500 Failure Event: -37 - Would block requesting userauth list
[libssh2] 0.459249 Userauth: Permitted auth methods: publickey,password
Authentication methods: publickey,password
[libssh2] 0.459329 Userauth: Attempting to login using password authentication
[libssh2] 0.459417 Failure Event: -37 - Waiting for password response
[libssh2] 0.470157 Userauth: Password authentication successful
libssh2_sftp_init()!
[libssh2] 0.470235 SFTP: Initializing SFTP subsystem
[libssh2] 0.470260 Conn: Allocated new channel ID#0
[libssh2] 0.470278 Conn: Opening Channel - win 2097152 pack 32768
[libssh2] 0.470383 Failure Event: -37 - Would block
[libssh2] 0.470408 Failure Event: -37 - Would block starting up channel
[libssh2] 0.487273 Conn: Connection Established - ID: 0/0 win: 24576/2097152 pack: 140428250742775/32768
[libssh2] 0.487352 Conn: starting request(subsystem) on channel 0/0, message=sftp
[libssh2] 0.487454 Failure Event: -37 - Would block to request SFTP subsystem
[libssh2] 0.489992 Conn: Setting channel 0/0 handle_extended_data mode to 1
[libssh2] 0.490046 SFTP: Sending FXP_INIT packet advertising version 3 support
[libssh2] 0.490102 Conn: Writing 9 bytes on channel 0/0, stream #0
[libssh2] 0.490121 Conn: Sending 9 bytes on channel 0/0, stream_id=0
[libssh2] 0.490205 SFTP: Requiring packet 2 id 0
[libssh2] 0.490225 SFTP: recv packet
[libssh2] 0.490237 Conn: channel_read() wants 4 bytes from channel 0/0 stream #0
[libssh2] 0.490258 Failure Event: -37 - would block
[libssh2] 0.490274 Failure Event: -37 - Would block receiving SSH_FXP_VERSION
[libssh2] 0.499553 SFTP: Requiring packet 2 id 0
[libssh2] 0.499587 SFTP: recv packet
[libssh2] 0.499601 Conn: channel_read() wants 4 bytes from channel 0/0 stream #0
[libssh2] 0.499652 Conn: 5 bytes packet_add() for 0/0/140698833649665
[libssh2] 0.499671 Conn: Ignoring extended data and refunding 5 bytes
[libssh2] 0.499685 Conn: shrinking window size by 5 bytes to 2097147, read_avail 0
[libssh2] 0.499698 Conn: Adjusting window 5 bytes for data on channel 0/0
[libssh2] 0.499776 Failure Event: -37 - would block
[libssh2] 0.499795 Failure Event: -37 - Would block receiving SSH_FXP_VERSION
[libssh2] 0.500499 SFTP: Requiring packet 2 id 0
[libssh2] 0.500534 SFTP: recv packet
[libssh2] 0.500548 Conn: channel_read() wants 4 bytes from channel 0/0 stream #0
[libssh2] 0.500611 Conn: 35 bytes packet_add() for 0/0/140698833649665
[libssh2] 0.500622 Conn: Ignoring extended data and refunding 35 bytes
[libssh2] 0.500629 Conn: shrinking window size by 35 bytes to 2097117, read_avail 0
[libssh2] 0.500636 Conn: Adjusting window 35 bytes for data on channel 0/0
[libssh2] 0.500670 Failure Event: -37 - would block
[libssh2] 0.500719 Failure Event: -37 - Would block receiving SSH_FXP_VERSION
[libssh2] 0.501063 SFTP: Requiring packet 2 id 0
[libssh2] 0.501089 SFTP: recv packet
[libssh2] 0.501098 Conn: channel_read() wants 4 bytes from channel 0/0 stream #0
[libssh2] 0.501129 Conn: 1 bytes packet_add() for 0/0/140698833649665
[libssh2] 0.501139 Conn: Ignoring extended data and refunding 1 bytes
[libssh2] 0.501145 Conn: shrinking window size by 1 bytes to 2097151, read_avail 0
[libssh2] 0.501152 Conn: Adjusting window 1 bytes for data on channel 0/0
[libssh2] 0.501187 Failure Event: -37 - would block
[libssh2] 0.501196 Failure Event: -37 - Would block receiving SSH_FXP_VERSION
[libssh2] 0.503486 SFTP: Requiring packet 2 id 0
[libssh2] 0.503512 SFTP: recv packet
[libssh2] 0.503520 Conn: channel_read() wants 4 bytes from channel 0/0 stream #0
[libssh2] 0.503551 Conn: EOF received for channel 0/0
[libssh2] 0.503563 Failure Event: -37 - Would block receiving SSH_FXP_VERSION
[libssh2] 0.505267 SFTP: Requiring packet 2 id 0
[libssh2] 0.505293 SFTP: recv packet
[libssh2] 0.505302 Conn: channel_read() wants 4 bytes from channel 0/0 stream #0
[libssh2] 0.505334 Conn: Channel 0 received request type exit-status (wr 0)
[libssh2] 0.505344 Conn: Exit status 127 received for channel 0/0
[libssh2] 0.505360 Conn: Close received for channel 0/0
[libssh2] 0.505370 Failure Event: -37 - Would block receiving SSH_FXP_VERSION

At this point it freezes apparently indefinitely, and I need to stop it with ctrl-c.

As reference, here's a trace from a successful connection to a Debian 11 server:

[libssh2] 0.106046 Conn: Setting blocking mode ON
[libssh2] 0.203746 Key Ex: Sent KEX: curve25519-sha256,[email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1,diffie-hellman-group-exchange-sha1
[libssh2] 0.203810 Key Ex: Sent HOSTKEY: ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,[email protected],[email protected],[email protected],ssh-ed25519,ssh-rsa,ssh-dss
[libssh2] 0.203958 Key Ex: Sent CRYPT_CS: aes128-ctr,aes192-ctr,aes256-ctr,aes256-cbc,[email protected],aes192-cbc,aes128-cbc,blowfish-cbc,arcfour128,arcfour,cast128-cbc,3des-cbc
[libssh2] 0.203984 Key Ex: Sent CRYPT_SC: aes128-ctr,aes192-ctr,aes256-ctr,aes256-cbc,[email protected],aes192-cbc,aes128-cbc,blowfish-cbc,arcfour128,arcfour,cast128-cbc,3des-cbc
[libssh2] 0.204000 Key Ex: Sent MAC_CS: hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-sha1-96,hmac-md5,hmac-md5-96,hmac-ripemd160,[email protected]
[libssh2] 0.204015 Key Ex: Sent MAC_SC: hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-sha1-96,hmac-md5,hmac-md5-96,hmac-ripemd160,[email protected]
[libssh2] 0.204029 Key Ex: Sent COMP_CS: none
[libssh2] 0.204042 Key Ex: Sent COMP_SC: none
[libssh2] 0.204056 Key Ex: Sent LANG_CS: 
[libssh2] 0.204069 Key Ex: Sent LANG_SC: 
[libssh2] 0.277625 Key Ex: Agreed on KEX method: curve25519-sha256
[libssh2] 0.277676 Key Ex: Agreed on HOSTKEY method: ecdsa-sha2-nistp256
[libssh2] 0.277695 Key Ex: Agreed on CRYPT_CS method: aes128-ctr
[libssh2] 0.277711 Key Ex: Agreed on CRYPT_SC method: aes128-ctr
[libssh2] 0.277726 Key Ex: Agreed on MAC_CS method: hmac-sha2-256
[libssh2] 0.277740 Key Ex: Agreed on MAC_SC method: hmac-sha2-256
[libssh2] 0.277754 Key Ex: Agreed on COMP_CS method: none
[libssh2] 0.277769 Key Ex: Agreed on COMP_SC method: none
[libssh2] 0.281806 Key Ex: Initiating curve25519 SHA2
[libssh2] 0.802537 Key Ex: Server's MD5 Fingerprint: 17:da:11:2d:9c:97:fd:4c:8e:0c:58:7a:a3:7d:8f:27
[libssh2] 0.803115 Key Ex: Server's SHA1 Fingerprint: 98:2d:9f:34:da:4f:23:4d:09:47:87:30:8a:e9:51:76:0a:f9:67:19
[libssh2] 0.803563 Key Ex: Server's SHA256 Fingerprint: zZYsRpxYPUQYd7zuXNjPGVAjcr+LnOvAhgyCsxcOlWE=
[libssh2] 0.813907 Key Ex: Received NEWKEYS message
[libssh2] 0.813985 Key Ex: session_id calculated
[libssh2] 0.814056 Key Ex: Client to Server IV and Key calculated
[libssh2] 0.814087 Key Ex: Server to Client IV and Key calculated
[libssh2] 0.814112 Key Ex: Client to Server HMAC Key calculated
[libssh2] 0.814130 Key Ex: Server to Client HMAC Key calculated
[libssh2] 0.814143 Key Ex: Client to Server compression initialized
[libssh2] 0.814155 Key Ex: Server to Client compression initialized
Fingerprint: 98 2D 9F 34 DA 4F 23 4D 09 47 87 30 8A E9 51 76 0A F9 67 19 
[libssh2] 1.155163 Failure Event: -37 - Would block requesting userauth list
[libssh2] 1.330660 Userauth: Permitted auth methods: publickey,password
Authentication methods: publickey,password
[libssh2] 1.330742 Userauth: Attempting to login using password authentication
[libssh2] 1.330844 Failure Event: -37 - Waiting for password response
[libssh2] 1.495517 Userauth: Password authentication successful
libssh2_sftp_init()!
[libssh2] 1.495590 SFTP: Initializing SFTP subsystem
[libssh2] 1.495616 Conn: Allocated new channel ID#0
[libssh2] 1.495636 Conn: Opening Channel - win 2097152 pack 32768
[libssh2] 1.495805 Failure Event: -37 - Would block
[libssh2] 1.495846 Failure Event: -37 - Would block starting up channel
[libssh2] 1.634893 Conn: Received global request type [email protected] (wr 0)
[libssh2] 1.634981 Failure Event: -37 - Would block
[libssh2] 1.635003 Failure Event: -37 - Would block starting up channel
[libssh2] 1.802321 Conn: Connection Established - ID: 0/0 win: 0/2097152 pack: 140475495383040/32768
[libssh2] 1.802382 Conn: starting request(subsystem) on channel 0/0, message=sftp
[libssh2] 1.802449 Failure Event: -37 - Would block to request SFTP subsystem
[libssh2] 1.972887 Conn: Window adjust for channel 0/0, adding 2097152 bytes, new window_size=140698835746816
[libssh2] 1.972959 Conn: Setting channel 0/0 handle_extended_data mode to 1
[libssh2] 1.972974 SFTP: Sending FXP_INIT packet advertising version 3 support
[libssh2] 1.972984 Conn: Writing 9 bytes on channel 0/0, stream #0
[libssh2] 1.972996 Conn: Sending 9 bytes on channel 0/0, stream_id=0
[libssh2] 1.973154 SFTP: Requiring packet 2 id 0
[libssh2] 1.973179 SFTP: recv packet
[libssh2] 1.973191 Conn: channel_read() wants 4 bytes from channel 0/0 stream #0
[libssh2] 1.973205 Failure Event: -37 - would block
[libssh2] 1.973216 Failure Event: -37 - Would block receiving SSH_FXP_VERSION
[libssh2] 2.105433 SFTP: Requiring packet 2 id 0
[libssh2] 2.105474 SFTP: recv packet
[libssh2] 2.105485 Conn: channel_read() wants 4 bytes from channel 0/0 stream #0
[libssh2] 2.108895 Conn: 183 bytes packet_add() for 0/0/140698833649664
[libssh2] 2.109666 Conn: increasing read_avail by 183 bytes to 183/2097152
[libssh2] 2.109693 Conn: channel_read() got 4 of data from 0/0/0
[libssh2] 2.109704 SFTP: Data begin - Packet Length: 179
[libssh2] 2.109714 Conn: channel_read() wants 179 bytes from channel 0/0 stream #0
[libssh2] 2.109726 Conn: channel_read() got 179 of data from 0/0/0 [ul]
[libssh2] 2.109737 SFTP: Received packet type 2 (len 179)
[libssh2] 2.109746 SFTP: Received packet id 3
[libssh2] 2.109755 SFTP: Got 2
[libssh2] 2.109763 SFTP: Enabling SFTP version 3 compatibility
libssh2_sftp_open()!
[libssh2] 2.109783 SFTP: Sending file open request
[libssh2] 2.109792 Conn: Writing 34 bytes on channel 0/0, stream #0
[libssh2] 2.109818 Conn: Sending 34 bytes on channel 0/0, stream_id=0
[libssh2] 2.109908 SFTP: recv packet
[libssh2] 2.109927 Conn: channel_read() wants 4 bytes from channel 0/0 stream #0
[libssh2] 2.109940 Failure Event: -37 - would block
[libssh2] 2.109992 Failure Event: -37 - Would block waiting for status message
[libssh2] 2.276913 SFTP: recv packet
[libssh2] 2.276958 Conn: channel_read() wants 4 bytes from channel 0/0 stream #0
[libssh2] 2.277017 Conn: 33 bytes packet_add() for 0/0/140698833649664
[libssh2] 2.277031 Conn: increasing read_avail by 33 bytes to 33/2096969
[libssh2] 2.277044 Conn: channel_read() got 4 of data from 0/0/0
[libssh2] 2.277054 SFTP: Data begin - Packet Length: 29
[libssh2] 2.277063 Conn: channel_read() wants 29 bytes from channel 0/0 stream #0
[libssh2] 2.277074 Conn: channel_read() got 29 of data from 0/0/0 [ul]
[libssh2] 2.277084 SFTP: Received packet type 101 (len 29)
[libssh2] 2.277093 SFTP: Received packet id 0
[libssh2] 2.277102 Failure Event: -31 - Failed opening remote file
[libssh2] 2.277111 SFTP: got FXP_STATUS 2
Unable to open file with SFTP: 2
[libssh2] 2.277195 Conn: Freeing channel 0/0 resources
[libssh2] 2.277211 Conn: Sending EOF on channel 0/0
[libssh2] 2.277247 Conn: Closing channel 0/0
all done

To do: figure out a workaround. Maybe we need a fix upstream in libssh2 or openssl.

[allanrbo]

Just realized, it's probably because Dropbear on OpenWRT doesn't come with an SFTP server by default: https://openwrt.org/docs/guide-user/services/nas/sftp.server . Solution idea: fall back to SCP?