Racy qemu pexpect test

[lool]

We've recently added a test to verify that a password change was properly enforced, along with a qemu test.

However it failed in a recent CI run:

/usr/lib/python3/dist-packages/pexpect/expect.py:144: TIMEOUT
---------------------------- Captured stdout setup -----------------------------
Formatting '/tmp/tmpjbzf0_dl/disk1.qcow', fmt=qcow size=4294967296 backing_file=/__w/qcom-deb-images/qcom-deb-images/disk-ufs.img backing_fmt=raw
=========================== short test summary info ============================
FAILED ci/qemu_test.py::test_password_reset_required - pexpect.exceptions.TIMEOUT: Timeout exceeded.
<pexpect.pty_spawn.spawn object at 0xf0f8f8d58c20>
command: /usr/bin/qemu-system-aarch64
args: ['/usr/bin/qemu-system-aarch64', '-cpu', 'cortex-a57', '-m', '2048', '-M', 'virt', '-drive', 'if=none,file=/tmp/tmpjbzf0_dl/disk1.qcow,format=qcow,id=disk1', '-device', 'virtio-scsi-pci,id=scsi1', '-device', 'scsi-hd,bus=scsi1.0,drive=disk1,physical_block_size=4096,logical_block_size=4096', '-nographic', '-bios', '/usr/share/AAVMF/AAVMF_CODE.fd']
buffer (last 100 chars): b'plicable law.\r\r\n'
before (last 100 chars): b'\nDebian GNU/Linux comes with ABSOLUTELY NO WARRANTY, to the extent\r\r\npermitted by applicable law.\r\r\n'
after: <class 'pexpect.exceptions.TIMEOUT'>

the contents of buffer and before suggest the prompt is reached, but it's probably garbled by some other boot message, and pexpect doesn't match and times out.

We need some out of band signaling that boot is complete. Since we have adbd, we could use this.

I've found that adding -netdev user,id=net0,hostfwd=tcp::5555-:5555 -device virtio-net-pci,netdev=net0 to qemu-system allowed the instance to be visible in adb devices, and then I could adb shell into it.

[basak-qcom]

I wonder if we can get the actual output logged and presented as an artifact or something, if not just directly logged. That would help this time as well as others to fix the actual race.

Would you have any objection if I could arrange for the output to actually be dumped to stdout on failure?

[lool]

The mini snippet from the pexpect failure was already enough for me to get a serious hint at the problem, but I wouldn't mind if we collected the whole console output like LAVA does; it might be hard to exploit reliably, but it's good for humans for debugging or sanity checking

[basak-qcom]

Thanks! I've prepared this in #169.

[basak-qcom]

The mini snippet from the pexpect failure was already enough for me to get a serious hint at the problem...

What do you think this hints? It looks to me that perhaps it just happened to time out after /etc/issue but before the login prompt?

[or rather, looking again, after login and /etc/motd but before the shell prompt]

[lool]

I'm not experienced with pexpect, but for me the suspicious thing is:

buffer (last 100 chars): b'plicable law.\r\r\n'

as this isn't lining up with any actual output lines, so I take it as "something produced new lines on the console while this was being printed"; I suspect a similar thing is happening with the debian login and prevented pexpect from matching.

Today's daily run passed testing, so this will be tricky to repro :-/

[basak-qcom]

Ah. I think that might just be because of:

>>> len("debian@debian:~$")
16
>>> len('plicable law.\r\r\n')
16

The "before" string output seems complete, so perhaps buffer is simply limited to the expected string length.

[lool]

https://github.com/qualcomm-linux/qcom-deb-images/actions/runs/18476464034/job/52642905706 shows that the debug output works, but I think it's an unrelated problem of missing configs with the defconfig used for mainline kernels