Timeout running long script using adt-virt-qemu

[Richard Huddie]

When using adt-virt-qemu to run a script that is larger than ~4215 bytes on a qemu image, the script fails to start execution and a timeout occurs.

This behaviour was observed when attempting to unpack a large list of deb files when running the qemu with ro-apt setup-command. A full test log is shown at [1].

For smaller scripts it works fine. But when the script size is about 4215 bytes or more it will start to timeout and fail. I've tried bulking out a smaller script with comment lines to confirm the problem is related to the size of the script, rather than the commands in the script. I've also checked that the number of bytes returned by the socket.send() at [2] is correct to confirm it is sending the whole script.

Simple steps to reproduce:

$ python -c 'print "echo " * 1000' > /tmp/scr
$ autopkgtest -d --setup-commands /tmp/scr tests/testpkg-simple/ -- qemu /srv/vm/autopkgtest-zesty-amd64.img

[1] http://pastebin.ubuntu.com/23529002/
[2] https://anonscm.debian.org/git/autopkgtest/autopkgtest.git/tree/virt/autopkgtest-virt-qemu#n384

[Richard Huddie (rhuddie)]

Attaching strace log extract from the qemu which shows the logs from the autopkgtest sh process running on ttyS1: http://pastebin.ubuntu.com/23564079/

This shows the commands to apt-get download the list of deb files, followed by command to extract each one. At this point it hangs.

[Richard Huddie (rhuddie)]

Some more investigation shows some slightly different behaviour depending on what format data is sent in. If there is a single line (as above in echo example) of >4096 bytes then it is received as a 4096 chunk using a read() and executed, appending '\n'. The remaining commands from next chunk don't get executed in this case.

If there are commands sent on multiple lines, (e.g. socket.send(b'echo aaa\necho bbb\n')) then each line is received in a separate read() and then executed. Result of each read() is returned in a write(). If the individual lines exceed 4096 then they will also be truncated.

For the case of the test log file the lines are less than 4096, but the last command hangs on write(), which I've not been able to reproduce yet using a dummy script.