Re: iotest40 problem

[Li Zhang <lizhang@suse.de>]

Update what I observed.

It seems that aqmp is not stable when running test cases.
So I revert the patches as the following, iotest40/41 test cases work well.

commit 76cd358671e6b8e7c435ec65b1c44200254514a9

Author: John Snow <jsnow@redhat.com>

Date:   Tue Oct 26 13:56:12 2021 -0400



     python, iotests: replace qmp with aqmp



     Swap out the synchronous QEMUMonitorProtocol from qemu.qmp with the 
sync

     wrapper from qemu.aqmp instead.



     Add an escape hatch in the form of the environment variable

     QEMU_PYTHON_LEGACY_QMP which allows you to cajole QEMUMachine into 
using

     the old implementation, proving that both implementations work

     concurrently.



     Signed-off-by: John Snow <jsnow@redhat.com>

     Reviewed-by: Kevin Wolf <kwolf@redhat.com>

     Reviewed-by: Hanna Reitz <hreitz@redhat.com>

     Message-id: 20211026175612.4127598-9-jsnow@redhat.com

     Signed-off-by: John Snow <jsnow@redhat.com>


commit 1611e6cf4e7163f6102b37010a8b7e7120f468b5

Author: John Snow <jsnow@redhat.com>

Date:   Thu Nov 18 15:46:18 2021 -0500



     python/machine: handle "fast" QEMU terminations



     In the case that the QEMU process actually launches -- but then dies so

     quickly that we can't establish a QMP connection to it -- QEMUMachine

     currently calls _post_shutdown() assuming that it never launched the VM

     process.



     This isn't true, though: it "merely" may have failed to establish a QMP

     connection and the process is in the middle of its own exit path.



     If we don't wait for the subprocess, the caller may get a bogus `None`

     return for .exitcode(). This behavior was observed from

     device-crash-test; after the switch to Async QMP, the timings were

     changed such that it was now seemingly possible to witness the failure

     of "vm.launch()" *prior* to the exitcode becoming available.



     The semantic of the `_launched` property is changed in this

     patch. Instead of representing the condition "launch() executed

     successfully", it will now represent "has forked a child process

     successfully". This way, wait() when called in the exit path won't

     become a no-op.



     Signed-off-by: John Snow <jsnow@redhat.com>

     Reviewed-by: Willian Rampazzo <willianr@redhat.com>

     Message-id: 20211118204620.1897674-6-jsnow@redhat.com

     Signed-off-by: John Snow <jsnow@redhat.com>





On 3/25/22 11:17, Li Zhang wrote:
> Hi,
> 
> I backport some iotests patches to the tree and change timeout.
> It doesn't work.
> 
> Sometimes, iotest41 also reports the errors.
> [ 1347s] 
> +======================================================================
> [ 1347s] +ERROR: test_top_node_in_wrong_chain (__main__.TestSingleDrive)
> [ 1347s] 
> +----------------------------------------------------------------------
> [ 1347s] +Traceback (most recent call last):
> [ 1347s] +  File 
> "/home/abuild/rpmbuild/BUILD/qemu-6.2.0/python/qemu/machine/machine.py", 
> line 399, in launch
> [ 1347s] +    self._launch()
> [ 1347s] +  File 
> "/home/abuild/rpmbuild/BUILD/qemu-6.2.0/python/qemu/machine/machine.py", 
> line 434, in _launch
> [ 1347s] +    self._post_launch()
> [ 1347s] +  File 
> "/home/abuild/rpmbuild/BUILD/qemu-6.2.0/python/qemu/machine/qtest.py", 
> line 147, in _post_launch
> [ 1347s] +    super()._post_launch()
> [ 1347s] +  File 
> "/home/abuild/rpmbuild/BUILD/qemu-6.2.0/python/qemu/machine/machine.py", 
> line 340, in _post_launch
> [ 1347s] +    self._qmp.accept(self._qmp_timer)
> [ 1347s] +  File 
> "/home/abuild/rpmbuild/BUILD/qemu-6.2.0/python/qemu/aqmp/legacy.py", 
> line 69, in accept
> [ 1347s] +    timeout
> [ 1347s] +  File 
> "/home/abuild/rpmbuild/BUILD/qemu-6.2.0/python/qemu/aqmp/legacy.py", 
> line 42, in _sync
> [ 1347s] +    asyncio.wait_for(future, timeout=timeout)
> [ 1347s] +  File "/usr/lib64/python3.6/asyncio/base_events.py", line 
> 488, in run_until_complete
> [ 1347s] +    return future.result()
> [ 1347s] +  File "/usr/lib64/python3.6/asyncio/tasks.py", line 362, in 
> wait_for
> [ 1347s] +    raise futures.TimeoutError()
> [ 1347s] +concurrent.futures._base.TimeoutError
> 
> 
> I can see other errors like this, it's the problem of the socket.
> 
> [ 1535s] socket_accept failed: Resource temporarily unavailable
> [ 1535s] **
> [ 1535s] 
> ERROR:../tests/qtest/libqtest.c:321:qtest_init_without_qmp_handshake: 
> assertion failed: (s->fd >= 0 && s->qmp_fd >= 0)
> 
> 
> The script is running the command as this:
> /usr/bin/make -O -j4 check-block V=1
> 
> I can see the errors on ppc, arm or x86.
> But I couldn't reproduce it when I run it manually.
> 
> It will be appreciated if any suggestions. Thanks.
> 
> 
> On 3/24/22 14:47, Li Zhang wrote:
>> Hi,
>>
>> When I run the testsuit on our buidling system, it reports a timeout 
>> sometimes not always as the following.
>> It couldn't connect qmp socket. Any ideas about this problem?
>>
>>
>> [ 1989s] --- 
>> /home/abuild/rpmbuild/BUILD/qemu-6.2.0/tests/qemu-iotests/040.out
>> [ 1989s] +++ 040.out.bad
>> [ 1989s] @@ -1,5 +1,55 @@
>> [ 1989s] 
>> -.................................................................
>> [ 1989s] +....ERROR:qemu.aqmp.qmp_client.qemu-6471:Failed to establish 
>> connection: asyncio.exceptions.CancelledError
>> [ 1989s] 
>> +E..................................ERROR:qemu.aqmp.qmp_client.qemu-6471:Failed 
>> to establish connection: asyncio.exceptions.CancelledError
>> [ 1989s] +E.........................
>> [ 1989s] 
>> +======================================================================
>> [ 1989s] +ERROR: test_commit_node (__main__.TestActiveZeroLengthImage)
>> [ 1989s] 
>> +----------------------------------------------------------------------
>> [ 1989s] +Traceback (most recent call last):
>> [ 1989s] +  File 
>> "/home/abuild/rpmbuild/BUILD/qemu-6.2.0/tests/qemu-iotests/040", line 
>> 94, in setUp
>> [ 1989s] +    self.vm.launch()
>> [ 1989s] +  File 
>> "/home/abuild/rpmbuild/BUILD/qemu-6.2.0/python/qemu/machine/machine.py", 
>> line 399, in launch
>> [ 1989s] +    self._launch()
>> [ 1989s] +  File 
>> "/home/abuild/rpmbuild/BUILD/qemu-6.2.0/python/qemu/machine/machine.py", 
>> line 434, in _launch
>> [ 1989s] +    self._post_launch()
>> [ 1989s] +  File 
>> "/home/abuild/rpmbuild/BUILD/qemu-6.2.0/python/qemu/machine/qtest.py", 
>> line 147, in _post_launch
>> [ 1989s] +    super()._post_launch()
>> [ 1989s] +  File 
>> "/home/abuild/rpmbuild/BUILD/qemu-6.2.0/python/qemu/machine/machine.py", 
>> line 340, in _post_launch
>> [ 1989s] +    self._qmp.accept(self._qmp_timer)
>> [ 1989s] +  File 
>> "/home/abuild/rpmbuild/BUILD/qemu-6.2.0/python/qemu/aqmp/legacy.py", 
>> line 67, in accept
>> [ 1989s] +    self._sync(
>> [ 1989s] +  File 
>> "/home/abuild/rpmbuild/BUILD/qemu-6.2.0/python/qemu/aqmp/legacy.py", 
>> line 41, in _sync
>> [ 1989s] +    return self._aloop.run_until_complete(
>> [ 1989s] +  File "/usr/lib64/python3.8/asyncio/base_events.py", line 
>> 616, in run_until_complete
>> [ 1989s] +    return future.result()
>> [ 1989s] +  File "/usr/lib64/python3.8/asyncio/tasks.py", line 501, in 
>> wait_for
>> [ 1989s] +    raise exceptions.TimeoutError()
>> [ 1989s] +asyncio.exceptions.TimeoutError
>>
> 
>