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

[Peter Maydell <peter.maydell@linaro.org>]

On Mon, 17 Jan 2022 at 20:35, John Snow <jsnow@redhat.com> wrote:
>
> On Mon, Jan 17, 2022 at 5:05 AM Kevin Wolf <kwolf@redhat.com> wrote:
> >
> > Am 10.01.2022 um 16:55 hat Peter Maydell geschrieben:
> > > Just saw this failure of iotests in a netbsd VM

> This trace says that we timed out while awaiting a connection from
> QEMU during the VM launch phase. i.e. python/qemu/qmp/machine.py line
> 340:
>
>     def _post_launch(self) -> None:
>         if self._qmp_connection:
>             self._qmp.accept(self._qmp_timer)  <-- we timed out here.
>
> (Note to self: make this traceback look more obvious as to what was
> canceled and why. I think I can improve readability here a bit ...)
>
> Sky's the limit on why QEMU never connected to the socket, but:
>
> > > --- /home/qemu/qemu-test.MPWquy/src/tests/qemu-iotests/040.out
> > > fcntl(): Invalid argument
>
> That looks fairly suspicious, and I don't know which process was
> responsible for printing it (or when, relative to the other outputs).
> I assume you don't see any such output like this on a good run.

The NetBSD VM prints those fcntl messages all over the place.
I think something in the build system (make? ninja? who knows)
triggers them.

> > > -OK
> > > +FAILED (errors=1)
> > >   TEST   iotest-qcow2: 041 [fail]
> > > QEMU          --
> > > "/home/qemu/qemu-test.MPWquy/build/tests/qemu-iotests/../../qemu-system-aarch64"
> > > -nodefaults -display none -accel qtest -machine virt
> > > QEMU_IMG      --
> > > "/home/qemu/qemu-test.MPWquy/build/tests/qemu-iotests/../../qemu-img"
> > > QEMU_IO       --
> > > "/home/qemu/qemu-test.MPWquy/build/tests/qemu-iotests/../../qemu-io"
> > > --cache writeback --aio threads -f qcow2
> > > QEMU_NBD      --
> > > "/home/qemu/qemu-test.MPWquy/build/tests/qemu-iotests/../../qemu-nbd"
> > > IMGFMT        -- qcow2
> > > IMGPROTO      -- file
> > > PLATFORM      -- NetBSD/amd64 localhost 9.2
> > > TEST_DIR      -- /home/qemu/qemu-test.MPWquy/build/tests/qemu-iotests/scratch
> > > SOCK_DIR      -- /tmp/tmpuniuicbi
> > > GDB_OPTIONS   --
> > > VALGRIND_QEMU --
> > > PRINT_QEMU_OUTPUT --
> > >
> > > --- /home/qemu/qemu-test.MPWquy/src/tests/qemu-iotests/041.out
> > > +++ 041.out.bad
> > > @@ -1,5 +1,32 @@
> > > -...........................................................................................................
> > > +..........................................ERROR:qemu.aqmp.qmp_client.qemu-15252:Failed
> > > to establish connection: concurrent.futures._base.CancelledError
> > > +E................................................................
> > > +======================================================================
> > > +ERROR: test_small_buffer (__main__.TestSingleBlockdev)
> > > +----------------------------------------------------------------------
> > > +Traceback (most recent call last):
> > > +  File "/home/qemu/qemu-test.MPWquy/src/tests/qemu-iotests/041", line
> > > 233, in setUp
> > > +    TestSingleDrive.setUp(self)
> > > +  File "/home/qemu/qemu-test.MPWquy/src/tests/qemu-iotests/041", line
> > > 54, in setUp
> > > +    self.vm.launch()
> > > +  File "/home/qemu/qemu-test.MPWquy/src/python/qemu/machine/machine.py",
> > > line 399, in launch
> > > +    self._launch()
> > > +  File "/home/qemu/qemu-test.MPWquy/src/python/qemu/machine/machine.py",
> > > line 434, in _launch
> > > +    self._post_launch()
> > > +  File "/home/qemu/qemu-test.MPWquy/src/python/qemu/machine/qtest.py",
> > > line 147, in _post_launch
> > > +    super()._post_launch()
> > > +  File "/home/qemu/qemu-test.MPWquy/src/python/qemu/machine/machine.py",
> > > line 340, in _post_launch
> > > +    self._qmp.accept(self._qmp_timer)
> > > +  File "/home/qemu/qemu-test.MPWquy/src/python/qemu/aqmp/legacy.py",
> > > line 69, in accept
> > > +    timeout
> > > +  File "/home/qemu/qemu-test.MPWquy/src/python/qemu/aqmp/legacy.py",
> > > line 42, in _sync
> > > +    asyncio.wait_for(future, timeout=timeout)
> > > +  File "/usr/pkg/lib/python3.7/asyncio/base_events.py", line 587, in
> > > run_until_complete
> > > +    return future.result()
> > > +  File "/usr/pkg/lib/python3.7/asyncio/tasks.py", line 449, in wait_for
> > > +    raise futures.TimeoutError()
> > > +concurrent.futures._base.TimeoutError
>
> Same problem here, except I don't see any output from QEMU to blame.
> As far as the Python code knows, it just never got a connection on the
> socket, so it timed out and died.

I think the NetBSD VM does for some reason get a bit slow to do
stuff. I've never worked out why. In the past we've had to bump
up various overoptimistic timeouts to help it out.

> 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?
>
> diff --git a/python/qemu/machine/machine.py b/python/qemu/machine/machine.py
> index 67ab06ca2b..ca49e6fcd2 100644
> --- a/python/qemu/machine/machine.py
> +++ b/python/qemu/machine/machine.py
> @@ -403,16 +403,19 @@ def launch(self) -> None:
>              # Assume the VM didn't launch or is exiting.
>              # If we don't wait for the process, exitcode() may still be
>              # 'None' by the time control is ceded back to the caller.
> +            LOG.error('Error launching VM')
>              if self._launched:
> +                LOG.error('Process was forked, waiting on it')
>                  self.wait()
>              else:
> +                LOG.error('Process was not forked, just cleaning up')
>                  self._post_shutdown()
>
> -            LOG.debug('Error launching VM')
>              if self._qemu_full_args:
> -                LOG.debug('Command: %r', ' '.join(self._qemu_full_args))
> +                LOG.error('Command: %r', ' '.join(self._qemu_full_args))
>              if self._iolog:
> -                LOG.debug('Output: %r', self._iolog)
> +                LOG.error('Output: %r', self._iolog)
> +            LOG.error('exitcode: %s', str(self.exitcode()))
>              raise
>
>      def _launch(self) -> None:

Yeah, I should be able to test this.

-- PMM