Race between command launch and tty initialization

[jerome-pouiller]

My scenario is this one:

import paramiko
device = paramiko.client.SSHClient()
device.connect(remotehost, username="root")
chan = device.get_transport().open_session()
chan.get_pty()
chan.exec_command("sleep 20")
time.sleep(0.5)
chan.send(b'\x03')
chan.recv_exit_status()

recv_exit_status() return immediately. However, if I remove time.sleep(0.5), recv_exit_status() return after 20sec.

Note that if I replace sleep by cat, cat receive the character \x03 instead of receiving the signal interrupt.

There is a race somewhere, but I can't say if it is in paramiko or in the remote shell.

[radssh]

I tried to reproduce this with both paramiko 2.4.1 under python2.7 and paramiko. 2.7.1 under python 3.7, and could not, even with no time.sleep() call. You may want to setup logging to stderr at the start of your test program, to see if the order of events traced might help track down the difference in behavior.

I added:

import logging
logging.basicConfig(level=logging.DEBUG, stream=sys.stderr)

before any paramiko calls, and added a log message just prior to sending the b'\x03', and my logging consistently had this sequence of messages:

DEBUG:paramiko.transport:userauth is OK
INFO:paramiko.transport:Authentication (publickey) successful!
DEBUG:paramiko.transport:[chan 0] Max packet in: 32768 bytes
DEBUG:paramiko.transport:Received global request "hostkeys-00@openssh.com"
DEBUG:paramiko.transport:Rejecting "hostkeys-00@openssh.com" global request from server.
DEBUG:paramiko.transport:Debug msg: Ignored authorized keys: bad ownership or modes for file /var/home/paul/.ssh/authorized_keys
DEBUG:paramiko.transport:Debug msg: cert: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
DEBUG:paramiko.transport:[chan 0] Max packet out: 32768 bytes
DEBUG:paramiko.transport:Secsh channel 0 opened.
DEBUG:paramiko.transport:[chan 0] Sesch channel 0 request ok
DEBUG:paramiko.transport:[chan 0] Sesch channel 0 request ok
INFO:root:Sending Ctrl-C...
DEBUG:paramiko.transport:[chan 0] Unhandled channel request "exit-signal"
DEBUG:paramiko.transport:[chan 0] EOF received (0)
DEBUG:paramiko.transport:[chan 0] EOF sent (0)

I'm suspecting on your failures, the send is occurring before the session channel is fully opened (or acknowledged), as part of that is managed by the Transport thread.

[jerome-pouiller]

Here is the debug output after removing time.sleep(.5) and adding logging.info("Sending Ctrl+C"):

DEBUG:paramiko.transport:userauth is OK
INFO:paramiko.transport:Authentication (publickey) successful!
DEBUG:paramiko.transport:[chan 0] Max packet in: 32768 bytes
DEBUG:paramiko.transport:Received global request "hostkeys-00@openssh.com"
DEBUG:paramiko.transport:Rejecting "hostkeys-00@openssh.com" global request from server.
DEBUG:paramiko.transport:Debug msg: b'/root/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding'
DEBUG:paramiko.transport:[chan 0] Max packet out: 32768 bytes
DEBUG:paramiko.transport:Secsh channel 0 opened.
DEBUG:paramiko.transport:[chan 0] Sesch channel 0 request ok
DEBUG:paramiko.transport:[chan 0] Sesch channel 0 request ok
INFO:root:Sending Ctrl+C

I have to add that the remote target is a Raspberry. It is probably slow to process the data. And indeed, if I connect to a more powerful host, the problem does not appears.

Also note that I use paramiko 2.7.1 with python 3 on Debian 11 (Bullseye).

[radssh]

That looks okay from the client/paramiko side - I did just try the test program against my RaspberryPi (3B+) and did not have the timing issue that you get.

[jerome-pouiller]

I tried to run strace on the script. Since the data is encrypted, the result is a bit difficult to interpret, but indeed, it seems the data are sent in correct order:

[lsof shows that fd 15 is our socket]
poll([{fd=15, events=POLLOUT}], 1, 100) = 1 ([{fd=15, revents=POLLOUT}])
[A packet of 80 bytes is probably the start of command sleep 20]
sendto(15, "H\273\354\230:#Akiu\2I\207&YO\277\21\211i1\220,=\276E/\251F\346\23!"..., 80, 0, NULL, 0) = 80
futex(0x2d92540, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY) = 0
poll([{fd=15, events=POLLOUT}], 1, 100) = 1 ([{fd=15, revents=POLLOUT}])
[A packet of 64 bytes is probably the string \x03]
sendto(15, "\251\236I4\256}\223Oi\240\314\273,\336\r\6x\321763\376\17\231\231\221B\342\262\363\272&"..., 64, 0, NULL, 0) = 64

So the problem would be on the remote side.