Re: iotest 040, 041, intermittent failure in netbsd VM

[John Snow]

On Tue, Jan 18, 2022 at 1:34 PM John Snow <jsnow@redhat.com> wrote:
>
> On Tue, Jan 18, 2022 at 7:13 AM Peter Maydell <peter.maydell@linaro.org> 
> wrote:
> >
> > On Mon, 17 Jan 2022 at 20:35, John Snow <jsnow@redhat.com> wrote:
> > > I do expect this to print more information on failure than it
> > > currently is, though (bug somewhere in machine.py, I think).
> > > Can you please try applying this temporary patch and running `./check
> > > -qcow2 040 041` until you see a breakage and show me the output from
> > > that?
> >
>
> Thanks for playing tele-debug.
>
> > Having fixed my setup to not use an ancient host QEMU, here's
> > the relevant bit of the log:
> >
> >   TEST   iotest-qcow2: 037
> >   TEST   iotest-qcow2: 038 [not run]
> >   TEST   iotest-qcow2: 039 [not run]
> >   TEST   iotest-qcow2: 040 [fail]
> > QEMU          --
> > "/home/qemu/qemu-test.vdrI02/build/tests/qemu-iotests/../../qemu-system-aarch64"
> > -nodefaults -display none -accel qtest -machine virt
> > QEMU_IMG      --
> > "/home/qemu/qemu-test.vdrI02/build/tests/qemu-iotests/../../qemu-img"
> > QEMU_IO       --
> > "/home/qemu/qemu-test.vdrI02/build/tests/qemu-iotests/../../qemu-io"
> > --cache writeback --aio threads -f qcow2
> > QEMU_NBD      --
> > "/home/qemu/qemu-test.vdrI02/build/tests/qemu-iotests/../../qemu-nbd"
> > IMGFMT        -- qcow2
> > IMGPROTO      -- file
> > PLATFORM      -- NetBSD/amd64 localhost 9.2
> > TEST_DIR      -- 
> > /home/qemu/qemu-test.vdrI02/build/tests/qemu-iotests/scratch
> > SOCK_DIR      -- /tmp/tmp1h12r7ev
> > GDB_OPTIONS   --
> > VALGRIND_QEMU --
> > PRINT_QEMU_OUTPUT --
> >
> > --- /home/qemu/qemu-test.vdrI02/src/tests/qemu-iotests/040.out
> > +++ 040.out.bad
> > @@ -1,5 +1,95 @@
> > -.................................................................
> > +.......ERROR:qemu.aqmp.qmp_client.qemu-12407:Failed to establish
> > connection: concurrent.futures._base.CancelledError
> > +ERROR:qemu.machine.machine:Error launching VM
> > +ERROR:qemu.machine.machine:Process was forked, waiting on it
> > +ERROR:qemu.machine.machine:Command:
> > '/home/qemu/qemu-test.vdrI02/build/tests/qemu-iotests/../../qemu-system-aarch64
> > -display none -vga none -chardev
> > socket,id=mon,path=/tmp/tmp1h12r7ev/qemu-12407-monitor.sock -mon
> > chardev=mon,mode=control -qtest
> > unix:path=/tmp/tmp1h12r7ev/qemu-12407-qtest.sock -accel qtest
> > -nodefaults -display none -accel qtest -machine virt -drive
> > if=none,id=drive0,file=/home/qemu/qemu-test.vdrI02/build/tests/qemu-iotests/scratch/test.img,format=qcow2,cache=writeback,aio=threads,node-name=top,backing.node-name=mid,backing.backing.node-name=base
> > -device virtio-scsi -device scsi-hd,id=scsi0,drive=drive0'
>
> > +ERROR:qemu.machine.machine:Output: "qemu-system-aarch64: -chardev
> > socket,id=mon,path=/tmp/tmp1h12r7ev/qemu-12407-monitor.sock: Failed to
> > connect to '/tmp/tmp1h12r7ev/qemu-12407-monitor.sock': No such file or
> > directory\n"
>
> ... Oh. That's unpleasant. My guess is that we aren't listening on the
> socket before the QEMU process gets far enough to want to connect to
> it. The change to an asynchronous backend must have jostled the
> timing.
>
> > +ERROR:qemu.machine.machine:exitcode: 1
>
> And, oh: The VM launching library only chirps about *negative* error
> codes. That's why it wasn't printing anything more useful. I suppose
> the thinking was that we use the VM launch utility to knowingly launch
> bad command lines, so we only wanted to see failure notifications on
> -errno style codes, but that obviously makes debugging unintentional
> failures a lot more awful. I'll try to improve the usability and
> legibility of the errors here.
>
> Thanks,
> --js

I've published '[PATCH v2 0/5] Python: minor fixes' and pushed to
jsnow/python. Test it if you want; otherwise I'll wait for
reviews/acks and send a PR like normal. CI is still running on the
final push, but early smoke tests looked good.

(Patch 1 fixes compatibility with QEMU 2.11, patch 3 adds better
diagnostic info to failures, patch 5 should ultimately fix the root
cause of the race condition.)

Thanks,
--js