On Tue, Jul 25, 2023 at 1:13 PM Peter Maydell <peter.mayd...@linaro.org> 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) ?
>
Hi Peter,
First of all, I am sorry for the frustration you experienced while
trying to understand all of this. It tooke me a while too. Anyways,
the 90 seconds timeout is set here[1].
> I don't understand the debug.log, because it says all of
> * that it retrieved the URL
That happens here[2], because Python's urllib.request.urlopen()[3]
returned a response. The message is clearly misleading, though,
because:
1. the response may not indicate that the request was successful (even
though the most common exception raised by unsuccessful operations,
HTTPError, is being handled)
2. that the file's content being pointed at by the URL has been transferred.
I've opened an issue[4] to fix this misleading message.
> * that it wanted to cancel the test
Yes, this is the default behavior set here[5] (cancel_on_missing=True).
> * that the test timed out
>
My understanding, up to this point, is that:
Avocado signals to the test that it should be interrupted. The
handling of the exception gets to the attempt to fetch the asset,
which fails and is thus considered missing. Because of
cancel_on_missing=True, It sets the status of the test, up to that
point, to be CANCELed.
But, Avocado "knows better", because it triggered the interruption of
the test, so it overwrites that status of the test as INTERRUPTed.
The whole thing may be complex and confusing, but IMO it seems
coherent so far (minus the misleading "retrieved" message).
Your question (" 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)
?) is actually very important and up to the point. For Avocado 88.1,
there are two things happening when it comes to requirements:
1. The "assets" plugin runs *before* the job, and attempts to identify
and cache all assets (best effort, and sometimes limited approach,
because it employs a static syntactic analysis of the source code to
identify assets to be retrieved. This *usually* handles the
requirements before the tests.
2. The actual execution of the "fetch_asset()" code during the test
execution (including during setUp()). This is *not* limited by the
static syntactic analysis mentioned earlier.
Ideally, step 2 would *not* happen, as it can violate the
"requirements before test" principle. One way to achieve that is
simply to set find_only=True at the same place cancel_on_missing
defaults to True[5]. It's documented here[6].
For newer Avocado, there's a completely different requirement
mechanism[7], that is completely outside of the test execution. I
hope that it will be leveraged by QEMU (it was designed to improve the
current design/implementation limitations mentioned previously). But,
this is a bit out of the scope at this point, because the goal is to
have Avocado 103.0 addressing logging and properly cleaning up all
tests (like stray processes) which are the two high priority issues we
are tracking with the "customer:QEMU" label before proposing a bump in
Avocado version.
> 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'}
>
[1] -
https://gitlab.com/qemu-project/qemu/-/blob/ccdd31267678db9d80578b5f80bbe94141609ef4/tests/avocado/boot_linux_console.py#L98
[2] -
https://github.com/avocado-framework/avocado/blob/1fba8042a8a4a83f5342138786240f676e58074d/avocado/utils/download.py#L46
[3] -
https://docs.python.org/3/library/urllib.request.html#urllib.request.urlopen
[4] - https://github.com/avocado-framework/avocado/issues/5742
[5] -
https://gitlab.com/qemu-project/qemu/-/blob/ccdd31267678db9d80578b5f80bbe94141609ef4/tests/avocado/avocado_qemu/__init__.py#L259
[6] -
https://avocado-framework.readthedocs.io/en/102.0/api/test/avocado.html#avocado.Test.fetch_asset
[7] - https://avocado-framework.readthedocs.io/en/102.0/blueprints/BP004.html
>
> thanks
> -- PMM
>
