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