QA » openQA Project

Hm, we have a workaround in place which is even automatically applied, QA tools team is limited in capacity and nobody seems to have a clear idea what to do so we can also regard is Low+future

A query to find corresponding jobs:

select jobs.id,t_finished,state,result,test,reason,host from jobs, comments, workers where t_finished >= '2020-08-01' and jobs.id = comments.job_id and comments.text ~ '69451' order by t_finished desc limit 10;

this shows that this ticket is used a lot recently and the problem reproduces. This is making the issue more prominent and important. And yes, it can be that some downloads in a job succeed, others do not.

In https://openqa.suse.de/tests/4612518# there is

[info] [#1051] Download of "/var/lib/openqa/cache/openqa.suse.de/SLES-15-SP3-aarch64-21.1@aarch64-filesystem_withouthome-uefi-vars.qcow2" failed: 404 Not Found

so maybe the behaviour changed a bit and now it says "404 Not Found" but still this is not enough to be clear to readers because in before it still said "Download successful".

Your query doesn't make much sense, you need to join the tables to get actually different job IDs.

The query

select concat('https://openqa.suse.de/t', jobs.id) as job, jobs.t_finished, text as comment, (select concat(host, ':', instance) as worker from workers where workers.id = jobs.assigned_worker_id) from jobs join comments on jobs.id = comments.job_id where t_finished >= '2020-08-01' and jobs.id = comments.job_id and comments.text like '%poo#69451%' order by t_finished desc;

returns currently 36 jobs on OSD and 9 jobs on o3.

I had a look at quite a share of these jobs. Most jobs I've checked have either no more logs or they are actually just containing multiple downloads and one was successful and others not. Considering so many jobs being wrongly associated with that ticket I wouldn't deduce the frequency this problem occurs from this SQL query.

I only found one job which where the log actually matches the log from the ticket's observation:

[2020-09-17T18:00:38.0616 CEST] [info] [pid:9073] +++ setup notes +++
[2020-09-17T18:00:38.0616 CEST] [info] [pid:9073] Running on openqaworker9:23 (Linux 4.12.14-lp151.28.67-default #1 SMP Fri Sep 4 15:23:21 UTC 2020 (2c5a14f) x86_64)
[2020-09-17T18:00:38.0625 CEST] [debug] [pid:9073] Found ISO, caching SLE-12-SP4-Server-DVD-x86_64-GM-DVD1.iso
[2020-09-17T18:00:38.0628 CEST] [info] [pid:9073] Downloading SLE-12-SP4-Server-DVD-x86_64-GM-DVD1.iso, request #7271 sent to Cache Service
[2020-09-17T18:08:59.0731 CEST] [info] [pid:9073] Download of SLE-12-SP4-Server-DVD-x86_64-GM-DVD1.iso processed:
[info] [#7271] Cache size of "/var/lib/openqa/cache" is 49GiB, with limit 50GiB
[info] [#7271] Downloading "SLE-12-SP4-Server-DVD-x86_64-GM-DVD1.iso" from "http://openqa.suse.de/tests/4704446/asset/iso/SLE-12-SP4-Server-DVD-x86_64-GM-DVD1.iso"
[info] [#7271] Cache size 50GiB + needed 4GiB exceeds limit of 50GiB, purging least used assets
[info] [#7271] Purging "/var/lib/openqa/cache/openqa.suse.de/sle-15-x86_64-ha-rolling_upgrade_update.qcow2" because we need space for new assets, reclaiming 1.1GiB
[info] [#7271] Purging "/var/lib/openqa/cache/openqa.suse.de/SLE-15-SP1-Installer-DVD-x86_64-GM-DVD1.iso" because we need space for new assets, reclaiming 663MiB
[info] [#7271] Purging "/var/lib/openqa/cache/openqa.suse.de/SLE-15-SP3-Online-x86_64-Build36.5-Media1.iso.sha256" because we need space for new assets, reclaiming 112 Byte
[info] [#7271] Purging "/var/lib/openqa/cache/openqa.suse.de/SLE-15-SP3-x86_64-Build36.5-sles4sap-gnome.qcow2" because we need space for new assets, reclaiming 1.6GiB
[info] [#7271] Purging "/var/lib/openqa/cache/openqa.suse.de/SLE-12-SP4-Server-DVD-x86_64-GM-DVD1.iso" because we need space for new assets, reclaiming 4GiB
[info] [#7271] Size of "/var/lib/openqa/cache/openqa.suse.de/SLE-12-SP4-Server-DVD-x86_64-GM-DVD1.iso" is 4GiB, with ETag ""101000000-5a69b6dce2b91""
[info] [#7271] Download of "/var/lib/openqa/cache/openqa.suse.de/SLE-12-SP4-Server-DVD-x86_64-GM-DVD1.iso" successful, new cache size is 47GiB

[2020-09-17T18:08:59.0732 CEST] [error] [pid:9073] Failed to download SLE-12-SP4-Server-DVD-x86_64-GM-DVD1.iso to /var/lib/openqa/cache/openqa.suse.de/SLE-12-SP4-Server-DVD-x86_64-GM-DVD1.iso
[2020-09-17T18:08:59.0851 CEST] [info] [pid:9073] +++ worker notes +++
[2020-09-17T18:08:59.0852 CEST] [info] [pid:9073] End time: 2020-09-17 16:08:59
[2020-09-17T18:08:59.0852 CEST] [info] [pid:9073] Result: setup failure
[2020-09-17T18:08:59.0876 CEST] [info] [pid:54995] Uploading autoinst-log.txt

(log of https://openqa.suse.de/tests/4704446)

Here the asset has been purged while the download was still ongoing. Maybe that was also the case for https://openqa.suse.de/tests/4504422 (the job mentioned in the ticket description). Unfortunately the job's log has already been cleaned up so it is impossible to check that at this point.

So maybe there's a bug which makes it possible for assets to be purged while still being downloaded. I'll have a look at the asset cache code.

Clarifing the AC about "referencing the same asset". We have to be careful that the auto-review regex is rather generic so this ticket will catch the cases where the downloaded asset was purged as well as the case when other assets failed to download.

waiting for related ticket #71827 after https://github.com/os-autoinst/openQA/pull/3418 is in