Re: avocado test failing INTERRUPTED for "Missing asset"

["Philippe Mathieu-Daudé" <philmd@linaro.org>]

On 25/7/23 19:13, Peter Maydell wrote:
> Currently this CI job is failing:
> 
> https://gitlab.com/qemu-project/qemu/-/jobs/4737819946
> 
> because:
> 
> (05/59) tests/avocado/boot_linux_console.py:BootLinuxConsole.test_arm_exynos4210_initrd:
> INTERRUPTED: Missing asset
> https://snapshot.debian.org/archive/debian/20190928T224601Z/pool/main/l/linux/linux-image-4.19.0-6-armmp_4.19.67-2+deb10u1_armhf.deb\nRunner
> error occurred: Timeout reached\nOriginal status: CANCEL\n{'name':
> '05-tests/avocado/boot_linux_console... (90.67 s)
> 
> Why is a "Missing asset" causing a timeout after 90 seconds,
> rather than being accounted as a "SKIP" ("missing requirements
> in the test environment" sounds like what we have here) ?

Maybe something to report to upstream Avocado.


That said, we want CI to be reproducible. If we fetch assets from
unreliable sources, we can't be reproducible. If we are unable to
provide a assets cache, we'll keep hitting this problem. If we can
not find a way to have assets stored (requiring sysadmin time setting
up some infra, possibly only for GitLab), then I'd consider stopping
running tests depending on external assets on CI; otherwise at some
point we'll get tired to waste time figuring out the same problem.

As a maintainer I'm happy to run the avocado tests using my local
assets cache, and I would rather keep using the framework. But then
my cache is likely different from others (users, maintainers, CI).
Similarly few users/maintainers end up having the same cache and
running the same set of tests.

$ du -chs ~/avocado/data/cache/
5.7G    /Users/philmd/avocado/data/cache/

Some files are older than 3 years, and I'm happy to still run the
tests depending on them (although they disappeared from their
original http server).

> I don't understand the debug.log, because it says all of
>   * that it retrieved the URL
>   * that it wanted to cancel the test
>   * that the test timed out
> 
> Here it is:
> 
> 16:03:16 DEBUG| PARAMS (key=arch, path=*, default=arm) => 'arm'
> 16:03:16 DEBUG| PARAMS (key=cpu, path=*, default=None) => None
> 16:03:16 DEBUG| PARAMS (key=qemu_bin, path=*,
> default=./qemu-system-arm) => './qemu-system-arm'
> 16:03:16 DEBUG| PARAMS (key=machine, path=*, default=smdkc210) => 'smdkc210'
> 16:03:16 INFO | Asset not in cache, fetching it.
> 16:03:16 INFO | Fetching
> https://snapshot.debian.org/archive/debian/20190928T224601Z/pool/main/l/linux/linux-image-4.19.0-6-armmp_4.19.67-2+deb10u1_armhf.deb
> -> /builds/qemu-project/qemu/avocado-cache/by_location/5f20376efeb69c8898caaff3edf7de45b4540163/linux-image-4.19.0-6-armmp_4.19.67-2+deb10u1_armhf.deb.ooffovd_
> 16:04:05 DEBUG| Retrieved URL
> "https://snapshot.debian.org/archive/debian/20190928T224601Z/pool/main/l/linux/linux-image-4.19.0-6-armmp_4.19.67-2+deb10u1_armhf.deb":
> content-length 33882084, date: "Tue, 25 Jul 2023 16:03:16 GMT",
> last-modified: "Tue, 24 Sep 2019 22:31:23 GMT"
> 16:04:46 ERROR| RuntimeError: Test interrupted by SIGTERM
> 16:04:46 ERROR|
> 16:04:46 ERROR| Reproduced traceback from:
> /builds/qemu-project/qemu/build/tests/venv/lib/python3.9/site-packages/avocado/core/test.py:767
> 16:04:46 ERROR| Traceback (most recent call last):
> 16:04:46 ERROR|   File
> "/builds/qemu-project/qemu/build/tests/venv/lib/python3.9/site-packages/avocado/core/test.py",
> line 1043, in fetch_asset
> 16:04:46 ERROR|     return asset_obj.fetch()
> 16:04:46 ERROR|   File
> "/builds/qemu-project/qemu/build/tests/venv/lib/python3.9/site-packages/avocado/utils/asset.py",
> line 381, in fetch
> 16:04:46 ERROR|     raise OSError("Failed to fetch %s (%s)." %
> (self.asset_name, error))
> 16:04:46 ERROR| OSError: Failed to fetch
> linux-image-4.19.0-6-armmp_4.19.67-2+deb10u1_armhf.deb (Test
> interrupted by SIGTERM).
> 16:04:46 ERROR|
> 16:04:46 ERROR| During handling of the above exception, another
> exception occurred:
> 16:04:46 ERROR|
> 16:04:46 ERROR| Traceback (most recent call last):
> 16:04:46 ERROR|   File
> "/builds/qemu-project/qemu/build/tests/avocado/boot_linux_console.py",
> line 514, in test_arm_exynos4210_initrd
> 16:04:46 ERROR|     deb_path = self.fetch_asset(deb_url, asset_hash=deb_hash)
> 16:04:46 ERROR|   File
> "/builds/qemu-project/qemu/build/tests/avocado/avocado_qemu/__init__.py",
> line 260, in fetch_asset
> 16:04:46 ERROR|     return super().fetch_asset(name,
> 16:04:46 ERROR|   File
> "/builds/qemu-project/qemu/build/tests/venv/lib/python3.9/site-packages/avocado/core/test.py",
> line 1049, in fetch_asset
> 16:04:46 ERROR|     self.cancel("Missing asset {}".format(name))
> 16:04:46 ERROR|   File
> "/builds/qemu-project/qemu/build/tests/venv/lib/python3.9/site-packages/avocado/core/test.py",
> line 988, in cancel
> 16:04:46 ERROR|     raise exceptions.TestCancel(message)
> 16:04:46 ERROR| avocado.core.exceptions.TestCancel: Missing asset
> https://snapshot.debian.org/archive/debian/20190928T224601Z/pool/main/l/linux/linux-image-4.19.0-6-armmp_4.19.67-2+deb10u1_armhf.deb
> 16:04:46 ERROR|
> 16:04:46 ERROR| CANCEL
> 05-tests/avocado/boot_linux_console.py:BootLinuxConsole.test_arm_exynos4210_initrd
> -> TestCancel: Missing asset
> https://snapshot.debian.org/archive/debian/20190928T224601Z/pool/main/l/linux/linux-image-4.19.0-6-armmp_4.19.67-2+deb10u1_armhf.deb
> 16:04:46 INFO |
> 
> Runner error occurred: Timeout reached
> Original status: CANCEL
> {'name': '05-tests/avocado/boot_linux_console.py:BootLinuxConsole.test_arm_exynos4210_initrd',
> 'logdir': '/builds/qemu-project/qemu/build/tests/results/job-2023-07-25T16.00-c6ec778/test-results/05-tests_avocado_boot_linux_console.py_BootLinuxConsole.test_arm_exynos4210_initrd',
> 'logfile': '/builds/qemu-project/qemu/build/tests/results/job-2023-07-25T16.00-c6ec778/test-results/05-tests_avocado_boot_linux_console.py_BootLinuxConsole.test_arm_exynos4210_initrd/debug.log',
> 'status': 'CANCEL', 'running': False, 'paused': False, 'time_start':
> 1690300996.270224, 'time_elapsed': 90.66501116752625, 'time_end':
> 1690301086.9352353, 'fail_reason': 'Missing asset
> https://snapshot.debian.org/archive/debian/20190928T224601Z/pool/main/l/linux/linux-image-4.19.0-6-armmp_4.19.67-2+deb10u1_armhf.deb',
> 'fail_class': 'TestCancel', 'traceback': 'Traceback (most recent call
> last):\n  File "/builds/qemu-project/qemu/build/tests/venv/lib/python3.9/site-packages/avocado/core/test.py",
> line 1043, in fetch_asset\n    return asset_obj.fetch()\n  File
> "/builds/qemu-project/qemu/build/tests/venv/lib/python3.9/site-packages/avocado/utils/asset.py",
> line 381, in fetch\n    raise OSError("Failed to fetch %s (%s)." %
> (self.asset_name, error))\nOSError: Failed to fetch
> linux-image-4.19.0-6-armmp_4.19.67-2+deb10u1_armhf.deb (Test
> interrupted by SIGTERM).\n\nDuring handling of the above exception,
> another exception occurred:\n\nTraceback (most recent call last):\n
> File "/builds/qemu-project/qemu/build/tests/venv/lib/python3.9/site-packages/avocado/core/test.py",
> line 765, in _run_avocado\n    testMethod()\n  File
> "/builds/qemu-project/qemu/build/tests/avocado/boot_linux_console.py",
> line 514, in test_arm_exynos4210_initrd\n    deb_path =
> self.fetch_asset(deb_url, asset_hash=deb_hash)\n  File
> "/builds/qemu-project/qemu/build/tests/avocado/avocado_qemu/__init__.py",
> line 260, in fetch_asset\n    return super().fetch_asset(name,\n  File
> "/builds/qemu-project/qemu/build/tests/venv/lib/python3.9/site-packages/avocado/core/test.py",
> line 1049, in fetch_asset\n    self.cancel("Missing asset
> {}".format(name))\n  File
> "/builds/qemu-project/qemu/build/tests/venv/lib/python3.9/site-packages/avocado/core/test.py",
> line 988, in cancel\n    raise
> exceptions.TestCancel(message)\navocado.core.exceptions.TestCancel:
> Missing asset https://snapshot.debian.org/archive/debian/20190928T224601Z/pool/main/l/linux/linux-image-4.19.0-6-armmp_4.19.67-2+deb10u1_armhf.deb\n',
> 'tags': {'arch': set(), 'machine': set(), 'accel': set()}, 'timeout':
> 90, 'whiteboard': '', 'phase': 'FINISHED', 'class_name':
> 'BootLinuxConsole', 'params': [], 'job_logdir':
> '/builds/qemu-project/qemu/build/tests/results/job-2023-07-25T16.00-c6ec778',
> 'job_unique_id': 'c6ec77846be47fc859fe109c38c0932cc07fe04c'}
> 
> 
> thanks
> -- PMM