Re: [OE-core] [PATCH v2 2/8] oeqa ssh.py: fix hangs in run()

[Mikko Rapeli <mikko.rapeli@linaro.org>]

Hi,

On Thu, Feb 09, 2023 at 12:42:09PM +0100, Alexander Kanavin wrote:
> On Thu, 9 Feb 2023 at 12:12, Mikko Rapeli <mikko.rapeli@linaro.org> wrote:
> > select() returns with any data, even single character. Fancy readers
> > will read larger chunks but will read more data than is available and thus
> > block for ever. Plain read() will read the data which is available from
> > select() and thus really small amounts like single characters if that's
> > available over the socket. This is visible in the partial read output of
> > do_testimage() task output log which becomes quite unreadable without change.
> 
> Yes, but this does not explain why single characters happen to begin
> with - RP offered a hypothesis, but the problem is that data arrives
> that way, not the tight-loop manner in which we're reading it.

Without the sleep(0.2) with ssh, the do_testimage task output can be like this (which
isn't too bad, just annoying):

DEBUG: [Running]$ ssh -l root -o ServerAliveCountMax=2 -o ServerAliveInterval=30 -o UserKnownHostsFile=/dev/null -o StrictHostKeyChecking=no -o LogLevel=ERROR -p 2222 127.0.0.1 export PATH=/usr/sbin:/sbin:/usr/bin:/bin; cat /etc/controllerimage
DEBUG: Waiting for process output: time: 1675942983.6053402, endtime: 1675943283.6033137
DEBUG: Partial data from SSH call:
cat: 
DEBUG: Waiting for process output: time: 1675942986.2085373, endtime: 1675943286.208536
DEBUG: Partial data from SSH call:
/etc/controllerimage
DEBUG: Waiting for process output: time: 1675942986.2111514, endtime: 1675943286.2111504
DEBUG: Partial data from SSH call:
: No such file or directory
DEBUG: Waiting for process output: time: 1675942986.2140906, endtime: 1675943286.2140894
DEBUG: Partial data from SSH call:


DEBUG: Waiting for process output: time: 1675942986.216261, endtime: 1675943286.21626
DEBUG: [Command returned '1' after 2.64 seconds]

I think qemu is just slower than what anyone expects, including the ssh
protocol which does some buffer but then gives up. It may also be the
kernel and image running under qemu which busy starting up, e.g.
generating entropy or keys.

With the sleep(0.2) output is:

DEBUG: [Running]$ ssh -l root -o ServerAliveCountMax=2 -o ServerAliveInterval=30 -o UserKnownHostsFile=/dev/null -o StrictHostKeyChecking=no -o LogLevel=ERROR -p 2222 127.0.0.1 export PATH=/usr/sbin:/sbin:/usr/bin:/bin; cat /etc/controllerimage
DEBUG: Waiting for process output: time: 1675945065.6815689, endtime: 1675945365.6790204
DEBUG: Partial data from SSH call:
cat: /etc/controllerimage: No such file or directory

DEBUG: Waiting for process output: time: 1675945068.308055, endtime: 1675945368.3080513
DEBUG: [Command returned '1' after 2.83 seconds]
DEBUG: Command: cat /etc/controllerimage
Status: 1 Output:
cat: /etc/controllerimage: No such file or directory

NOTE:  ... ok

Similar thing happens then over serial console which is even slower. I
know debugging the data read and written to serial are not wanted but I
had the changes in place and saw bootloader and kernel messages being
read initally one character at a time and later on 5-10 characters at a time
which made debugging problems really annoying. The small sleep does
improve things, doesn't solve everything but also doesn't really harm.

No data is lost and less time is used looping around the file
descriptor.

Cheers,

-Mikko