Re: tests/avocado/machine_s390_ccw_virtio: Fedora test failing

[Philippe Mathieu-Daudé]

Cc'ing Jan/Cleber/Beraldo.

On 16/11/22 10:43, Thomas Huth wrote:
> On 15/11/2022 12.13, Philippe Mathieu-Daudé wrote:
> > On 15/11/22 12:05, Thomas Huth wrote:
> > > On 15/11/2022 12.03, Philippe Mathieu-Daudé wrote:
> > > > Hi,
> > > >
> > > > As of v7.2.0-rc0 I am getting:
> > > >
> > > >   (101/198) 
> > > > tests/avocado/machine_s390_ccw_virtio.py:S390CCWVirtioMachine.test_s390x_fedora: FAIL (23.51 s)
> > >
> > > Is it 100% reproducible? ... the test is known to be a little bit 
> > > shaky, that's also why it is disabled in the gitlab CI.
> >
> > I am running it on my workstation, not GitLab.
>
> I just double-checked and for me, it's working fine an my laptop, with 
> both, rc0 and rc1.
>
> > 5/5 failures. I'll skip it locally (no need to send a patch) and we can
> > have a look after the release.
>
> If it is a real bug, we should fix it before the release. Could you 
> maybe bisect it, please?
>
> Also, what do you get when dumping the console? I.e.:
>
> ./tests/venv/bin/avocado --show=console run -t arch:s390x \
> tests/avocado/machine_s390_ccw_virtio.py:S390CCWVirtioMachine.test_s390x_fedora

When running with the current (old) Avocado runner I get:

Avocado crashed: TypeError: cannot pickle '_thread.RLock' object
Please include the traceback info and command line used on your bug report
Report bugs visiting https://github.com/avocado-framework/avocado/issues/new

I can use the 'new' runner:

$ TMPDIR=/tmp ./tests/venv/bin/avocado --show=app,console run 
--test-runner=nrunner -t arch:s390x 
tests/avocado/machine_s390_ccw_virtio.py:S390CCWVirtioMachine.test_s390x_fedora
JOB ID     : 2e62ee88c4f04926281f31ab696f4cd4703612f5
JOB LOG    : 
/Users/philmd/avocado/job-results/job-2022-11-16T11.05-2e62ee8/job.log
 (1/1) 
tests/avocado/machine_s390_ccw_virtio.py:S390CCWVirtioMachine.test_s390x_fedora: 
STARTED
 (1/1) 
tests/avocado/machine_s390_ccw_virtio.py:S390CCWVirtioMachine.test_s390x_fedora: 
FAIL (24.63 s)
RESULTS    : PASS 0 | ERROR 0 | FAIL 1 | SKIP 0 | WARN 0 | INTERRUPT 0 | 
CANCEL 0
JOB TIME   : 25.16 s

but I'm almost blind: I don't get any console output. The only useful
info I found is closer to stderr:

$ cat 
/Users/philmd/avocado/job-results/job-2022-11-16T11.05-2e62ee8//test-results/1-tests_avocado_machine_s390_ccw_virtio.py_S390CCWVirtioMachine.test_s390x_fedora/debug.log
11:05:20 INFO | INIT 1-S390CCWVirtioMachine.test_s390x_fedora
11:05:20 DEBUG| PARAMS (key=timeout, path=*, default=120) => 120
11:05:20 DEBUG| Test metadata:
11:05:20 DEBUG|   filename: 
/Users/philmd/source/qemu/build/tests/avocado/machine_s390_ccw_virtio.py
11:05:20 DEBUG|   teststmpdir: /tmp/avocado_zswqnw_l
11:05:20 DEBUG|   workdir: 
/tmp/tmppq8l13fn/test-results/tmp_dir2cjl2nd2/1-S390CCWVirtioMachine.test_s390x_fedora
11:05:20 INFO | START 1-S390CCWVirtioMachine.test_s390x_fedora
11:05:20 DEBUG| DATA (filename=output.expected) => NOT FOUND (data 
sources: variant, test, file)
11:05:20 DEBUG| PARAMS (key=arch, path=*, default=s390x) => 's390x'
11:05:20 DEBUG| PARAMS (key=cpu, path=*, default=None) => None
11:05:20 DEBUG| PARAMS (key=qemu_bin, path=*, 
default=./qemu-system-s390x) => './qemu-system-s390x'
11:05:20 DEBUG| PARAMS (key=machine, path=*, default=s390-ccw-virtio) => 
's390-ccw-virtio'
11:05:22 DEBUG| QEMUMachine "default" created
11:05:22 DEBUG| QEMUMachine "default" temp_dir: 
/tmp/tmppq8l13fn/test-results/tmp_dir2cjl2nd2/1-S390CCWVirtioMachine.test_s390x_fedora/qemu-machine-di5d3r66
11:05:22 DEBUG| QEMUMachine "default" log_dir: 
/tmp/tmppq8l13fn/test-results/1-S390CCWVirtioMachine.test_s390x_fedora
11:05:40 INFO | Test whether QEMU CLI options have been considered
11:05:41 INFO | Test screendump of virtio-gpu device
11:05:44 ERROR|
11:05:44 ERROR| Reproduced traceback from: 
/Users/philmd/source/qemu/build/tests/venv/lib/python3.10/site-packages/avocado/core/test.py:772
11:05:44 ERROR| Traceback (most recent call last):
11:05:44 ERROR|   File 
"/Users/philmd/source/qemu/build/tests/venv/lib/python3.10/site-packages/avocado/core/decorators.py", 
line 90, in wrapper
11:05:44 ERROR|     return function(obj, *args, **kwargs)
11:05:44 ERROR|   File 
"/Users/philmd/source/qemu/build/tests/avocado/machine_s390_ccw_virtio.py", 
line 256, in test_s390x_fedora
11:05:44 ERROR|     self.assertEqual(line, b"The quick fox jumps over a 
lazy dog\n")
11:05:44 ERROR|   File 
"/opt/homebrew/Cellar/python@3.10/3.10.8/Frameworks/Python.framework/Versions/3.10/lib/python3.10/unittest/case.py", 
line 845, in assertEqual
11:05:44 ERROR|     assertion_func(first, second, msg=msg)
11:05:44 ERROR|   File 
"/opt/homebrew/Cellar/python@3.10/3.10.8/Frameworks/Python.framework/Versions/3.10/lib/python3.10/unittest/case.py", 
line 838, in _baseAssertEqual
11:05:44 ERROR|     raise self.failureException(msg)
11:05:44 ERROR| AssertionError: 
b'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\[979 chars]\x00' != b'The 
quick fox jumps over a lazy dog\n'
11:05:44 ERROR|
11:05:44 DEBUG| Local variables:
11:05:44 DEBUG|  -> obj <class 
'machine_s390_ccw_virtio.S390CCWVirtioMachine'>: 
1-S390CCWVirtioMachine.test_s390x_fedora
11:05:44 DEBUG|  -> args <class 'tuple'>: ()
11:05:44 DEBUG|  -> kwargs <class 'dict'>: {}
11:05:44 DEBUG|  -> condition <class 'NoneType'>: None
11:05:44 DEBUG|  -> function <class 'function'>: <function 
S390CCWVirtioMachine.test_s390x_fedora at 0x1030d1990>
11:05:44 DEBUG|  -> message <class 'str'>: Running on GitLab
11:05:44 DEBUG|  -> negate <class 'bool'>: False
11:05:44 ERROR| FAIL 1-S390CCWVirtioMachine.test_s390x_fedora -> 
AssertionError: b'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\[979 
chars]\x00' != b'The quick fox jumps over a lazy dog\n'
11:05:44 INFO |

IIUC Cleber should post a series soon upgrading the QEMU Avocado
framework to use the 'new' runner.