Infinite loop while opening SFTP channel to misconfigured server
Hello,
a client reported an SFTP upload with libssh hanging for hours. Doing the same upload with the OpenSSH client resulted in the error message "The user does not have any roots specified; the Channel is being Closed" during opening a channel for SFTP after successfully authenticating, which points to some kind of misconfiguration on the server side.
The server banner is "SSH-2.0-VShell_4_2_5_1322 VShell", apparently an SSH server product from VanDyke.
Using libssh, after successful authentication, sftp_new() followed by sftp_init() is called. One of both functions does not return (I'm not exactly sure which one). The client sent us the libssh debug log you can find below which I trimmed to the relevant part after authentication. The last line repeats indefinitely.
I am unable to debug this because I have access to neither the client nor server part. However, I have an uneducated guess of what might happen here:
A channel is opened and the SFTP subsystem is being established. The server returns an error message because of some misconfiguration on the server side and closes the channel. After the channel is closed, we get stuck in the first while loop in sftp_packet_read() which attempts to read 4 bytes until it gets them or EOF is encountered. Since the channel is closed, we won't get any more data. Therefore, ssh_channel_is_eof() is called which returns false because either channel->stdout_buffer or channel->stderr_buffer still contains data. My guess is that channel->stderr_buffer contains the error message that the server sent. The loop in sftp_packet_read() only attempts to read from the stdout stream, not from stderr, and therefore never terminates.
PACKET (ssh_packet_userauth_success) ssh_packet_userauth_success: Authentication successful
FUNCTION (ssh_packet_userauth_success) ssh_packet_userauth_success: Received SSH_USERAUTH_SUCCESS
PROTOCOL (channel_open) channel_open: Creating a channel 43 with 64000 window and 32768 max packet
PACKET (ssh_socket_unbuffered_write) ssh_socket_unbuffered_write: Enabling POLLOUT for socket
PACKET (packet_send2) packet_send2: packet: wrote [type=90, len=44, padding_size=19, comp=24, payload=24]
PACKET (channel_open) channel_open: Sent a SSH_MSG_CHANNEL_OPEN type session for channel 43
FUNCTION (ssh_socket_pollcallback) ssh_socket_pollcallback: Poll callback on socket 0 (POLLOUT ), out buffer 0
FUNCTION (ssh_socket_pollcallback) ssh_socket_pollcallback: sending control flow event
FUNCTION (ssh_packet_socket_controlflow_callback) ssh_packet_socket_controlflow_callback: sending channel_write_wontblock callback
FUNCTION (ssh_socket_pollcallback) ssh_socket_pollcallback: Poll callback on socket 0 (POLLIN ), out buffer 0
PACKET (ssh_packet_socket_callback) ssh_packet_socket_callback: packet: read type 91 [len=28,padding=10,comp=17,payload=17]
PACKET (ssh_packet_process) ssh_packet_process: Dispatching handler for packet type 91
PACKET (ssh_packet_channel_open_conf) ssh_packet_channel_open_conf: Received SSH2_MSG_CHANNEL_OPEN_CONFIRMATION
PROTOCOL (ssh_packet_channel_open_conf) ssh_packet_channel_open_conf: Received a CHANNEL_OPEN_CONFIRMATION for channel 43:0
PROTOCOL (ssh_packet_channel_open_conf) ssh_packet_channel_open_conf: Remote window : 0, maxpacket : 32768
PACKET (ssh_socket_unbuffered_write) ssh_socket_unbuffered_write: Enabling POLLOUT for socket
PACKET (packet_send2) packet_send2: packet: wrote [type=98, len=44, padding_size=16, comp=27, payload=27]
PACKET (channel_request) channel_request: Sent a SSH_MSG_CHANNEL_REQUEST subsystem
FUNCTION (ssh_socket_pollcallback) ssh_socket_pollcallback: Poll callback on socket 0 (POLLOUT ), out buffer 0
FUNCTION (ssh_socket_pollcallback) ssh_socket_pollcallback: sending control flow event
FUNCTION (ssh_packet_socket_controlflow_callback) ssh_packet_socket_controlflow_callback: sending channel_write_wontblock callback
FUNCTION (ssh_socket_pollcallback) ssh_socket_pollcallback: Poll callback on socket 0 (POLLIN ), out buffer 0
PACKET (ssh_packet_socket_callback) ssh_packet_socket_callback: packet: read type 93 [len=28,padding=18,comp=9,payload=9]
PACKET (ssh_packet_process) ssh_packet_process: Dispatching handler for packet type 93
PROTOCOL (channel_rcv_change_window) channel_rcv_change_window: Adding 131072 bytes to channel (43:0) (from 0 bytes)
FUNCTION (ssh_socket_pollcallback) ssh_socket_pollcallback: Poll callback on socket 0 (POLLIN ), out buffer 0
PACKET (ssh_packet_socket_callback) ssh_packet_socket_callback: packet: read type 99 [len=12,padding=6,comp=5,payload=5]
PACKET (ssh_packet_process) ssh_packet_process: Dispatching handler for packet type 99
PACKET (ssh_packet_channel_success) ssh_packet_channel_success: Received SSH_CHANNEL_SUCCESS on channel (43:0)
PROTOCOL (channel_request) channel_request: Channel request subsystem success
PACKET (ssh_socket_unbuffered_write) ssh_socket_unbuffered_write: Enabling POLLOUT for socket
PACKET (packet_send2) packet_send2: packet: wrote [type=94, len=28, padding_size=9, comp=18, payload=18]
PACKET (channel_write_common) channel_write_common: channel_write wrote 9 bytes
PACKET (ssh_channel_read_timeout) ssh_channel_read_timeout: Read (4) buffered : 0 bytes. Window: 64000
FUNCTION (ssh_socket_pollcallback) ssh_socket_pollcallback: Poll callback on socket 0 (POLLOUT ), out buffer 0
FUNCTION (ssh_socket_pollcallback) ssh_socket_pollcallback: sending control flow event
FUNCTION (ssh_packet_socket_controlflow_callback) ssh_packet_socket_controlflow_callback: sending channel_write_wontblock callback
FUNCTION (ssh_socket_pollcallback) ssh_socket_pollcallback: Poll callback on socket 0 (POLLIN ), out buffer 0
PACKET (ssh_packet_socket_callback) ssh_packet_socket_callback: packet: read type 95 [len=124,padding=14,comp=109,payload=109]
PACKET (ssh_packet_process) ssh_packet_process: Dispatching handler for packet type 95
PACKET (channel_rcv_data) channel_rcv_data: Channel receiving 96 bytes data in 1 (local win=64000 remote win=131063)
PACKET (channel_default_bufferize) channel_default_bufferize: placing 96 bytes into channel buffer (stderr=1)
PACKET (channel_rcv_data) channel_rcv_data: Channel windows are now (local win=63904 remote win=131063)
PACKET (ssh_socket_unbuffered_write) ssh_socket_unbuffered_write: Enabling POLLOUT for socket
PACKET (packet_send2) packet_send2: packet: wrote [type=93, len=28, padding_size=18, comp=9, payload=9]
PROTOCOL (grow_window) grow_window: growing window (channel 43:0) to 1280000 bytes
PACKET (ssh_packet_socket_callback) ssh_packet_socket_callback: Processing 48 bytes left in socket buffer
PACKET (ssh_packet_socket_callback) ssh_packet_socket_callback: packet: read type 97 [len=12,padding=6,comp=5,payload=5]
PACKET (ssh_packet_process) ssh_packet_process: Dispatching handler for packet type 97
PACKET (channel_rcv_close) channel_rcv_close: Received close on channel (43:0)
PACKET (channel_rcv_close) channel_rcv_close: Remote host not polite enough to send an eof before close
PACKET (ssh_channel_read_timeout) ssh_channel_read_timeout: Read (4) buffered : 0 bytes. Window: 1280000
PACKET (ssh_channel_read_timeout) ssh_channel_read_timeout: Read (4) buffered : 0 bytes. Window: 1280000
PACKET (ssh_channel_read_timeout) ssh_channel_read_timeout: Read (4) buffered : 0 bytes. Window: 1280000