Re: QEMU CI failed due to canceled download

[Wainer dos Santos Moschetta]

Hi,

On 2/25/21 1:51 AM, Thomas Huth wrote:
>  Hi,
>
> I just faced this failure in the CI:
>
>  https://gitlab.com/thuth/qemu/-/jobs/1053467007#L73
>
> I thought we'd handle CANCEL as "skipped"? Why did this
> cause the CI to fail?

Yes, CANCEL'ed tests should not change the job status (same semantic of 
SKIP).

For that execution in particular the test was actually interrupted (see 
on the summary report, the INTERRUPT accounts for 1). Sorry, I only 
glanced at the logs so I am not sure it is a bug on the fetch/download 
code or somewhere else.

BTW, it seems the GitLab cache mechanism for those acceptance tests is 
not working, as can be seen in:

https://gitlab.com/thuth/qemu/-/jobs/1053467007#L25

Thanks!

Wainer

> For reference, here's the debug.log:
>
> 19:33:28 DEBUG| PARAMS (key=arch, path=*, default=aarch64) => 'aarch64'
> 19:33:28 DEBUG| PARAMS (key=machine, path=*, default=None) => None
> 19:33:28 DEBUG| PARAMS (key=qemu_bin, path=*, 
> default=./qemu-system-aarch64) => './qemu-system-aarch64'
> 19:33:28 DEBUG| Looking for and selecting a qemu-img binary to be used 
> to create the bootable snapshot image
> 19:33:28 INFO | Downloading/preparing boot image
> 19:48:28 ERROR|
> 19:48:28 ERROR| Reproduced traceback from: 
> /builds/thuth/qemu/build/tests/venv/lib/python3.8/site-packages/avocado/core/test.py:753
> 19:48:28 ERROR| Traceback (most recent call last):
> 19:48:28 ERROR|   File 
> "/builds/thuth/qemu/build/tests/acceptance/avocado_qemu/__init__.py", 
> line 292, in download_boot
> 19:48:28 ERROR|     boot = vmimage.get(
> 19:48:28 ERROR|   File 
> "/builds/thuth/qemu/build/tests/venv/lib/python3.8/site-packages/avocado/utils/vmimage.py", 
> line 533, in get
> 19:48:28 ERROR|     return Image(name=provider.name, 
> url=provider.get_image_url(),
> 19:48:28 ERROR|   File 
> "/builds/thuth/qemu/build/tests/venv/lib/python3.8/site-packages/avocado/utils/vmimage.py", 
> line 205, in get_image_url
> 19:48:28 ERROR|     if int(self.version) >= 28:
> 19:48:28 ERROR|   File 
> "/builds/thuth/qemu/build/tests/venv/lib/python3.8/site-packages/avocado/utils/vmimage.py", 
> line 97, in version
> 19:48:28 ERROR|     return self._best_version or self.get_version()
> 19:48:28 ERROR|   File 
> "/builds/thuth/qemu/build/tests/venv/lib/python3.8/site-packages/avocado/utils/vmimage.py", 
> line 146, in get_version
> 19:48:28 ERROR|     resulting_versions = self.get_versions()
> 19:48:28 ERROR|   File 
> "/builds/thuth/qemu/build/tests/venv/lib/python3.8/site-packages/avocado/utils/vmimage.py", 
> line 124, in get_versions
> 19:48:28 ERROR|     self._feed_html_parser(self.url_versions, parser)
> 19:48:28 ERROR|   File 
> "/builds/thuth/qemu/build/tests/venv/lib/python3.8/site-packages/avocado/utils/vmimage.py", 
> line 113, in _feed_html_parser
> 19:48:28 ERROR|     data = urlopen(url).read()
> 19:48:28 ERROR|   File "/usr/lib/python3.8/urllib/request.py", line 
> 222, in urlopen
> 19:48:28 ERROR|     return opener.open(url, data, timeout)
> 19:48:28 ERROR|   File "/usr/lib/python3.8/urllib/request.py", line 
> 525, in open
> 19:48:28 ERROR|     response = self._open(req, data)
> 19:48:28 ERROR|   File "/usr/lib/python3.8/urllib/request.py", line 
> 542, in _open
> 19:48:28 ERROR|     result = self._call_chain(self.handle_open, 
> protocol, protocol +
> 19:48:28 ERROR|   File "/usr/lib/python3.8/urllib/request.py", line 
> 502, in _call_chain
> 19:48:28 ERROR|     result = func(*args)
> 19:48:28 ERROR|   File "/usr/lib/python3.8/urllib/request.py", line 
> 1393, in https_open
> 19:48:28 ERROR|     return self.do_open(http.client.HTTPSConnection, req,
> 19:48:28 ERROR|   File "/usr/lib/python3.8/urllib/request.py", line 
> 1354, in do_open
> 19:48:28 ERROR|     r = h.getresponse()
> 19:48:28 ERROR|   File "/usr/lib/python3.8/http/client.py", line 1347, 
> in getresponse
> 19:48:28 ERROR|     response.begin()
> 19:48:28 ERROR|   File "/usr/lib/python3.8/http/client.py", line 307, 
> in begin
> 19:48:28 ERROR|     version, status, reason = self._read_status()
> 19:48:28 ERROR|   File "/usr/lib/python3.8/http/client.py", line 268, 
> in _read_status
> 19:48:28 ERROR|     line = str(self.fp.readline(_MAXLINE + 1), 
> "iso-8859-1")
> 19:48:28 ERROR|   File "/usr/lib/python3.8/socket.py", line 669, in 
> readinto
> 19:48:28 ERROR|     return self._sock.recv_into(b)
> 19:48:28 ERROR|   File "/usr/lib/python3.8/ssl.py", line 1241, in 
> recv_into
> 19:48:28 ERROR|     return self.read(nbytes, buffer)
> 19:48:28 ERROR|   File "/usr/lib/python3.8/ssl.py", line 1099, in read
> 19:48:28 ERROR|     return self._sslobj.read(len, buffer)
> 19:48:28 ERROR|   File 
> "/builds/thuth/qemu/build/tests/venv/lib/python3.8/site-packages/avocado/plugins/runner.py", 
> line 77, in sigterm_handler
> 19:48:28 ERROR|     raise RuntimeError("Test interrupted by SIGTERM")
> 19:48:28 ERROR| RuntimeError: Test interrupted by SIGTERM
> 19:48:28 ERROR|
> 19:48:28 ERROR| During handling of the above exception, another 
> exception occurred:
> 19:48:28 ERROR|
> 19:48:28 ERROR| Traceback (most recent call last):
> 19:48:28 ERROR|   File 
> "/builds/thuth/qemu/build/tests/acceptance/avocado_qemu/__init__.py", 
> line 257, in setUp
> 19:48:28 ERROR|     self.set_up_boot()
> 19:48:28 ERROR|   File 
> "/builds/thuth/qemu/build/tests/acceptance/avocado_qemu/__init__.py", 
> line 321, in set_up_boot
> 19:48:28 ERROR|     path = self.download_boot()
> 19:48:28 ERROR|   File 
> "/builds/thuth/qemu/build/tests/acceptance/avocado_qemu/__init__.py", 
> line 299, in download_boot
> 19:48:28 ERROR|     self.cancel('Failed to download/prepare boot image')
> 19:48:28 ERROR|   File 
> "/builds/thuth/qemu/build/tests/venv/lib/python3.8/site-packages/avocado/core/test.py", 
> line 984, in cancel
> 19:48:28 ERROR|     raise exceptions.TestCancel(message)
> 19:48:28 ERROR| avocado.core.exceptions.TestCancel: Failed to 
> download/prepare boot image
> 19:48:28 ERROR|
> 19:48:28 ERROR| CANCEL 
> 01-tests/acceptance/boot_linux.py:BootLinuxAarch64.test_virt_tcg -> 
> TestCancel: Failed to download/prepare boot image
> 19:48:28 INFO |
>
> Runner error occurred: Timeout reached
> Original status: CANCEL
> {'name': 
> '01-tests/acceptance/boot_linux.py:BootLinuxAarch64.test_virt_tcg', 
> 'logdir': 
> '/builds/thuth/qemu/build/tests/results/job-2021-02-24T19.33-5b27292/test-results/01-tests_acceptance_boot_linux.py_BootLinuxAarch64.test_virt_tcg', 
> 'logfile': 
> '/builds/thuth/qemu/build/tests/results/job-2021-02-24T19.33-5b27292/test-results/01-tests_acceptance_boot_linux.py_BootLinuxAarch64.test_virt_tcg/debug.log', 
> 'status': 'CANCEL', 'running': False, 'paused': False, 'time_start': 
> 1614195208.4540772, 'time_elapsed': 900.2490696907043, 'time_end': 
> 1614196108.703147, 'fail_reason': 'Failed to download/prepare boot 
> image', 'fail_class': 'TestCancel', 'traceback': 'Traceback (most 
> recent call last):\n File 
> "/builds/thuth/qemu/build/tests/acceptance/avocado_qemu/__init__.py", 
> line 292, in download_boot\n    boot = vmimage.get(\n  File 
> "/builds/thuth/qemu/build/tests/venv/lib/python3.8/site-packages/avocado/utils/vmimage.py", 
> line 533, in get\n    return Image(name=provider.name, 
> url=provider.get_image_url(),\n  File 
> "/builds/thuth/qemu/build/tests/venv/lib/python3.8/site-packages/avocado/utils/vmimage.py", 
> line 205, in get_image_url\n    if int(self.version) >= 28:\n File 
> "/builds/thuth/qemu/build/tests/venv/lib/python3.8/site-packages/avocado/utils/vmimage.py", 
> line 97, in version\n    return self._best_version or 
> self.get_version()\n  File 
> "/builds/thuth/qemu/build/tests/venv/lib/python3.8/site-packages/avocado/utils/vmimage.py", 
> line 146, in get_version\n    resulting_versions = 
> self.get_versions()\n  File 
> "/builds/thuth/qemu/build/tests/venv/lib/python3.8/site-packages/avocado/utils/vmimage.py", 
> line 124, in get_versions\n self._feed_html_parser(self.url_versions, 
> parser)\n  File 
> "/builds/thuth/qemu/build/tests/venv/lib/python3.8/site-packages/avocado/utils/vmimage.py", 
> line 113, in _feed_html_parser\n    data = urlopen(url).read()\n File 
> "/usr/lib/python3.8/urllib/request.py", line 222, in urlopen\n    
> return opener.open(url, data, timeout)\n  File 
> "/usr/lib/python3.8/urllib/request.py", line 525, in open\n response = 
> self._open(req, data)\n  File "/usr/lib/python3.8/urllib/request.py", 
> line 542, in _open\n result = self._call_chain(self.handle_open, 
> protocol, protocol +\n  File "/usr/lib/python3.8/urllib/request.py", 
> line 502, in _call_chain\n    result = func(*args)\n  File 
> "/usr/lib/python3.8/urllib/request.py", line 1393, in https_open\n    
> return self.do_open(http.client.HTTPSConnection, req,\n  File 
> "/usr/lib/python3.8/urllib/request.py", line 1354, in do_open\n    r = 
> h.getresponse()\n  File "/usr/lib/python3.8/http/client.py", line 
> 1347, in getresponse\n    response.begin()\n  File 
> "/usr/lib/python3.8/http/client.py", line 307, in begin\n version, 
> status, reason = self._read_status()\n  File 
> "/usr/lib/python3.8/http/client.py", line 268, in _read_status\n    
> line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")\n  File 
> "/usr/lib/python3.8/socket.py", line 669, in readinto\n    return 
> self._sock.recv_into(b)\n  File "/usr/lib/python3.8/ssl.py", line 
> 1241, in recv_into\n    return self.read(nbytes, buffer)\n  File 
> "/usr/lib/python3.8/ssl.py", line 1099, in read\n    return 
> self._sslobj.read(len, buffer)\n File 
> "/builds/thuth/qemu/build/tests/venv/lib/python3.8/site-packages/avocado/plugins/runner.py", 
> line 77, in sigterm_handler\n    raise RuntimeError("Test interrupted 
> by SIGTERM")\nRuntimeError: Test interrupted by SIGTERM\n\nDuring 
> handling of the above exception, another exception 
> occurred:\n\nTraceback (most recent call last):\n  File 
> "/builds/thuth/qemu/build/tests/venv/lib/python3.8/site-packages/avocado/core/test.py", 
> line 747, in _run_avocado\n    self.setUp()\n  File 
> "/builds/thuth/qemu/build/tests/acceptance/avocado_qemu/__init__.py", 
> line 257, in setUp\n    self.set_up_boot()\n  File 
> "/builds/thuth/qemu/build/tests/acceptance/avocado_qemu/__init__.py", 
> line 321, in set_up_boot\n    path = self.download_boot()\n  File 
> "/builds/thuth/qemu/build/tests/acceptance/avocado_qemu/__init__.py", 
> line 299, in download_boot\n    self.cancel(\'Failed to 
> download/prepare boot image\')\n  File 
> "/builds/thuth/qemu/build/tests/venv/lib/python3.8/site-packages/avocado/core/test.py", 
> line 984, in cancel\n    raise 
> exceptions.TestCancel(message)\navocado.core.exceptions.TestCancel: 
> Failed to download/prepare boot image\n', 'timeout': 900, 
> 'whiteboard': '', 'phase': 'FINISHED', 'class_name': 
> 'BootLinuxAarch64', 'job_logdir': 
> '/builds/thuth/qemu/build/tests/results/job-2021-02-24T19.33-5b27292', 
> 'job_unique_id': '5b27292fb97a200bfe5bfeae2d35f53b94eb4c5c', 'params': 
> []}
>
>
>  Thomas