avocado test failing INTERRUPTED for "Missing asset"

avocado test failing INTERRUPTED for "Missing asset"

[Peter Maydell]

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) ?

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

Re: avocado test failing INTERRUPTED for "Missing asset"

[Philippe Mathieu-Daudé]

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

Re: avocado test failing INTERRUPTED for "Missing asset"

[Thomas Huth]

On 26/07/2023 09.33, Philippe Mathieu-Daudé wrote:
> 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.

We're back to using Avocado v88.1 in QEMU. We first need someone who can 
update to the latest Avocado release and take care of the remaining 
problems... This is *very* frustrating.

  Thomas

Re: avocado test failing INTERRUPTED for "Missing asset"

[Cleber Rosa]

On Tue, Jul 25, 2023 at 1:13 PM Peter Maydell <peter.maydell@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
>

Re: avocado test failing INTERRUPTED for "Missing asset"

[Peter Maydell]

On Thu, 27 Jul 2023 at 16:20, Cleber Rosa <crosa@redhat.com> wrote:
>
> On Tue, Jul 25, 2023 at 1:13 PM Peter Maydell <peter.maydell@linaro.org> wrote:
> > 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).

Ah, so the problem is that we are trying to download the asset
file, and the remote server is stalling so it doesn't actually
download the file in 90s, and Avocado doesn't distinguish
"hit the timeout while trying to download assets" from
"hit the timeout running the actual test" ?

This sounds to me like the ideal would be that there is a separate
timeout for file downloads (which could then be a lot shorter than
the overall test timeout), and "timeout during asset download"
would be detected separately from "timeout while actually running
test".  But maybe the separation-of-phases in newer Avocado achieves
that already ?

thanks
-- PMM

Re: avocado test failing INTERRUPTED for "Missing asset"

[Cleber Rosa]

On Thu, Jul 27, 2023 at 11:50 AM Peter Maydell <peter.maydell@linaro.org> wrote:
>
> Ah, so the problem is that we are trying to download the asset
> file, and the remote server is stalling so it doesn't actually
> download the file in 90s, and Avocado doesn't distinguish
> "hit the timeout while trying to download assets" from
> "hit the timeout running the actual test" ?
>

Yes, exactly.  Once the test starts, that's the only timeout being
enforced.  The fetch_asset() (and all the download code path) is
simply part of the test and thus under the test timeout.  Also, right
now, avocado.Test.fetch_asset() doesn't provide a timeout parameter
(but the underlying avocado.utils.asset.Asset.fetch() does).

> This sounds to me like the ideal would be that there is a separate
> timeout for file downloads (which could then be a lot shorter than
> the overall test timeout), and "timeout during asset download"
> would be detected separately from "timeout while actually running
> test".  But maybe the separation-of-phases in newer Avocado achieves
> that already ?
>

The mechanism in newer Avocado will simply never attempt to run tests
that don't have the stated requirements fulfilled.  With regards to
timeouts, each of the different kinds of requirement implementations
(file downloads and cache, A.K.A. "assets", packages installation,
ansible module execution,  etc) are supposed to provide their own
features, including timeouts.

Anyways, I'll look into, and report back on:

1. expanding avocado.Test.fetch_asset() with a timeout parameter
2. making sure the newer implementation for the requirement types used
by QEMU respect a timeout (they don't need to be smaller than the
test, because they run completely outside of the test).

For now, are you OK with re-running those jobs if the servers stall
the transfers? Or would you rather see a patch that changes the
find_only parameter to True, so that if the pre-test attempt to
download the asset fails, the transfer is never attempted during the
test?

Thanks,
- Cleber.

> thanks
> -- PMM
>

Re: avocado test failing INTERRUPTED for "Missing asset"

[Cleber Rosa]

On Wed, Jul 26, 2023 at 3:34 AM Philippe Mathieu-Daudé
<philmd@linaro.org> wrote:
>
> 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.
>
>

Hi Philippe,

Please check my response to Peter's first message on this thread.
It's a rather long answer, but I hope this behavior is understandable.

> 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.
>

Right, in an ideal world, we could have a master list of all the
assets that every single job will need, and require an admin to make
sure each and every one of them is cached before running a job.  The
current approach with Avocado's pre-job "fetch asset" plugin is to do
as much as possible without having duplication of the assets URLs in
such a "asset master list" and in the test code.

Also, it will not abort a job if any of these assets fail to be
fetched.  It's a convenient choice that, on the other hand, yields
lower reproducibility and reliability.

> 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).
>

This is a well maintained cache! :) Can we rsync from it? :)

Jokes aside, I'm open for ideas on how to better balance this
convenience versus reliability question.

Thanks,
- Cleber.

Re: avocado test failing INTERRUPTED for "Missing asset"

[Cleber Rosa]

On Wed, Jul 26, 2023 at 5:07 AM Thomas Huth <thuth@redhat.com> wrote:
>
> On 26/07/2023 09.33, Philippe Mathieu-Daudé wrote:
> > 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.
>
> We're back to using Avocado v88.1 in QEMU. We first need someone who can
> update to the latest Avocado release and take care of the remaining
> problems... This is *very* frustrating.
>
>   Thomas
>

Hi Thomas,

As you might remember from a couple of months ago, I was (and still
am) running the Avocado QEMU tests extensively with the latest Avocado
and attempting to cover all gaps before the 103.0 LTS release.

To make it clear, Avocado is currently on sprint #103[1] which will
release 103.0, a "Long Term Stability'' release.  It may sound like a
marketing gimmick, but it's important for QEMU because we want to be
able to address all bugs that are eventually caught after its release
while still minimizing disruption.

The frustration you mentioned with the attempt to migrate from 88.1 to
101.0, and now back to 88.1 is the kind of disruption we want to
avoid.  With 103.0 LTS, like with 92.X LTS, we can and will release
minor releases with needed fixes.

So, this is also an invitation to everyone else running the
Avocado-based  QEMU tests with either Avocado 102.0, or the latest
development version and report issues.

BTW, Avocado's GitHub has a "customer:QEMU"[2] label that can be added
to issues that will certainly increase its classification and
priority.

PS: 88.1 was a minor release to address an issue with the release
process itself, so there were no differences from 88.0 that mattered
to users, nor was there the possibility of a 88.2 release with more
fixes.

Thanks,
- Cleber.

[1] - https://github.com/avocado-framework/avocado/milestone/29
[2] - https://github.com/avocado-framework/avocado/issues?q=is%3Aopen+is%3Aissue+label%3Acustomer%3AQEMU+milestone%3A%22%23103+%28LTS+release+-+Sound+of+Freedom%29%22

Re: avocado test failing INTERRUPTED for "Missing asset"

[Peter Maydell]

On Thu, 27 Jul 2023 at 20:08, Cleber Rosa <crosa@redhat.com> wrote:
>
> On Thu, Jul 27, 2023 at 11:50 AM Peter Maydell <peter.maydell@linaro.org> wrote:
> >
> > Ah, so the problem is that we are trying to download the asset
> > file, and the remote server is stalling so it doesn't actually
> > download the file in 90s, and Avocado doesn't distinguish
> > "hit the timeout while trying to download assets" from
> > "hit the timeout running the actual test" ?
> >
>
> Yes, exactly.  Once the test starts, that's the only timeout being
> enforced.  The fetch_asset() (and all the download code path) is
> simply part of the test and thus under the test timeout.  Also, right
> now, avocado.Test.fetch_asset() doesn't provide a timeout parameter
> (but the underlying avocado.utils.asset.Asset.fetch() does).
>
> > This sounds to me like the ideal would be that there is a separate
> > timeout for file downloads (which could then be a lot shorter than
> > the overall test timeout), and "timeout during asset download"
> > would be detected separately from "timeout while actually running
> > test".  But maybe the separation-of-phases in newer Avocado achieves
> > that already ?
> >
>
> The mechanism in newer Avocado will simply never attempt to run tests
> that don't have the stated requirements fulfilled.  With regards to
> timeouts, each of the different kinds of requirement implementations
> (file downloads and cache, A.K.A. "assets", packages installation,
> ansible module execution,  etc) are supposed to provide their own
> features, including timeouts.
>
> Anyways, I'll look into, and report back on:
>
> 1. expanding avocado.Test.fetch_asset() with a timeout parameter

If newer-avocado does all this stuff differently it might not
be worth the extra effort on something we're going to move away from.

> 2. making sure the newer implementation for the requirement types used
> by QEMU respect a timeout (they don't need to be smaller than the
> test, because they run completely outside of the test).

The main thing I think is that timeouts on asset fetch should
result in a SKIP or CANCEL status, not INTERRUPTED, because
the CI treats INTERRUPTED as a failure, whereas SKIP and CANCEL
are OK.

> For now, are you OK with re-running those jobs if the servers stall
> the transfers? Or would you rather see a patch that changes the
> find_only parameter to True, so that if the pre-test attempt to
> download the asset fails, the transfer is never attempted during the
> test?

I think for the moment we're OK retrying (or more usually, saying
"this job is failing today, ignore it") -- usually this kind
of thing is "somebody's server is having troubles" and it goes
away after a day or so.

thanks
-- PMM

Re: avocado test failing INTERRUPTED for "Missing asset"

[Richard Henderson]

On 7/27/23 12:08, Cleber Rosa wrote:
> Anyways, I'll look into, and report back on:
> 
> 1. expanding avocado.Test.fetch_asset() with a timeout parameter
> 2. making sure the newer implementation for the requirement types used
> by QEMU respect a timeout (they don't need to be smaller than the
> test, because they run completely outside of the test).
> 
> For now, are you OK with re-running those jobs if the servers stall
> the transfers? Or would you rather see a patch that changes the
> find_only parameter to True, so that if the pre-test attempt to
> download the asset fails, the transfer is never attempted during the
> test?

I would be perfectly happy with find_only.  From your description that more-or-less 
matches the behaviour of v103.  I would also suggest that if the pre-test attempt fails, 
trying again in just a few minutes during the test isn't likely to work either.


r~