Page MenuHomePhabricator

OpenSSH : ssh_channel_new and ssh_channel_open_session blocks when we reach MaxSessions limit
Open, Needs TriagePublic

Description

I have done the test with version 0.7.5. By default, OpenSSH limits to 10 the session for one connection. Libssh doesn't give an answer when it doesn't give back the hand to my program.

Event Timeline

qgarnier created this task.Aug 31 2017, 2:46 PM
asn added a project: Restricted Project.Sep 20 2018, 4:38 PM
Jakuje added a subscriber: Jakuje.Fri, Sep 13, 2:59 PM

I just tested the ssh-client from examples, which is using channel_open with sshd configured with MaxSessions 0 and it is correctly failing and not hanging for me. Can you test with current libssh master or 0.9 and provide more ellaborate reproducer?

I didn't test with 'MaxSession 0'. I let the default value. I have done a new test with libssh 0.9.0. I tried to open 12 channels at the same time. Now it hangs on 'ssh_channel_request_exec'.
I should have an error before when i tries to open a session with 'ssh_channel_open_session' no ?

You can test it if you have a rhel/centos 7. Need to install rpm:
https://github.com/garnier-quentin/perl-libssh/tree/master/contrib/RPMS

And a script:

use Libssh::Session qw(:all);

my $ssh_host = "10.30.2.15";
my $ssh_port = 22;
my $ssh_user = "root";
my $ssh_pass = "centreon";

my $session = Libssh::Session->new();
if ($session->options(host => $ssh_host, port => $ssh_port, user => $ssh_user) != SSH_OK) {
    print $session->error() . "\n";
    exit(1);
}

if ($session->connect() != SSH_OK) {
    print $session->error() . "\n";
    exit(1);
}

if ($session->auth_publickey_auto() != SSH_AUTH_SUCCESS) {
    printf("auth issue pubkey: %s\n", $session->error(GetErrorSession => 1));
    if ($session->auth_password(password => $ssh_pass) != SSH_AUTH_SUCCESS) {
        printf("auth issue: %s\n", $session->error(GetErrorSession => 1));
        exit(1);
    }
}

print "== authentification succeeded\n";

sub my_callback {
    my (%options) = @_;

    print "================================================\n";
    print "=== exit = " . $options{exit} . "\n";
    if ($options{exit} == SSH_OK || $options{exit} == SSH_AGAIN) { # AGAIN means timeout
        print "=== exit_code = " . $options{exit_code} . "\n";
        print "=== userdata = " . $options{userdata} . "\n";
        print "=== stdout = " . $options{stdout} . "\n";
        print "=== stderr = " . $options{stderr} . "\n";
    } else {
        printf("error: %s\n", $session->error(GetErrorSession => 1));
    }
    print "================================================\n";

    #$options{session}->add_command(command => { cmd => 'ls -l', callback => \&my_callback, userdata => 'cmd 3'});
}

$session->execute(commands => [
                    { cmd => 'sleep 5; ls -l', callback => \&my_callback, userdata => 'cmd ok'},
                    { cmd => 'sleep 8; ls -l', callback => \&my_callback, userdata => 'cmd ok 2'},
                    { cmd => 'sleep 8; ls -l', callback => \&my_callback, userdata => 'cmd ok 3'},
                    { cmd => 'sleep 5; ls -l', callback => \&my_callback, userdata => 'cmd ok 4'},
                    { cmd => 'sleep 8; ls -l', callback => \&my_callback, userdata => 'cmd ok 5 '},
                    { cmd => 'sleep 8; ls -l', callback => \&my_callback, userdata => 'cmd ok 6 '},
                    { cmd => 'sleep 8; ls -l', callback => \&my_callback, userdata => 'cmd ok 7 '},
                    { cmd => 'sleep 8; ls -l', callback => \&my_callback, userdata => 'cmd ok 8 '},
                    { cmd => 'sleep 8; ls -l', callback => \&my_callback, userdata => 'cmd ok 9 '},
                    { cmd => 'sleep 8; ls -l', callback => \&my_callback, userdata => 'cmd ok 10 '},
                    { cmd => 'ls wanterrormsg', callback => \&my_callback, userdata => 'cmd stderr'},
                    { cmd => 'ls -l; sleep 20; ls -l; sleep 20;', callback => \&my_callback, userdata => 'cmd timeout'},
                    { cmd => 'sleep 7', callback => \&my_callback, userdata => 'cmd timeout no data'},
                  ],
                  timeout => 20, timeout_nodata => 10, parallel => 12);

exit(0);

Thank you for the reproducer. I can confirm and reproduce with your attached code. This is the backtrace:

#0  0x00007f8df8576c10 in __poll_nocancel () from /lib64/libc.so.6
#1  0x00007f8df14d58c0 in ssh_poll () from /lib64/libssh.so.4
#2  0x00007f8df14d6033 in ssh_poll_ctx_dopoll () from /lib64/libssh.so.4
#3  0x00007f8df14d798c in ssh_handle_packets () from /lib64/libssh.so.4
#4  0x00007f8df14d7a93 in ssh_handle_packets_termination () from /lib64/libssh.so.4
#5  0x00007f8df14ae889 in channel_request () from /lib64/libssh.so.4
#6  0x00007f8df14afa6b in ssh_channel_request_exec () from /lib64/libssh.so.4
#7  0x00007f8df1740837 in XS_Libssh__Session_ssh_channel_request_exec ()
   from /usr/lib64/perl5/vendor_perl/auto/Libssh/Session/Session.so
#8  0x00007f8df989c41f in Perl_pp_entersub () from /usr/lib64/perl5/CORE/libperl.so
#9  0x00007f8df9894b96 in Perl_runops_standard () from /usr/lib64/perl5/CORE/libperl.so
#10 0x00007f8df9831985 in perl_run () from /usr/lib64/perl5/CORE/libperl.so
#11 0x0000000000400ce9 in main ()

In the server, log the event of failed session opening is visible here:

Sep 17 14:59:42 jjelen-rhel-7.3 sshd[1553]: debug1: channel 10: new [server-session]
Sep 17 14:59:42 jjelen-rhel-7.3 sshd[1553]: debug1: session_open: channel 10
Sep 17 14:59:42 jjelen-rhel-7.3 sshd[1553]: error: no more sessions
Sep 17 14:59:42 jjelen-rhel-7.3 sshd[1553]: debug1: session open failed, free channel 10
Sep 17 14:59:42 jjelen-rhel-7.3 sshd[1553]: debug1: channel 10: free: server-session, nchannels 11
Sep 17 14:59:42 jjelen-rhel-7.3 sshd[1553]: debug3: channel 10: status: The following connections are open:\r\n ...
Sep 17 14:59:42 jjelen-rhel-7.3 sshd[1553]: debug1: server_input_channel_open: failure session

If I read the specs and openssh code correctly, already the channel_open fails with the error, even though your code gets to the sending the request through this failed channel.

The debug logs from libssh says that it received the failure correctly:

[2019/09/17 14:59:42.185127, 3] channel_open:  Sent a SSH_MSG_CHANNEL_OPEN type session for channel 53
[2019/09/17 14:59:42.185140, 4] ssh_socket_pollcallback:  Poll callback on socket 3 (POLLOUT ), out buffer 0
[2019/09/17 14:59:42.185150, 4] ssh_socket_pollcallback:  sending control flow event
[2019/09/17 14:59:42.185159, 4] ssh_packet_socket_controlflow_callback:  sending channel_write_wontblock callback
[2019/09/17 14:59:42.186449, 4] ssh_socket_pollcallback:  Poll callback on socket 3 (POLLIN ), out buffer 0
[2019/09/17 14:59:42.186475, 3] ssh_packet_socket_callback:  packet: read type 92 [len=48,padding=19,comp=28,payload=28]
[2019/09/17 14:59:42.186487, 3] ssh_packet_process:  Dispatching handler for packet type 92
[2019/09/17 14:59:42.186502, 1] ssh_packet_channel_open_fail:  Channel opening failure: channel 53 error (1) open failed

Immediately after that, some errors follow, which means that the failure above was not correctly propagated to the calling function (your perl code):

[2019/09/17 14:59:42.186628, 3] channel_request:  Sent a SSH_MSG_CHANNEL_REQUEST exec
[2019/09/17 14:59:42.186640, 4] ssh_socket_pollcallback:  Poll callback on socket 3 (POLLOUT ), out buffer 0
[2019/09/17 14:59:42.186669, 4] ssh_socket_pollcallback:  sending control flow event
[2019/09/17 14:59:42.186681, 4] ssh_packet_socket_controlflow_callback:  sending channel_write_wontblock callback
[2019/09/17 14:59:42.189931, 4] ssh_socket_pollcallback:  Poll callback on socket 3 (POLLIN ), out buffer 0
[2019/09/17 14:59:42.189957, 3] ssh_packet_socket_callback:  packet: read type 100 [len=16,padding=10,comp=5,payload=5]
[2019/09/17 14:59:42.189969, 3] ssh_packet_process:  Dispatching handler for packet type 100
[2019/09/17 14:59:42.189980, 3] ssh_packet_channel_failure:  Received SSH_CHANNEL_FAILURE on channel (43:0)
[2019/09/17 14:59:42.189990, 1] ssh_packet_channel_failure:  SSH_CHANNEL_FAILURE received in incorrect state 0

Reading through the code of libssh, it looks like it does not handle the failures of channel_open() correctly -- the channel_open() allocates the channel structure and sets state OPENING. The ssh_packet_channel_open_fail() function handles the failure of opening and sets the state to OPEN_DENIED, which is handled inside of ssh_handle_packets_termination() function. Further on in channel_open(), we check the status and set the return code to SSH_OK only if the channel was opened successfully. But in case it was not, the return value from ssh_handle_packets_termination() is used, which is also SSH_OK if I am right.

If I am right, the following patch should address the issue. I was not able to build RHEL 7 libssh package because of outdated cmake nor I was able to make your perl module on my Fedora. It would be great if you could try that:

https://gitlab.com/jjelen/libssh-mirror/commit/7788d760a38e40987ea7e90141607ce14e60ea07

Thanks! I test tomorrow with your patch on libssh. I give you a feedback if it solved or not.

qgarnier added a comment.EditedWed, Sep 18, 9:34 AM

I have tested and it's working now! Thanks

== authentification succeeded
================================================
=== exit = -1
error: Channel opening failure: channel 53 error (1) open failed
================================================
================================================
=== exit = -1
error: Channel opening failure: channel 54 error (1) open failed
================================================
================================================
=== exit = -1
error: Channel opening failure: channel 55 error (1) open failed
...

I have a request. Could you add the perl binding in the listing ? Or is not enough finished for that ?

Jakuje added a subscriber: asn.Wed, Sep 18, 10:43 AM

Thank you for testing. Whether and where to list your perl bindings in the main page, that is more up to @asn, but I do not think it should be a problem.