Page MenuHomePhabricator

Calling sftp_new() on session that was not authenticated hangs
Open, Needs TriagePublic

Description

On Fedora 29 with libssh-0.8.7-1.fc29.x86_64, the following program

#include <libssh/libssh.h>
#include <libssh/sftp.h>
#include <stdio.h>

int main(void) {
        ssh_session session = ssh_new();
        ssh_options_set(session, SSH_OPTIONS_HOST, "localhost");
        int verbosity = SSH_LOG_FUNCTIONS;
        ssh_options_set(session, SSH_OPTIONS_LOG_VERBOSITY, &verbosity);
        ssh_connect(session);

/*
        if (ssh_userauth_publickey_auto(session, NULL, NULL) != SSH_AUTH_SUCCESS) {
                fprintf(stderr, "Public key auth failed.\n");
                return -1;
        }
*/

        fprintf(stderr, "Will call sftp_new\n");
        sftp_session sftp = sftp_new(session);
        fprintf(stderr, "Called sftp_new\n");
        sftp_init(sftp);

        ssh_disconnect(session);
        sftp_free(sftp);

        ssh_free(session);
        return 0;
}

hangs at the

[2019/03/14 14:38:34.461983, 3] ssh_packet_process:  Dispatching handler for packet type 7
[2019/03/14 14:38:34.461990, 3] ssh_packet_ext_info:  Received SSH_MSG_EXT_INFO
[2019/03/14 14:38:34.461996, 3] ssh_packet_ext_info:  Follows 1 extensions
[2019/03/14 14:38:34.462002, 3] ssh_packet_ext_info:  Extension: server-sig-algs=<ssh-ed25519,ssh-rsa,rsa-sha2-256,rsa-sha2-512,ssh-dss,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,null>
[2019/03/14 14:38:34.462011, 3] ssh_connect:  current state : 7
Will call sftp_new
[2019/03/14 14:38:34.462024, 2] channel_open:  Creating a channel 43 with 64000 window and 32768 max packet
[2019/03/14 14:38:34.462059, 3] packet_send2:  packet: wrote [len=44,padding=19,comp=24,payload=24]
[2019/03/14 14:38:34.462068, 3] channel_open:  Sent a SSH_MSG_CHANNEL_OPEN type session for channel 43
[2019/03/14 14:38:34.462077, 4] ssh_socket_pollcallback:  Poll callback on socket 3 (POLLOUT ), out buffer 80
[2019/03/14 14:38:34.462086, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2019/03/14 14:38:34.462093, 4] ssh_socket_pollcallback:  Poll callback on socket 3 (POLLOUT ), out buffer 0
[2019/03/14 14:38:34.462099, 4] ssh_socket_pollcallback:  sending control flow event
[2019/03/14 14:38:34.462104, 4] ssh_packet_socket_controlflow_callback:  sending channel_write_wontblock callback
[2019/03/14 14:38:34.502268, 4] ssh_socket_pollcallback:  Poll callback on socket 3 (POLLIN ), out buffer 0
[2019/03/14 14:38:34.502315, 3] ssh_packet_socket_callback:  packet: read type 3 [len=12,padding=6,comp=5,payload=5]
[2019/03/14 14:38:34.502323, 3] ssh_packet_process:  Dispatching handler for packet type 3
[2019/03/14 14:38:34.502330, 1] ssh_packet_unimplemented:  Received SSH_MSG_UNIMPLEMENTED (sequence number 3)

stage, that sftp_new() call never returns.

When the part calling ssh_userauth_publickey_auto() is uncommented, the output changes to

Will call sftp_new
[2019/03/14 14:40:22.871497, 2] channel_open:  Creating a channel 43 with 64000 window and 32768 max packet
[2019/03/14 14:40:22.871577, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2019/03/14 14:40:22.871599, 3] packet_send2:  packet: wrote [len=44,padding=19,comp=24,payload=24]
[2019/03/14 14:40:22.871623, 3] channel_open:  Sent a SSH_MSG_CHANNEL_OPEN type session for channel 43
[2019/03/14 14:40:22.871648, 4] ssh_socket_pollcallback:  Poll callback on socket 3 (POLLOUT ), out buffer 0
[2019/03/14 14:40:22.871668, 4] ssh_socket_pollcallback:  sending control flow event
[2019/03/14 14:40:22.871685, 4] ssh_packet_socket_controlflow_callback:  sending channel_write_wontblock callback
[2019/03/14 14:40:22.984270, 4] ssh_socket_pollcallback:  Poll callback on socket 3 (POLLIN ), out buffer 0
[2019/03/14 14:40:22.984857, 3] ssh_packet_socket_callback:  packet: read type 80 [len=492,padding=16,comp=475,payload=475]
[2019/03/14 14:40:22.984869, 3] ssh_packet_process:  Dispatching handler for packet type 80
[2019/03/14 14:40:22.984879, 2] ssh_packet_global_request:  Received SSH_MSG_GLOBAL_REQUEST packet
[2019/03/14 14:40:22.984886, 2] ssh_packet_global_request:  UNKNOWN SSH_MSG_GLOBAL_REQUEST hostkeys-00@openssh.com 0
[2019/03/14 14:40:22.984892, 1] ssh_packet_process:  Couldn't do anything with packet type 80
[2019/03/14 14:40:22.984936, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2019/03/14 14:40:22.984945, 3] packet_send2:  packet: wrote [len=12,padding=6,comp=5,payload=5]
[2019/03/14 14:40:22.984951, 3] ssh_packet_socket_callback:  Processing 176 bytes left in socket buffer
[2019/03/14 14:40:22.984963, 3] ssh_packet_socket_callback:  packet: read type 4 [len=140,padding=19,comp=120,payload=120]
[2019/03/14 14:40:22.984972, 3] ssh_packet_process:  Dispatching handler for packet type 4
[2019/03/14 14:40:22.984979, 2] ssh_packet_ignore_callback:  Received SSH_MSG_DEBUG packet
[2019/03/14 14:40:22.984989, 4] ssh_socket_pollcallback:  Poll callback on socket 3 (POLLIN POLLOUT ), out buffer 0
[2019/03/14 14:40:22.985002, 3] ssh_packet_socket_callback:  packet: read type 4 [len=140,padding=19,comp=120,payload=120]
[2019/03/14 14:40:22.985010, 3] ssh_packet_process:  Dispatching handler for packet type 4
[2019/03/14 14:40:22.985018, 2] ssh_packet_ignore_callback:  Received SSH_MSG_DEBUG packet
[2019/03/14 14:40:22.985031, 3] ssh_packet_socket_callback:  Processing 64 bytes left in socket buffer
[2019/03/14 14:40:22.985042, 3] ssh_packet_socket_callback:  packet: read type 91 [len=28,padding=10,comp=17,payload=17]
[2019/03/14 14:40:22.985050, 3] ssh_packet_process:  Dispatching handler for packet type 91
[2019/03/14 14:40:22.985058, 3] ssh_packet_channel_open_conf:  Received SSH2_MSG_CHANNEL_OPEN_CONFIRMATION
[2019/03/14 14:40:22.985066, 2] ssh_packet_channel_open_conf:  Received a CHANNEL_OPEN_CONFIRMATION for channel 43:0
[2019/03/14 14:40:22.985072, 2] ssh_packet_channel_open_conf:  Remote window : 0, maxpacket : 32768
[2019/03/14 14:40:22.985079, 4] ssh_socket_pollcallback:  sending control flow event
[2019/03/14 14:40:22.985088, 4] ssh_packet_socket_controlflow_callback:  sending channel_write_wontblock callback
[2019/03/14 14:40:22.985126, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2019/03/14 14:40:22.985135, 3] packet_send2:  packet: wrote [len=44,padding=16,comp=27,payload=27]
[2019/03/14 14:40:22.985143, 3] channel_request:  Sent a SSH_MSG_CHANNEL_REQUEST subsystem
[2019/03/14 14:40:22.985154, 4] ssh_socket_pollcallback:  Poll callback on socket 3 (POLLOUT ), out buffer 0
[2019/03/14 14:40:22.985160, 4] ssh_socket_pollcallback:  sending control flow event
[2019/03/14 14:40:22.985167, 4] ssh_packet_socket_controlflow_callback:  sending channel_write_wontblock callback
[2019/03/14 14:40:22.986675, 4] ssh_socket_pollcallback:  Poll callback on socket 3 (POLLIN ), out buffer 0
[2019/03/14 14:40:22.986707, 3] ssh_packet_socket_callback:  packet: read type 93 [len=28,padding=18,comp=9,payload=9]
[2019/03/14 14:40:22.986719, 3] ssh_packet_process:  Dispatching handler for packet type 93
[2019/03/14 14:40:22.986732, 2] channel_rcv_change_window:  Adding 2097152 bytes to channel (43:0) (from 0 bytes)
[2019/03/14 14:40:22.986741, 3] ssh_packet_socket_callback:  Processing 48 bytes left in socket buffer
[2019/03/14 14:40:22.986753, 3] ssh_packet_socket_callback:  packet: read type 99 [len=12,padding=6,comp=5,payload=5]
[2019/03/14 14:40:22.986762, 3] ssh_packet_process:  Dispatching handler for packet type 99
[2019/03/14 14:40:22.986771, 3] ssh_packet_channel_success:  Received SSH_CHANNEL_SUCCESS on channel (43:0)
[2019/03/14 14:40:22.986780, 2] channel_request:  Channel request subsystem success
Called sftp_new

I would expect some error state to be returned by sftp_new() in situation when the authentication did not happen.

Event Timeline

adelton created this task.Thu, Mar 14, 2:42 PM