search

amphp / ssh

Async SSH client for PHP based on Amp.
35 stars 7 forks source link

Sessions are not properly closed #22

Open Mika56 opened 2 years ago

Mika56 commented 2 years ago

Hi,

Using Process, it looks like the SSH sessions are not properly closed. This is easy to reproduce, you just have to send more than 10 commands: 

<?php
$command = 'date && sleep 0.2s';
$sessions = 11;

Loop::run(function() use ($command, $sessions) {
    $authentication = new UsernamePassword('mikael', '');
    $sshResource = yield connect('192.168.2.250:22', $authentication);

    for($i = 0; $i < $sessions; $i++) {
        $process = new Process($sshResource, $command);
        $buffer = buffer($process->getStdout());
        yield $process->start();
        yield $process->join();
        echo 'Session '.$i.' output: '.(yield $buffer).PHP_EOL;
    }

    yield $sshResource->close();
});

The output with $sessions = 10; is as expected:

Session 0 output: Sat 05 Mar 2022 05:45:00 PM CET

Session 1 output: Sat 05 Mar 2022 05:45:00 PM CET

Session 2 output: Sat 05 Mar 2022 05:45:00 PM CET

Session 3 output: Sat 05 Mar 2022 05:45:01 PM CET

Session 4 output: Sat 05 Mar 2022 05:45:01 PM CET

Session 5 output: Sat 05 Mar 2022 05:45:01 PM CET

Session 6 output: Sat 05 Mar 2022 05:45:01 PM CET

Session 7 output: Sat 05 Mar 2022 05:45:02 PM CET

Session 8 output: Sat 05 Mar 2022 05:45:02 PM CET

Session 9 output: Sat 05 Mar 2022 05:45:02 PM CET

However, adding one more session fails:

Session 0 output: Sat 05 Mar 2022 05:45:40 PM CET

Session 1 output: Sat 05 Mar 2022 05:45:40 PM CET

Session 2 output: Sat 05 Mar 2022 05:45:40 PM CET

Session 3 output: Sat 05 Mar 2022 05:45:40 PM CET

Session 4 output: Sat 05 Mar 2022 05:45:41 PM CET

Session 5 output: Sat 05 Mar 2022 05:45:41 PM CET

Session 6 output: Sat 05 Mar 2022 05:45:41 PM CET

Session 7 output: Sat 05 Mar 2022 05:45:41 PM CET

Session 8 output: Sat 05 Mar 2022 05:45:41 PM CET

Session 9 output: Sat 05 Mar 2022 05:45:42 PM CET

[critical] Error thrown while running command "ssh-session-test -v". Message: "Failed to open channel : open failed"

In Channel.php line 134:

  [RuntimeException]
  Failed to open channel : open failed

Exception trace:
  at /home/mikael/configurer/vendor/amphp/ssh/src/Channel/Channel.php:134
 Amp\Ssh\Channel\Channel->Amp\Ssh\Channel\{closure}() at n/a:n/a
 Generator->send() at /home/mikael/configurer/vendor/amphp/amp/lib/Coroutine.php:118
 Amp\Coroutine->Amp\{closure}() at /home/mikael/configurer/vendor/amphp/amp/lib/Internal/Placeholder.php:149
 Amp\Promise@anonymous\/home/mikael/configurer/vendor/amphp/amp/lib/Deferred.php:22$7f->resolve() at /home/mikael/configurer/vendor/amphp/amp/lib/Deferred.php:53
 Amp\Deferred->resolve() at /home/mikael/configurer/vendor/amphp/amp/lib/Internal/Producer.php:143
 Amp\Iterator@anonymous\/home/mikael/configurer/vendor/amphp/amp/lib/Emitter.php:23$b3->emit() at /home/mikael/configurer/vendor/amphp/amp/lib/Emitter.php:58
 Amp\Emitter->emit() at /home/mikael/configurer/vendor/amphp/ssh/src/Channel/Dispatcher.php:57
 Amp\Ssh\Channel\Dispatcher->Amp\Ssh\Channel\{closure}() at n/a:n/a
 Generator->send() at /home/mikael/configurer/vendor/amphp/amp/lib/Coroutine.php:118
 Amp\Coroutine->Amp\{closure}() at /home/mikael/configurer/vendor/amphp/amp/lib/Internal/Placeholder.php:149
 Amp\Coroutine->resolve() at /home/mikael/configurer/vendor/amphp/amp/lib/Coroutine.php:123
 Amp\Coroutine->Amp\{closure}() at /home/mikael/configurer/vendor/amphp/amp/lib/Internal/Placeholder.php:149
 Amp\Coroutine->resolve() at /home/mikael/configurer/vendor/amphp/amp/lib/Coroutine.php:123
 Amp\Coroutine->Amp\{closure}() at /home/mikael/configurer/vendor/amphp/amp/lib/Internal/Placeholder.php:149
 Amp\Coroutine->resolve() at /home/mikael/configurer/vendor/amphp/amp/lib/Coroutine.php:123
 Amp\Coroutine->Amp\{closure}() at /home/mikael/configurer/vendor/amphp/amp/lib/Internal/Placeholder.php:149
 Amp\Coroutine->resolve() at /home/mikael/configurer/vendor/amphp/amp/lib/Coroutine.php:123
 Amp\Coroutine->Amp\{closure}() at /home/mikael/configurer/vendor/amphp/amp/lib/Internal/Placeholder.php:149
 Amp\Coroutine->resolve() at /home/mikael/configurer/vendor/amphp/amp/lib/Coroutine.php:123
 Amp\Coroutine->Amp\{closure}() at /home/mikael/configurer/vendor/amphp/amp/lib/Internal/Placeholder.php:149
 Amp\Promise@anonymous\/home/mikael/configurer/vendor/amphp/amp/lib/Deferred.php:22$7f->resolve() at /home/mikael/configurer/vendor/amphp/amp/lib/Deferred.php:53
 Amp\Deferred->resolve() at /home/mikael/configurer/vendor/amphp/byte-stream/lib/ResourceInputStream.php:101
 Amp\ByteStream\ResourceInputStream::Amp\ByteStream\{closure}() at /home/mikael/configurer/vendor/amphp/amp/lib/Loop/NativeDriver.php:327
 Amp\Loop\NativeDriver->selectStreams() at /home/mikael/configurer/vendor/amphp/amp/lib/Loop/NativeDriver.php:127
 Amp\Loop\NativeDriver->dispatch() at /home/mikael/configurer/vendor/amphp/amp/lib/Loop/Driver.php:138
 Amp\Loop\Driver->tick() at /home/mikael/configurer/vendor/amphp/amp/lib/Loop/Driver.php:72
 Amp\Loop\Driver->run() at /home/mikael/configurer/vendor/amphp/amp/lib/Loop.php:95
 Amp\Loop::run() at /home/mikael/configurer/src/Command/SshSessionTestCommand.php:43
 App\Command\SshSessionTestCommand->execute() at /home/mikael/configurer/vendor/symfony/console/Command/Command.php:291
 Symfony\Component\Console\Command\Command->run() at /home/mikael/configurer/vendor/symfony/console/Application.php:1007
 Symfony\Component\Console\Application->doRunCommand() at /home/mikael/configurer/vendor/symfony/framework-bundle/Console/Application.php:94
 Symfony\Bundle\FrameworkBundle\Console\Application->doRunCommand() at /home/mikael/configurer/vendor/symfony/console/Application.php:299
 Symfony\Component\Console\Application->doRun() at /home/mikael/configurer/vendor/symfony/framework-bundle/Console/Application.php:80
 Symfony\Bundle\FrameworkBundle\Console\Application->doRun() at /home/mikael/configurer/vendor/symfony/console/Application.php:171
 Symfony\Component\Console\Application->run() at /home/mikael/configurer/vendor/symfony/runtime/Runner/Symfony/ConsoleApplicationRunner.php:54
 Symfony\Component\Runtime\Runner\Symfony\ConsoleApplicationRunner->run() at /home/mikael/configurer/vendor/autoload_runtime.php:29
 require_once() at /home/mikael/configurer/bin/console:11

Here are the corresponding logs from the SSH server:

Mar 05 17:45:42 deployer-target sshd[3230]: Starting session: command for mikael from 192.168.2.15 port 55428 id 9
Mar 05 17:45:42 deployer-target sshd[3230]: debug2: fd 11 setting O_NONBLOCK
Mar 05 17:45:42 deployer-target sshd[3230]: debug2: fd 10 setting O_NONBLOCK
Mar 05 17:45:42 deployer-target sshd[3230]: debug2: fd 13 setting O_NONBLOCK
Mar 05 17:45:42 deployer-target sshd[3230]: debug2: channel 9: read<=0 rfd 11 len 0
Mar 05 17:45:42 deployer-target sshd[3230]: debug2: channel 9: read failed
Mar 05 17:45:42 deployer-target sshd[3230]: debug2: channel 9: chan_shutdown_read (i0 o0 sock -1 wfd 11 efd 13 [read])
Mar 05 17:45:42 deployer-target sshd[3230]: debug2: channel 9: input open -> drain
Mar 05 17:45:42 deployer-target sshd[3230]: debug2: channel 9: read 0 from efd 13
Mar 05 17:45:42 deployer-target sshd[3230]: debug2: channel 9: closing read-efd 13
Mar 05 17:45:42 deployer-target sshd[3230]: debug2: channel 9: ibuf empty
Mar 05 17:45:42 deployer-target sshd[3230]: debug2: channel 9: send eof
Mar 05 17:45:42 deployer-target sshd[3230]: debug2: channel 9: input drain -> closed
Mar 05 17:45:42 deployer-target sshd[3230]: debug1: Received SIGCHLD.
Mar 05 17:45:42 deployer-target sshd[3230]: debug1: session_by_pid: pid 3249
Mar 05 17:45:42 deployer-target sshd[3230]: debug1: session_exit_message: session 9 channel 9 pid 3249
Mar 05 17:45:42 deployer-target sshd[3230]: debug2: channel 9: request exit-status confirm 0
Mar 05 17:45:42 deployer-target sshd[3230]: debug1: session_exit_message: release channel 9
Mar 05 17:45:42 deployer-target sshd[3230]: debug2: channel 9: write failed
Mar 05 17:45:42 deployer-target sshd[3230]: debug2: channel 9: chan_shutdown_write (i3 o0 sock -1 wfd 10 efd -1 [closed])
Mar 05 17:45:42 deployer-target sshd[3230]: debug2: channel 9: send eow
Mar 05 17:45:42 deployer-target sshd[3230]: debug2: channel 9: output open -> closed
Mar 05 17:45:42 deployer-target sshd[3230]: debug2: channel 9: send close
Mar 05 17:45:42 deployer-target sshd[3230]: debug2: notify_done: reading
Mar 05 17:45:42 deployer-target sshd[3230]: debug1: server_input_channel_open: ctype session rchan 10 win 2147483647 max 16384
Mar 05 17:45:42 deployer-target sshd[3230]: debug1: input_session_request
Mar 05 17:45:42 deployer-target sshd[3230]: debug2: channel: expanding 20
Mar 05 17:45:42 deployer-target sshd[3230]: debug1: channel 10: new [server-session]
Mar 05 17:45:42 deployer-target sshd[3230]: debug1: session_open: channel 10
Mar 05 17:45:42 deployer-target sshd[3230]: error: no more sessions
Mar 05 17:45:42 deployer-target sshd[3230]: debug1: session open failed, free channel 10
Mar 05 17:45:42 deployer-target sshd[3230]: debug1: channel 10: free: server-session, nchannels 11
Mar 05 17:45:42 deployer-target sshd[3230]: debug1: server_input_channel_open: failure session

I'm no expert on SSH, but from what I could gather, the log should look like this:

Mar 05 17:48:40 deployer-target sshd[3257]: Starting session: command for mikael from 192.168.2.15 port 55430 id 0
Mar 05 17:48:40 deployer-target sshd[3257]: debug2: fd 4 setting TCP_NODELAY
Mar 05 17:48:40 deployer-target sshd[3257]: debug2: fd 11 setting O_NONBLOCK
Mar 05 17:48:40 deployer-target sshd[3257]: debug2: fd 10 setting O_NONBLOCK
Mar 05 17:48:40 deployer-target sshd[3257]: debug2: fd 13 setting O_NONBLOCK
Mar 05 17:48:40 deployer-target sshd[3257]: debug2: channel 0: read 0 from efd 13
Mar 05 17:48:40 deployer-target sshd[3257]: debug2: channel 0: closing read-efd 13
Mar 05 17:48:40 deployer-target sshd[3257]: debug2: notify_done: reading
Mar 05 17:48:40 deployer-target sshd[3257]: debug1: Received SIGCHLD.
Mar 05 17:48:40 deployer-target sshd[3257]: debug1: session_by_pid: pid 3258
Mar 05 17:48:40 deployer-target sshd[3257]: debug1: session_exit_message: session 0 channel 0 pid 3258
Mar 05 17:48:40 deployer-target sshd[3257]: debug2: channel 0: request exit-status confirm 0
Mar 05 17:48:40 deployer-target sshd[3257]: debug1: session_exit_message: release channel 0
Mar 05 17:48:40 deployer-target sshd[3257]: debug2: channel 0: write failed
Mar 05 17:48:40 deployer-target sshd[3257]: debug2: channel 0: chan_shutdown_write (i0 o0 sock -1 wfd 10 efd -1 [closed])
Mar 05 17:48:40 deployer-target sshd[3257]: debug2: channel 0: send eow
Mar 05 17:48:40 deployer-target sshd[3257]: debug2: channel 0: output open -> closed
--- Different from here ---
Mar 05 17:48:40 deployer-target sshd[3257]: debug2: channel 0: read<=0 rfd 11 len 0
Mar 05 17:48:40 deployer-target sshd[3257]: debug2: channel 0: read failed
Mar 05 17:48:40 deployer-target sshd[3257]: debug2: channel 0: chan_shutdown_read (i0 o3 sock -1 wfd 11 efd -1 [closed])
Mar 05 17:48:40 deployer-target sshd[3257]: debug2: channel 0: input open -> drain
Mar 05 17:48:40 deployer-target sshd[3257]: debug2: channel 0: ibuf empty
Mar 05 17:48:40 deployer-target sshd[3257]: debug2: channel 0: send eof
Mar 05 17:48:40 deployer-target sshd[3257]: debug2: channel 0: input drain -> closed
--- Different until here ---
Mar 05 17:48:40 deployer-target sshd[3257]: debug2: channel 0: send close
--- Different again
Mar 05 17:48:40 deployer-target sshd[3257]: debug2: channel 0: rcvd close
--- End of connection ---
Mar 05 17:48:40 deployer-target sshd[3257]: Received disconnect from 192.168.2.15 port 55430:11: disconnected by user

I think the Amp\Ssh\Channel channel is closed too soon, and the client is not acking the session close from the server, which has the consequence of not closing the session on the server side

Mika56 commented 2 years ago

Attaching a logger to connect yields more details:

[debug] Sending Amp\Ssh\Message\ChannelOpen packet
[debug] Receive Amp\Ssh\Message\ChannelOpenConfirmation packet
[debug] Sending Amp\Ssh\Message\ChannelRequestExec packet
[debug] Receive Amp\Ssh\Message\ChannelWindowAdjust packet
[debug] Receive Amp\Ssh\Message\ChannelSuccess packet
[debug] Receive Amp\Ssh\Message\ChannelData packet
[debug] Receive Amp\Ssh\Message\ChannelEof packet
[debug] Receive Amp\Ssh\Message\ChannelRequestExitStatus packet
[debug] Receive Amp\Ssh\Message\ChannelClose packet
Session 9 output: Sat 05 Mar 2022 06:01:34 PM CET

[debug] Sending Amp\Ssh\Message\ChannelOpen packet
[debug] Receive Amp\Ssh\Message\ChannelOpenFailure packet
[debug] Sending Amp\Ssh\Message\Disconnect packet
[debug] Shuting down ssh connection
[critical] Error thrown while running command "ssh-session-test -vvv". Message: "Failed to open channel : open failed"

Channel::close is supposed to send a ChannelClose message but when don't see any sent