tests: n810 arm failing

tests: n810 arm failing

[Philippe Mathieu-Daudé]

Hi,

The n810 arm test failed on latest master:

https://gitlab.com/qemu-project/qemu/-/jobs/1045015424/artifacts/browse/build/tests/results/latest/test-results/26-tests_acceptance_machine_arm_n8x0.py_N8x0Machine.test_n810/

16:02:18 DEBUG| PARAMS (key=arch, path=*, default=arm) => 'arm'
16:02:18 DEBUG| PARAMS (key=machine, path=*, default=n810) => 'n810'
16:02:18 DEBUG| PARAMS (key=qemu_bin, path=*, default=./qemu-system-arm)
=> './qemu-system-arm'
16:02:18 DEBUG| VM launch command: './qemu-system-arm -display none -vga
none -chardev
socket,id=mon,path=/var/tmp/avo_qemu_sock_nv8s4w64/qemu-850-monitor.sock
-mon chardev=mon,mode=control -machine n810 -serial null -chardev
socket,id=console,path=/var/tmp/avo_qemu_sock_nv8s4w64/qemu-850-console.sock,server=on,wait=off
-serial chardev:console -kernel
/builds/qemu-project/qemu/avocado-cache/by_location/07af9de13713c2905e8c6a88d6600eb1bc885c5c/meego-arm-n8x0-1.0.80.20100712.1431-vmlinuz-2.6.35~rc4-129.1-n8x0
-append printk.time=0 console=ttyS1'
16:02:21 DEBUG| >>> {'execute': 'qmp_capabilities'}
16:02:21 DEBUG| <<< {'return': {}}
16:03:49 ERROR|
16:03:49 ERROR| Reproduced traceback from:
tests/venv/lib/python3.7/site-packages/avocado/core/test.py:767
16:03:49 ERROR| Traceback (most recent call last):
16:03:49 ERROR|   File "tests/acceptance/machine_arm_n8x0.py", line 49,
in test_n810
16:03:49 ERROR|     self.__do_test_n8x0()
16:03:49 ERROR|   File "tests/acceptance/machine_arm_n8x0.py", line 33,
in __do_test_n8x0
16:03:49 ERROR|     wait_for_console_pattern(self, 'TSC2005 driver
initializing')
16:03:49 ERROR|   File "tests/acceptance/avocado_qemu/__init__.py", line
140, in wait_for_console_pattern
16:03:49 ERROR|     _console_interaction(test, success_message,
failure_message, None, vm=vm)
16:03:49 ERROR|   File "tests/acceptance/avocado_qemu/__init__.py", line
92, in _console_interaction
16:03:49 ERROR|     msg = console.readline().strip()
16:03:49 ERROR|   File "/usr/lib/python3.7/socket.py", line 589, in readinto
16:03:49 ERROR|     return self._sock.recv_into(b)
16:03:49 ERROR|   File
"tests/venv/lib/python3.7/site-packages/avocado/plugins/runner.py", line
77, in sigterm_handler
16:03:49 ERROR|     raise RuntimeError("Test interrupted by SIGTERM")
16:03:49 ERROR| RuntimeError: Test interrupted by SIGTERM
16:03:49 ERROR|
16:03:49 DEBUG| Local variables:
16:03:49 DEBUG|  -> self <class 'machine_arm_n8x0.N8x0Machine'>:
26-tests/acceptance/machine_arm_n8x0.py:N8x0Machine.test_n810
16:03:49 DEBUG| >>> {'execute': 'quit'}
16:03:49 DEBUG| <<< {'return': {}}
16:03:49 DEBUG| DATA (filename=output.expected) => NOT FOUND (data
sources: variant, test, file)
16:03:49 DEBUG| DATA (filename=stdout.expected) => NOT FOUND (data
sources: variant, test, file)
16:03:49 DEBUG| DATA (filename=stderr.expected) => NOT FOUND (data
sources: variant, test, file)
16:03:49 ERROR| Traceback (most recent call last):
16:03:49 ERROR|   File
"tests/venv/lib/python3.7/site-packages/avocado/core/test.py", line 856,
in _run_avocado
    raise test_exception
16:03:49 ERROR|   File
"tests/venv/lib/python3.7/site-packages/avocado/core/test.py", line 762,
in _run_avocado
    testMethod()
16:03:49 ERROR|   File "tests/acceptance/machine_arm_n8x0.py", line 49,
in test_n810
    self.__do_test_n8x0()
16:03:49 ERROR|   File "tests/acceptance/machine_arm_n8x0.py", line 33,
in __do_test_n8x0
    wait_for_console_pattern(self, 'TSC2005 driver initializing')
16:03:49 ERROR|   File "tests/acceptance/avocado_qemu/__init__.py", line
140, in wait_for_console_pattern
    _console_interaction(test, success_message, failure_message, None,
vm=vm)
16:03:49 ERROR|   File "tests/acceptance/avocado_qemu/__init__.py", line
92, in _console_interaction
    msg = console.readline().strip()
16:03:49 ERROR|   File "/usr/lib/python3.7/socket.py", line 589, in readinto
    return self._sock.recv_into(b)
16:03:49 ERROR|   File
"tests/venv/lib/python3.7/site-packages/avocado/plugins/runner.py", line
77, in sigterm_handler
    raise RuntimeError("Test interrupted by SIGTERM")
16:03:49 ERROR| RuntimeError: Test interrupted by SIGTERM
16:03:49 ERROR| ERROR
26-tests/acceptance/machine_arm_n8x0.py:N8x0Machine.test_n810 ->
RuntimeError: Test interrupted by SIGTERM
16:03:49 INFO |
Runner error occurred: Timeout reached
Original status: ERROR
{'name':
'26-tests/acceptance/machine_arm_n8x0.py:N8x0Machine.test_n810',
'logdir':
'26-tests_acceptance_machine_arm_n8x0.py_N8x0Machine.test_n810',
'logfile':
'26-tests_acceptance_machine_arm_n8x0.py_N8x0Machine.test_n810/debug.log',
'status': 'ERROR', 'running': False, 'paused': False, 'time_start':
1613923338.892834, 'time_elapsed': 90.31178283691406, 'time_end':
1613923429.2046168, 'fail_reason': 'Test interrupted by SIGTERM',
'fail_class': 'RuntimeError', 'traceback': 'Traceback (most recent call
last):\n  File
"tests/venv/lib/python3.7/site-packages/avocado/core/test.py", line 856,
in _run_avocado\n    raise test_exception\n  File
"tests/venv/lib/python3.7/site-packages/avocado/core/test.py", line 762,
in _run_avocado\n    testMethod()\n  File
"tests/acceptance/machine_arm_n8x0.py", line 49, in test_n810\n
self.__do_test_n8x0()\n  File "tests/acceptance/machine_arm_n8x0.py",
line 33, in __do_test_n8x0\n    wait_for_console_pattern(self, \'TSC2005
driver initializing\')\n  File
"tests/acceptance/avocado_qemu/__init__.py", line 140, in
wait_for_console_pattern\n    _console_interaction(test,
success_message, failure_message, None, vm=vm)\n  File
"tests/acceptance/avocado_qemu/__init__.py", line 92, in
_console_interaction\n    msg = console.readline().strip()\n  File
"/usr/lib/python3.7/socket.py", line 589, in readinto\n    return
self._sock.recv_into(b)\n  File
"tests/venv/lib/python3.7/site-packages/avocado/plugins/runner.py", line
77, in sigterm_handler\n    raise RuntimeError("Test interrupted by
SIGTERM")\nRuntimeError: Test interrupted by SIGTERM\n', 'timeout': 90,
'whiteboard': '', 'phase': 'FINISHED', 'class_name': 'N8x0Machine',
'job_logdir': 'tests/results/job-2021-02-21T16.00-e662b93',
'job_unique_id': 'e662b936b3c04ad082359ee970534ac7ae7ec3bc', 'params': []}

Re: tests: n810 arm failing

[Peter Maydell]

On Sun, 21 Feb 2021 at 17:26, Philippe Mathieu-Daudé <f4bug@amsat.org> wrote:
>
> Hi,
>
> The n810 arm test failed on latest master:
>
> https://gitlab.com/qemu-project/qemu/-/jobs/1045015424/artifacts/browse/build/tests/results/latest/test-results/26-tests_acceptance_machine_arm_n8x0.py_N8x0Machine.test_n810/

It passed on the gitlab CI run on the exact same commit hash
as 'staging' before I pushed the merge, though...

-- PMM

Re: tests: n810 arm failing

[Thomas Huth]

On 21/02/2021 20.33, Peter Maydell wrote:
> On Sun, 21 Feb 2021 at 17:26, Philippe Mathieu-Daudé <f4bug@amsat.org> wrote:
>>
>> Hi,
>>
>> The n810 arm test failed on latest master:
>>
>> https://gitlab.com/qemu-project/qemu/-/jobs/1045015424/artifacts/browse/build/tests/results/latest/test-results/26-tests_acceptance_machine_arm_n8x0.py_N8x0Machine.test_n810/
> 
> It passed on the gitlab CI run on the exact same commit hash
> as 'staging' before I pushed the merge, though...

Looking at the following run, it failed with some timeouts as well:

  https://gitlab.com/qemu-project/qemu/-/pipelines/259425956

... but in completely different spots. So maybe it was "just" a global 
slow-down in the CI farm? (Which sounds somewhat worrisome, too ... I hope 
gitlab-CI is not going down the same road as travis-ci.org did during the 
past year)

  Thomas

Re: tests: n810 arm failing

[Philippe Mathieu-Daudé]

On 2/22/21 7:25 AM, Thomas Huth wrote:
> On 21/02/2021 20.33, Peter Maydell wrote:
>> On Sun, 21 Feb 2021 at 17:26, Philippe Mathieu-Daudé <f4bug@amsat.org>
>> wrote:
>>>
>>> Hi,
>>>
>>> The n810 arm test failed on latest master:
>>>
>>> https://gitlab.com/qemu-project/qemu/-/jobs/1045015424/artifacts/browse/build/tests/results/latest/test-results/26-tests_acceptance_machine_arm_n8x0.py_N8x0Machine.test_n810/
>>>
>>
>> It passed on the gitlab CI run on the exact same commit hash
>> as 'staging' before I pushed the merge, though...
> 
> Looking at the following run, it failed with some timeouts as well:
> 
>  https://gitlab.com/qemu-project/qemu/-/pipelines/259425956
> 
> ... but in completely different spots.

This one is "read ASDF from console but some char got eaten
so ASF was displayed and Avocado is reading infinitely for
ASDF".

> So maybe it was "just" a global
> slow-down in the CI farm? (Which sounds somewhat worrisome, too ... I
> hope gitlab-CI is not going down the same road as travis-ci.org did
> during the past year)

The question here is how can we detect the failure cause? Is it the
CI infra or our test?

Currently Avocado only dump log for "FAILed" tests.

I sent a patch to also dump the log for "INTERRUPTed (by timeout)":
https://www.mail-archive.com/qemu-devel@nongnu.org/msg782782.html

Here we got an ERROR result (SIGTERM) so the log is not dumped.

Regards,

Phil.

Re: tests: n810 arm failing

[Philippe Mathieu-Daudé]

On 2/21/21 6:26 PM, Philippe Mathieu-Daudé wrote:
> Hi,
> 
> The n810 arm test failed on latest master:
> 
> https://gitlab.com/qemu-project/qemu/-/jobs/1045015424/artifacts/browse/build/tests/results/latest/test-results/26-tests_acceptance_machine_arm_n8x0.py_N8x0Machine.test_n810/
...
>     raise RuntimeError("Test interrupted by SIGTERM")
> 16:03:49 ERROR| RuntimeError: Test interrupted by SIGTERM
> 16:03:49 ERROR| ERROR
> 26-tests/acceptance/machine_arm_n8x0.py:N8x0Machine.test_n810 ->
> RuntimeError: Test interrupted by SIGTERM
> 16:03:49 INFO |
> Runner error occurred: Timeout reached

What we are missing here is we got a timeout ^
but return an error, so the debug.log is not shown:

> Original status: ERROR

...
> "tests/venv/lib/python3.7/site-packages/avocado/plugins/runner.py", line
> 77, in sigterm_handler\n    raise RuntimeError("Test interrupted by
> SIGTERM")\nRuntimeError: Test interrupted by SIGTERM\n', 'timeout': 90,
> 'whiteboard': '', 'phase': 'FINISHED', 'class_name': 'N8x0Machine',
> 'job_logdir': 'tests/results/job-2021-02-21T16.00-e662b93',
> 'job_unique_id': 'e662b936b3c04ad082359ee970534ac7ae7ec3bc', 'params': []}