Page MenuHomePhabricator

[sftp] sftp_new - channel opening failure
Closed, InvalidPublic

Description

Hi,

I have an issue to open sftp session on a ssh server through a Wallix Bastion. (ssh connection is ok) I use libssh 0.9.4.
My logs:

[2020/09/03 11:29:11.812530, 2] channel_open:  Creating a channel 44 with 64000 window and 32768 max packet
[2020/09/03 11:29:11.812547, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=67, in_blocks=23
[2020/09/03 11:29:11.812569, 3] packet_send2:  packet: wrote [type=90, len=44, padding_size=19, comp=24, payload=24]
[2020/09/03 11:29:11.812581, 3] channel_open:  Sent a SSH_MSG_CHANNEL_OPEN type session for channel 44
[2020/09/03 11:29:11.812597, 4] ssh_socket_pollcallback:  Poll callback on socket 3 (POLLOUT ), out buffer 80
[2020/09/03 11:29:11.812611, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2020/09/03 11:29:11.812625, 4] ssh_socket_pollcallback:  Poll callback on socket 3 (POLLOUT ), out buffer 0
[2020/09/03 11:29:11.812636, 4] ssh_socket_pollcallback:  sending control flow event
[2020/09/03 11:29:11.812646, 4] ssh_packet_socket_controlflow_callback:  sending channel_write_wontblock callback
[2020/09/03 11:29:11.828640, 4] ssh_socket_pollcallback:  Poll callback on socket 3 (POLLIN ), out buffer 0
[2020/09/03 11:29:11.828718, 3] ssh_packet_socket_callback:  packet: read type 92 [len=28,padding=10,comp=17,payload=17]
[2020/09/03 11:29:11.828746, 3] ssh_packet_process:  Dispatching handler for packet type 92
[2020/09/03 11:29:11.828774, 1] ssh_packet_channel_open_fail:  Channel opening failure: channel 44 error (1)
[2020/09/03 11:29:11.828800, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=67, in_blocks=23
error allocating SFTP session: Channel opening failure: channel 44 error (1)
[2020/09/03 11:29:11.828939, 3] ssh_packet_need_rekey:  packet: [data_rekey_needed=0, out_blocks=68, in_blocks=24
[2020/09/03 11:29:11.829063, 3] ssh_socket_unbuffered_write:  Enabling POLLOUT for socket
[2020/09/03 11:29:11.829080, 3] packet_send2:  packet: wrote [type=1, len=28, padding_size=7, comp=20, payload=20]

I have tried with sftp cli and it's working. I provide the log:

OpenSSH_7.4p1, OpenSSL 1.0.2k-fips  26 Jan 2017
debug1: Reading configuration data /root/.ssh/config
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 58: Applying options for *
debug2: resolving "10.239.239.212" port 22
debug2: ssh_connect_direct: needpriv 0
debug1: Connecting to 10.239.239.212 [10.239.239.212] port 22.
debug1: Connection established.
debug1: permanently_set_uid: 0/0
debug1: identity file /var/lib/centreon-gorgone/.ssh/plop_bastion_rsa type 1
debug1: key_load_public: No such file or directory
debug1: identity file /var/lib/centreon-gorgone/.ssh/plop_bastion_rsa-cert type -1
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_7.4
debug1: Remote protocol version 2.0, remote software version sashimi-0.6.5
debug1: no match: sashimi-0.6.5
debug2: fd 3 setting O_NONBLOCK
debug1: Authenticating to 10.239.239.212:22 as 'centreon@local@150001li97.ge.plop.fr:SSH:EXAPROBE'
debug3: hostkeys_foreach: reading file "/root/.ssh/known_hosts"
debug3: record_hostkey: found key type ED25519 in file /root/.ssh/known_hosts:39
debug3: load_hostkeys: loaded 1 keys from 10.239.239.212
debug3: order_hostkeyalgs: prefer hostkeyalgs: ssh-ed25519-cert-v01@openssh.com,ssh-ed25519
debug3: send packet: type 20
debug1: SSH2_MSG_KEXINIT sent
debug3: receive packet: type 20
debug1: SSH2_MSG_KEXINIT received
debug2: local client KEXINIT proposal
debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1,ext-info-c
debug2: host key algorithms: ssh-ed25519-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ssh-dss-cert-v01@openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss
debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc
debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc
debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: compression ctos: none,zlib@openssh.com,zlib
debug2: compression stoc: none,zlib@openssh.com,zlib
debug2: languages ctos:
debug2: languages stoc:
debug2: first_kex_follows 0
debug2: reserved 0
debug2: peer server KEXINIT proposal
debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,diffie-hellman-group-exchange-sha256
debug2: host key algorithms: ssh-ed25519,ssh-rsa
debug2: ciphers ctos: aes256-ctr,aes192-ctr,aes128-ctr,chacha20-poly1305@openssh.com
debug2: ciphers stoc: aes256-ctr,aes192-ctr,aes128-ctr,chacha20-poly1305@openssh.com
debug2: MACs ctos: hmac-sha2-256,hmac-sha2-512
debug2: MACs stoc: hmac-sha2-256,hmac-sha2-512
debug2: compression ctos: none
debug2: compression stoc: none
debug2: languages ctos:
debug2: languages stoc:
debug2: first_kex_follows 0
debug2: reserved 0
debug1: kex: algorithm: curve25519-sha256
debug1: kex: host key algorithm: ssh-ed25519
debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none
debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none
debug1: kex: curve25519-sha256 need=64 dh_need=64
debug1: kex: curve25519-sha256 need=64 dh_need=64
debug3: send packet: type 30
debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
debug3: receive packet: type 31
debug1: Server host key: ssh-ed25519 SHA256:3DK2gcuEfveCk8Txdz3yi5X+upHzvvR2bqly/S4FJXM
debug3: hostkeys_foreach: reading file "/root/.ssh/known_hosts"
debug3: record_hostkey: found key type ED25519 in file /root/.ssh/known_hosts:39
debug3: load_hostkeys: loaded 1 keys from 10.239.239.212
debug1: Host '10.239.239.212' is known and matches the ED25519 host key.
debug1: Found key in /root/.ssh/known_hosts:39
debug3: send packet: type 21
debug2: set_newkeys: mode 1
debug1: rekey after 134217728 blocks
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug3: receive packet: type 21
debug1: SSH2_MSG_NEWKEYS received
debug2: set_newkeys: mode 0
debug1: rekey after 134217728 blocks
debug2: key: /var/lib/centreon-gorgone/.ssh/plop_bastion_rsa (0x558d64663050), explicit
debug3: send packet: type 5
debug3: receive packet: type 6
debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug3: send packet: type 50
debug3: receive packet: type 51
debug1: Authentications that can continue: publickey,gssapi-with-mic,keyboard-interactive,password
debug3: start over, passed a different list publickey,gssapi-with-mic,keyboard-interactive,password
debug3: preferred gssapi-keyex,gssapi-with-mic,publickey,keyboard-interactive,password
debug3: authmethod_lookup gssapi-with-mic
debug3: remaining preferred: publickey,keyboard-interactive,password
debug3: authmethod_is_enabled gssapi-with-mic
debug1: Next authentication method: gssapi-with-mic
debug1: Unspecified GSS failure.  Minor code may provide more information
No Kerberos credentials available (default cache: KEYRING:persistent:0)

debug1: Unspecified GSS failure.  Minor code may provide more information
No Kerberos credentials available (default cache: KEYRING:persistent:0)

debug2: we did not send a packet, disable method
debug3: authmethod_lookup publickey
debug3: remaining preferred: keyboard-interactive,password
debug3: authmethod_is_enabled publickey
debug1: Next authentication method: publickey
debug1: Offering RSA public key: /var/lib/centreon-gorgone/.ssh/plop_bastion_rsa
debug3: send_pubkey_test
debug3: send packet: type 50
debug2: we sent a publickey packet, wait for reply
debug3: receive packet: type 60
debug1: Server accepts key: pkalg ssh-rsa blen 277
debug2: input_userauth_pk_ok: fp SHA256:3bz7GU6RCzSEqFUknivC/e72EaKGOEbYNvOWY5qr60M
debug3: sign_and_send_pubkey: RSA SHA256:3bz7GU6RCzSEqFUknivC/e72EaKGOEbYNvOWY5qr60M
debug3: send packet: type 50
debug3: receive packet: type 52
debug1: Authentication succeeded (publickey).
Authenticated to 10.239.239.212 ([10.239.239.212]:22).
debug2: fd 4 setting O_NONBLOCK
debug3: fd 5 is O_NONBLOCK
debug1: channel 0: new [client-session]
debug3: ssh_session2_open: channel_new: 0
debug2: channel 0: send open
debug3: send packet: type 90
debug1: Entering interactive session.
debug1: pledge: network
debug3: receive packet: type 91
debug2: callback start
debug2: fd 3 setting TCP_NODELAY
debug3: ssh_packet_set_tos: set IP_TOS 0x08
debug2: client_session2_setup: id 0
debug1: Sending environment.
debug3: Ignored env XDG_SESSION_ID
debug3: Ignored env HOSTNAME
debug3: Ignored env TERM
debug3: Ignored env SHELL
debug3: Ignored env HISTSIZE
debug3: Ignored env SSH_CLIENT
debug3: Ignored env PERL5LIB
debug3: Ignored env QTDIR
debug3: Ignored env PERL_MB_OPT
debug3: Ignored env QTINC
debug3: Ignored env SSH_TTY
debug3: Ignored env QT_GRAPHICSSYSTEM_CHECKED
debug3: Ignored env USER
debug3: Ignored env LS_COLORS
debug3: Ignored env MAIL
debug3: Ignored env PATH
debug3: Ignored env PWD
debug1: Sending env LANG = en_US.UTF-8
debug2: channel 0: request env confirm 0
debug3: send packet: type 98
debug3: Ignored env HISTCONTROL
debug3: Ignored env SHLVL
debug3: Ignored env HOME
debug3: Ignored env PERL_LOCAL_LIB_ROOT
debug3: Ignored env LOGNAME
debug3: Ignored env QTLIB
debug3: Ignored env SSH_CONNECTION
debug3: Ignored env LESSOPEN
debug3: Ignored env XDG_RUNTIME_DIR
debug3: Ignored env PERL_MM_OPT
debug3: Ignored env _
debug1: Sending subsystem: sftp
debug2: channel 0: request subsystem confirm 1
debug3: send packet: type 98
debug2: callback done
debug2: channel 0: open confirm rwindow 32000 rmax 35000
debug3: receive packet: type 99
debug2: channel_input_status_confirm: type 99 id 0
debug2: subsystem request accepted on channel 0
debug2: channel 0: rcvd adjust 1248009
debug2: Remote version: 3
debug2: Server supports extension "posix-rename@openssh.com" revision 1
debug2: Server supports extension "statvfs@openssh.com" revision 2
debug2: Server supports extension "fstatvfs@openssh.com" revision 2
debug2: Server supports extension "hardlink@openssh.com" revision 1
debug2: Server supports extension "fsync@openssh.com" revision 1
Connected to 10.239.239.212.
debug3: Sent message fd 3 T:16 I:1
debug3: SSH_FXP_REALPATH . -> /var/spool/centreon size 0
sftp>

What do you think about it ? A bug of libssh ? Maybe i should open a channel and use 'sftp_new_channel' ('sftp_new') ?

Event Timeline

qgarnier created this task.Thu, Sep 3, 11:54 AM
qgarnier updated the task description. (Show Details)
Jakuje added a subscriber: Jakuje.Thu, Sep 3, 12:16 PM

Please, share what code did you use (what function calls). The server can be restrticted to SFTP only and if you try to open different channel, it can fail. To create sftp channel, you should use just sftp_new(), sftp_init() as in the examples/samplesftp.c.

I use exactly that functions: https://github.com/garnier-quentin/perl-libssh/blob/master/lib/Libssh/Sftp.pm#L69

$self->{sftp_session} = sftp_new($session);
if (!defined($self->{sftp_session})) {
    $self->set_err(msg => 'error allocating SFTP session: ' . $options{session}->get_error());
    return SSH_ERROR;
}

my $ret = sftp_init($self->{sftp_session});
Jakuje added a comment.Thu, Sep 3, 2:40 PM

Some server logs might be helpful, but it looks like it is some non-standard ssh implementation so it might be hard.

The log says that you sent SSH_MSG_CHANNEL_OPEN (90) packet and got SSH_MSG_CHANNEL_OPEN_FAILURE (92) answer. The server provides just code (1) and no error description, which would be otherwise printed in the logs.

I also see that in this log, you request channel number 44, but libssh starts with channel 42, which means you already requested some channels in your code before this log. Can you share the whole log or what functions you call before?

Can you try to run the same code against normal OpenSSH server?

It's not an issue about libssh. In fact, we can only open 1 channel on the ssh connection. It's because of the software: Wallix bastion. Thanks for the help!

qgarnier closed this task as Invalid.Fri, Sep 4, 2:31 PM