QA » openQA Project

https://github.com/os-autoinst/openQA/pull/3418 for a specific log message which auto-review can match on

The note

            # note: This check has no effect if the download was performed by
            # an already enqueued Minion job or if the pruning happened within
            # a completely different asset download.

I asked to add in the PR review shows that the problem is tricky:

1. Multiple downloads can run in parallel and therefore purging might run in parallel.
2. Even the download for the particular asset might be triggered by different jobs and is therefore executed within another Minion job. That means at least within the worker (where the PR tries to extend the message) we can not reliable detect the case.

@kraih You know the asset cache better than me: Are the mentioned points correct? Any idea how to solve this? Even if we use a lock to prevent parallel purging it would still leave a race condition because at the time the worker tries to access the asset (and creates the hardlink) it might have been purged nevertheless. Maybe it would help to create the hard link already within the download task but different jobs obviously need different hard links so that would complicate things. By the way, updating the asset to be the most recently used asset before the purging doesn't seem to do the trick. Otherwise we wouldn't see the issue (see #69451#note-5).

mkittler wrote:

I asked to add in the PR review shows that the problem is tricky:

1. Multiple downloads can run in parallel and therefore purging might run in parallel.
2. Even the download for the particular asset might be triggered by different jobs and is therefore executed within another Minion job. That means at least within the worker (where the PR tries to extend the message) we can not reliable detect the case.

@kraih You know the asset cache better than me: Are the mentioned points correct?

If i understand you correctly only the first point is correct. There can be multiple downloads active at the same time (and multiple purges, which probably is the cause for race conditions somehow), and multiple requests for the same asset at the same time. It is correct that only one cache service Minion job will do the actual download, but all requests will receive the output from the Minion job that performed the download. That's a fairly new feature i added to the cache service, you see it in action every time the Minion job ids from the cache service logs are different from the id of the job that was supposed to perform the download.

Although only point 1. is correct the conclusion is still true: We can not easily detect the "Purging" case on the worker-side because the log message won't show up when the purging of the downloaded asset happened to make room for a completely different asset.

I don't know how to solve this race-free. As mentioned before: We could of course add a lock to prevent parallel purging within the cache service but that would still leave room for the asset being purged when the worker is trying to create the hardlink. We could try to create the hard-link already within the cache service. However, that's difficult because the same download/Minion job might be running for multiple openQA jobs and therefore multiple hardlinks need to be created. @kraih Any idea how to solve this? There's no designated way for Minion jobs to communicate with each other, right? We could of course "leave a message" about additional hardlinks within the database.

Encountered more cases today: https://openqa.suse.de/tests/4961797, https://openqa.suse.de/tests/4961771, https://openqa.suse.de/tests/4961784, https://openqa.suse.de/tests/4961792, https://openqa.suse.de/tests/4961774

So multiple jobs are affected but these are all about the asset sle-12-SP5-x86_64-:17046:kernel-ec2-Server-DVD-Incidents-Kernel@64bit-with-ltp.qcow2 and they ran at the same time on the same worker:

openqa=> select id, state, result, t_started, (select host from workers where id = assigned_worker_id) as worker_host from jobs where id in (4961797, 4961771, 4961784, 4961792, 4961774) order by t_started asc;
   id    | state |   result   |      t_started      | worker_host 
---------+-------+------------+---------------------+-------------
 4961797 | done  | incomplete | 2020-11-09 18:33:33 | 10.160.1.20
 4961771 | done  | incomplete | 2020-11-09 18:33:34 | 10.160.1.20
 4961774 | done  | incomplete | 2020-11-09 18:33:34 | 10.160.1.20
 4961784 | done  | incomplete | 2020-11-09 18:33:34 | 10.160.1.20
 4961792 | done  | incomplete | 2020-11-09 18:33:34 | 10.160.1.20

(10.160.1.20 is actually openqaworker9.)

That's the relevant log of the cache service:

Nov 09 19:33:28 openqaworker9 openqa-worker-cacheservice-minion[3240]: [24380] [i] [#1348] Downloading: "sle-12-SP5-x86_64-:17046:kernel-ec2-Server-DVD-Incidents-Kernel@64bit-with-ltp.qcow2"
Nov 09 19:33:28 openqaworker9 openqa-worker-cacheservice-minion[3240]: [24380] [i] [#1348] Cache size of "/var/lib/openqa/cache" is 47GiB, with limit 50GiB
Nov 09 19:33:28 openqaworker9 openqa-worker-cacheservice-minion[3240]: [24380] [i] [#1348] Downloading "sle-12-SP5-x86_64-:17046:kernel-ec2-Server-DVD-Incidents-Kernel@64bit-with-ltp.qcow2" from "http://openqa.suse.de/tests/4961776/asset/hdd/sle-12-SP5-x86_64-:17046:kernel-ec2-Server-DVD-Incidents-Kernel@64bit-wit>
Nov 09 19:34:22 openqaworker9 openqa-worker-cacheservice-minion[3240]: [24736] [i] [#1354] Downloading: "SLE-15-SP1-Installer-DVD-x86_64-GM-DVD1.iso"
Nov 09 19:34:22 openqaworker9 openqa-worker-cacheservice-minion[3240]: [24736] [i] [#1354] Cache size of "/var/lib/openqa/cache" is 47GiB, with limit 50GiB
Nov 09 19:34:22 openqaworker9 openqa-worker-cacheservice-minion[3240]: [24736] [i] [#1354] Downloading "SLE-15-SP1-Installer-DVD-x86_64-GM-DVD1.iso" from "http://openqa.suse.de/tests/4962171/asset/iso/SLE-15-SP1-Installer-DVD-x86_64-GM-DVD1.iso"
Nov 09 19:34:22 openqaworker9 openqa-worker-cacheservice-minion[3240]: [24736] [i] [#1354] Content of "/var/lib/openqa/cache/openqa.suse.de/SLE-15-SP1-Installer-DVD-x86_64-GM-DVD1.iso" has not changed, updating last use
Nov 09 19:34:22 openqaworker9 openqa-worker-cacheservice-minion[3240]: [24736] [i] [#1354] Finished download
Nov 09 19:34:32 openqaworker9 openqa-worker-cacheservice-minion[3240]: [24797] [i] [#1355] Sync: "rsync://openqa.suse.de/tests" to "/var/lib/openqa/cache/openqa.suse.de"
Nov 09 19:34:32 openqaworker9 openqa-worker-cacheservice-minion[3240]: [24797] [i] [#1355] Calling: rsync -avHP rsync://openqa.suse.de/tests/ --delete /var/lib/openqa/cache/openqa.suse.de/tests/
Nov 09 19:34:33 openqaworker9 openqa-worker-cacheservice-minion[3240]: [24797] [i] [#1355] Finished sync: 0
Nov 09 19:36:01 openqaworker9 openqa-worker-cacheservice-minion[3240]: [14671] [i] [#1339] Cache size 47GiB + needed 9.9GiB exceeds limit of 50GiB, purging least used assets
Nov 09 19:36:01 openqaworker9 openqa-worker-cacheservice-minion[3240]: [14671] [i] [#1339] Purging "/var/lib/openqa/cache/openqa.suse.de/SLE-12-SP4-SAP-DVD-x86_64-GM-DVD1.iso" because we need space for new assets, reclaiming 4.1GiB
Nov 09 19:36:01 openqaworker9 openqa-worker-cacheservice-minion[3240]: [14671] [i] [#1339] Purging "/var/lib/openqa/cache/openqa.suse.de/sle-12-SP5-x86_64-:17046:kernel-ec2-Server-DVD-Incidents-Kernel@64bit-with-ltp.qcow2" because we need space for new assets, reclaiming 2GiB
Nov 09 19:36:01 openqaworker9 openqa-worker-cacheservice-minion[3240]: [14671] [i] [#1339] Purging "/var/lib/openqa/cache/openqa.suse.de/SLES-12-SP3-x86_64-mru-install-minimal-with-addons-Build:17088:openldap2-Server-DVD-Incidents-64bit.qcow2" because we need space for new assets, reclaiming 1GiB
Nov 09 19:36:01 openqaworker9 openqa-worker-cacheservice-minion[3240]: [14671] [i] [#1339] Purging "/var/lib/openqa/cache/openqa.suse.de/SLE-12-SP3-Server-DVD-x86_64-GM-DVD1.iso" because we need space for new assets, reclaiming 3.6GiB
Nov 09 19:36:01 openqaworker9 openqa-worker-cacheservice-minion[3240]: [14671] [i] [#1339] Size of "/var/lib/openqa/cache/openqa.suse.de/SLE-15-SP2-Installer-DVD-x86_64-GM-DVD1.iso" is 9.9GiB, with ETag ""279000000-5b1a5e45390d0""
Nov 09 19:36:01 openqaworker9 openqa-worker-cacheservice-minion[3240]: [14671] [i] [#1339] Download of "/var/lib/openqa/cache/openqa.suse.de/SLE-15-SP2-Installer-DVD-x86_64-GM-DVD1.iso" successful, new cache size is 47GiB
Nov 09 19:36:01 openqaworker9 openqa-worker-cacheservice-minion[3240]: [14671] [i] [#1339] Finished download

That the asset is purged to make room for itself is really stupid. I suppose we can at least prevent this case in a simple way.

PR merged.

mkittler wrote:

It would also make sense to generally preserve assets while being downloaded.

can you explain that further?

I believe currently an asset might be purged even during its download. I'm not 100 % sure but I suppose this is so far only avoided by preferring the oldest assets when purging. However, an asset "ages" already during its download and as we've seen that might be enough so that the asset is purged right after its own download. The current fix only ensures that the very stupid case of purging an asset to make room for itself is prevented. However, the purging might have as well be triggered by a concurrent download and in this case we would have still purged the asset.

So I'd introduce a pending flag and prevent such assets from being purged. The pending flag would be unset after the download when we currently already bump the "last use". Likely we should also clear the flag on the service startup to avoid leftovers.

mkittler wrote:

I believe currently an asset might be purged even during its download. I'm not 100 % sure but I suppose this is so far only avoided by preferring the oldest assets when purging. However, an asset "ages" already during its download and as we've seen that might be enough so that the asset is purged right after its own download. The current fix only ensures that the very stupid case of purging an asset to make room for itself is prevented. However, the purging might have as well be triggered by a concurrent download and in this case we would have still purged the asset.

Yes, i believe you are correct. If assets age so fast that they expire while they are still being downloaded that that could actually happen.

So I'd introduce a pending flag and prevent such assets from being purged. The pending flag would be unset after the download when we currently already bump the "last use". Likely we should also clear the flag on the service startup to avoid leftovers.

Flagged entries would be incomplete, so they could just be removed to avoid other side effects.

PR: https://github.com/os-autoinst/openQA/pull/3545

On o3 some jobs are incomplete because of setup failure: Cache service status error 500: Internal Server Error. Not sure if it's related to the pr#3545.
An example: https://openqa.opensuse.org/tests/1469375#

My conclusion so far: The migration added by PR might have the existing problems with corrupted SQLite databases worse. However, the migration and queries generally work in production. By the way, the migration worked on other updated worker hosts and I couldn't reproduce it locally as well.

Just for the record, the error messages look like this on the worker host:

Nov 13 03:33:33 openqaworker4 openqa-workercache-daemon[2288]: [2425] [i] Worker 2425 started
Nov 13 03:33:38 openqaworker4 openqa-workercache-daemon[2288]: [2425] [e] [M7EWttEz] DBD::SQLite::st execute failed: database disk image is malformed at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/SQLite.pm line 115.
Nov 13 03:33:38 openqaworker4 openqa-workercache-daemon[2288]:  at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/SQLite.pm line 115.
Nov 13 03:33:38 openqaworker4 openqa-workercache-daemon[2288]: [2422] [e] [qyZyZIUC] DBD::SQLite::st execute failed: database disk image is malformed at /usr/lib/perl5/vendor_perl/5.26.1/Minion/Backend/SQLite.pm line 363.
Nov 13 03:33:38 openqaworker4 openqa-workercache-daemon[2288]:  at /usr/lib/perl5/vendor_perl/5.26.1/Minion/Backend/SQLite.pm line 363.
Nov 13 03:33:38 openqaworker4 openqa-workercache-daemon[2288]: [2422] [e] [sEiUhW7b] DBD::SQLite::st execute failed: database disk image is malformed at /usr/lib/perl5/vendor_perl/5.26.1/Minion/Backend/SQLite.pm line 363.
Nov 13 03:33:38 openqaworker4 openqa-workercache-daemon[2288]:  at /usr/lib/perl5/vendor_perl/5.26.1/Minion/Backend/SQLite.pm line 363.
Nov 13 03:38:05 openqaworker4 openqa-workercache-daemon[2288]: [2424] [e] [wJIj5DWB] DBD::SQLite::st execute failed: database disk image is malformed at /usr/lib/perl5/vendor_perl/5.26.1/Minion/Backend/SQLite.pm line 138.
Nov 13 03:38:05 openqaworker4 openqa-workercache-daemon[2288]:  at /usr/lib/perl5/vendor_perl/5.26.1/Minion/Backend/SQLite.pm line 138.
Nov 13 11:12:55 openqaworker4 systemd[1]: Stopping OpenQA Worker Cache Service...
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[2288]: [2288] [w] Stopping worker 2424 immediately
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[2288]: [2288] [w] Stopping worker 2422 immediately
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[2288]: [2288] [w] Stopping worker 2425 immediately
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[2288]: [2288] [w] Stopping worker 2423 immediately
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[2288]: [2288] [i] Worker 2425 stopped
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[2288]: [2288] [i] Worker 2424 stopped
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[2288]: [2288] [w] Stopping worker 2424 immediately
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[2288]: [2288] [w] Stopping worker 2422 immediately
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[2288]: [2288] [w] Stopping worker 2423 immediately
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[2288]: [2288] [i] Worker 2422 stopped
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[2288]: [2288] [w] Stopping worker 2423 immediately
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[2288]: [2288] [i] Worker 2423 stopped
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[2288]: [2288] [i] Manager 2288 stopped
Nov 13 11:12:55 openqaworker4 systemd[1]: Stopped OpenQA Worker Cache Service.

Even after restarting I still got

Nov 13 11:12:55 openqaworker4 systemd[1]: Started OpenQA Worker Cache Service.
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[3805]: [3805] [i] [gAI627UE] Purging "foo" because it appears pending after service startup
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[3805]: [3805] [i] [gAI627UE] Cache size of "/var/lib/openqa/cache" is 8.6GiB, with limit 50GiB
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[3805]: [3805] [i] Listening at "http://127.0.0.1:9530"
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[3805]: [3805] [i] Listening at "http://[::1]:9530"
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[3805]: [3805] [i] Manager 3805 started
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[3805]: Web application available at http://127.0.0.1:9530
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[3805]: Web application available at http://[::1]:9530
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[3805]: [3809] [i] Worker 3809 started
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[3805]: [3810] [i] Worker 3810 started
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[3805]: [3811] [i] Worker 3811 started
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[3805]: [3805] [i] Creating process id file "/tmp/prefork.pid"
Nov 13 11:12:55 openqaworker4 openqa-workercache-daemon[3805]: [3812] [i] Worker 3812 started
Nov 13 11:20:28 openqaworker4 openqa-workercache-daemon[3805]: [3810] [e] [pA0QM9KS] DBD::SQLite::db prepare_cached failed: no such table: minion_jobs at /usr/lib/perl5/vendor_perl/5.26.1/Minion/Backend/SQLite.pm line 138.
Nov 13 11:20:38 openqaworker4 openqa-workercache-daemon[3805]: [3810] [e] [UB1x20qX] DBD::SQLite::db prepare_cached failed: no such table: minion_jobs at /usr/lib/perl5/vendor_perl/5.26.1/Minion/Backend/SQLite.pm line 363.
Nov 13 11:20:38 openqaworker4 openqa-workercache-daemon[3805]:  at /usr/lib/perl5/vendor_perl/5.26.1/Minion/Backend/SQLite.pm line 363.
Nov 13 11:20:40 openqaworker4 openqa-workercache-daemon[3805]: [3810] [e] [XywseRLg] DBD::SQLite::db prepare_cached failed: no such table: minion_jobs at /usr/lib/perl5/vendor_perl/5.26.1/Minion/Backend/SQLite.pm line 363.
Nov 13 11:20:40 openqaworker4 openqa-workercache-daemon[3805]:  at /usr/lib/perl5/vendor_perl/5.26.1/Minion/Backend/SQLite.pm line 363.

That's the log of the -minion service at the same time:

Nov 13 03:37:57 openqaworker4 openqa-worker-cacheservice-minion[2289]: [2490] [i] [#165669] Size of "/var/lib/openqa/cache/openqa1-opensuse/openSUSE-Staging-DVD-x86_64.qcow2" is 2.4GiB, with ETag ""9744fe00-553b4174305b3""
Nov 13 03:37:57 openqaworker4 openqa-worker-cacheservice-minion[2289]: [2490] [i] [#165669] Download of "/var/lib/openqa/cache/openqa1-opensuse/openSUSE-Staging-DVD-x86_64.qcow2" successful, new cache size is 8.6GiB
Nov 13 03:37:57 openqaworker4 openqa-worker-cacheservice-minion[2289]: [2490] [i] [#165669] Finished download
Nov 13 03:38:05 openqaworker4 openqa-worker-cacheservice-minion[2289]: DBD::SQLite::st execute failed: database disk image is malformed at /usr/lib/perl5/vendor_perl/5.26.1/Minion/Backend/SQLite.pm line 422.
Nov 13 03:38:05 openqaworker4 openqa-worker-cacheservice-minion[2289]:  at /usr/lib/perl5/vendor_perl/5.26.1/Minion/Backend/SQLite.pm line 422.
Nov 13 03:38:05 openqaworker4 openqa-worker-cacheservice-minion[2289]:  at /usr/lib/perl5/vendor_perl/5.26.1/Minion/Command/minion/worker.pm line 26.
Nov 13 03:38:05 openqaworker4 systemd[1]: openqa-worker-cacheservice-minion.service: Main process exited, code=exited, status=4/NOPERMISSION
Nov 13 03:38:05 openqaworker4 systemd[1]: openqa-worker-cacheservice-minion.service: Unit entered failed state.
Nov 13 03:38:05 openqaworker4 systemd[1]: openqa-worker-cacheservice-minion.service: Failed with result 'exit-code'.
Nov 13 03:38:05 openqaworker4 systemd[1]: openqa-worker-cacheservice-minion.service: Service RestartSec=100ms expired, scheduling restart.
Nov 13 03:38:05 openqaworker4 systemd[1]: Stopped OpenQA Worker Cache Service Minion.
Nov 13 03:38:05 openqaworker4 systemd[1]: Started OpenQA Worker Cache Service Minion.
Nov 13 03:38:05 openqaworker4 openqa-worker-cacheservice-minion[2517]: [2517] [i] [7csBjR0R] Purging "/var/lib/openqa/cache/openqa1-opensuse/openSUSE-Staging:K-Tumbleweed-DVD-x86_64-Build246.1-Media.iso" because it appears pending after service startup
Nov 13 03:38:05 openqaworker4 openqa-worker-cacheservice-minion[2517]: [2517] [i] [7csBjR0R] Purging "/var/lib/openqa/cache/openqa1-opensuse/openSUSE-Staging:B-Tumbleweed-DVD-x86_64-Build355.20-Media.iso" because it appears pending after service startup
Nov 13 03:38:05 openqaworker4 openqa-worker-cacheservice-minion[2517]: [2517] [i] [7csBjR0R] Cache size of "/var/lib/openqa/cache" is 8.6GiB, with limit 50GiB
Nov 13 03:38:05 openqaworker4 openqa-worker-cacheservice-minion[2517]: [2517] [i] Resetting all leftover locks after restart
Nov 13 03:38:05 openqaworker4 openqa-worker-cacheservice-minion[2517]: [2517] [i] Worker 2517 started
Nov 13 03:38:05 openqaworker4 openqa-worker-cacheservice-minion[2517]: DBD::SQLite::st execute failed: database disk image is malformed at /usr/lib/perl5/vendor_perl/5.26.1/Minion/Backend/SQLite.pm line 422.
Nov 13 03:38:05 openqaworker4 openqa-worker-cacheservice-minion[2517]:  at /usr/lib/perl5/vendor_perl/5.26.1/Minion/Backend/SQLite.pm line 422.
Nov 13 03:38:05 openqaworker4 openqa-worker-cacheservice-minion[2517]:  at /usr/lib/perl5/vendor_perl/5.26.1/Minion/Command/minion/worker.pm line 26.
Nov 13 03:38:05 openqaworker4 systemd[1]: openqa-worker-cacheservice-minion.service: Main process exited, code=exited, status=255/n/a
Nov 13 03:38:05 openqaworker4 systemd[1]: openqa-worker-cacheservice-minion.service: Unit entered failed state.
Nov 13 03:38:05 openqaworker4 systemd[1]: openqa-worker-cacheservice-minion.service: Failed with result 'exit-code'.
…
Nov 13 11:14:16 openqaworker4 systemd[1]: Stopped OpenQA Worker Cache Service Minion.
Nov 13 11:14:16 openqaworker4 systemd[1]: Started OpenQA Worker Cache Service Minion.
Nov 13 11:14:17 openqaworker4 openqa-worker-cacheservice-minion[3842]: [3842] [i] [_VrdFEyu] Cache size of "/var/lib/openqa/cache" is 8.6GiB, with limit 50GiB
Nov 13 11:14:17 openqaworker4 openqa-worker-cacheservice-minion[3842]: [3842] [i] Resetting all leftover locks after restart
Nov 13 11:14:17 openqaworker4 openqa-worker-cacheservice-minion[3842]: [3842] [i] Worker 3842 started
Nov 13 11:14:17 openqaworker4 openqa-worker-cacheservice-minion[3842]: DBD::SQLite::st execute failed: database disk image is malformed at /usr/lib/perl5/vendor_perl/5.26.1/Minion/Backend/SQLite.pm line 301.
Nov 13 11:14:17 openqaworker4 openqa-worker-cacheservice-minion[3842]:  at /usr/lib/perl5/vendor_perl/5.26.1/Minion/Backend/SQLite.pm line 301.
Nov 13 11:14:17 openqaworker4 openqa-worker-cacheservice-minion[3842]:  at /usr/lib/perl5/vendor_perl/5.26.1/Minion/Command/minion/worker.pm line 26.
Nov 13 11:14:17 openqaworker4 systemd[1]: openqa-worker-cacheservice-minion.service: Main process exited, code=exited, status=255/n/a
Nov 13 11:14:17 openqaworker4 systemd[1]: openqa-worker-cacheservice-minion.service: Unit entered failed state.
Nov 13 11:14:17 openqaworker4 systemd[1]: openqa-worker-cacheservice-minion.service: Failed with result 'exit-code'.
Nov 13 11:14:17 openqaworker4 systemd[1]: openqa-worker-cacheservice-minion.service: Service RestartSec=100ms expired, scheduling restart.
Nov 13 11:14:17 openqaworker4 systemd[1]: Stopped OpenQA Worker Cache Service Minion.
Nov 13 11:14:17 openqaworker4 systemd[1]: openqa-worker-cacheservice-minion.service: Start request repeated too quickly.
Nov 13 11:14:17 openqaworker4 systemd[1]: Failed to start OpenQA Worker Cache Service Minion.
Nov 13 11:14:17 openqaworker4 systemd[1]: openqa-worker-cacheservice-minion.service: Unit entered failed state.
Nov 13 11:14:17 openqaworker4 systemd[1]: openqa-worker-cacheservice-minion.service: Failed with result 'exit-code'.
Nov 13 12:05:10 openqaworker4 systemd[1]: Started OpenQA Worker Cache Service Minion.
Nov 13 12:05:10 openqaworker4 openqa-worker-cacheservice-minion[3974]: [3974] [i] [hhbV1BD_] Purging "/var/lib/openqa/cache/openqa1-opensuse/openSUSE-Staging-DVD-x86_64.qcow2" because the asset is not registered
Nov 13 12:05:10 openqaworker4 openqa-worker-cacheservice-minion[3974]: [3974] [i] [hhbV1BD_] Purging "/var/lib/openqa/cache/openqa1-opensuse/openSUSE-Staging:J-Kubic-DVD-x86_64-Build324.2-Media.iso" because the asset is not registered
Nov 13 12:05:10 openqaworker4 openqa-worker-cacheservice-minion[3974]: [3974] [i] [hhbV1BD_] Purging "/var/lib/openqa/cache/openqa1-opensuse/openSUSE-Staging:J-MicroOS-DVD-x86_64-Build324.4-Media.iso" because the asset is not registered
Nov 13 12:05:11 openqaworker4 openqa-worker-cacheservice-minion[3974]: [3974] [i] [hhbV1BD_] Purging "/var/lib/openqa/cache/openqa1-opensuse/openSUSE-Staging:J-Tumbleweed-DVD-x86_64-Build324.5-Media.iso" because the asset is not registered
Nov 13 12:05:11 openqaworker4 openqa-worker-cacheservice-minion[3974]: [3974] [i] [hhbV1BD_] Cache size of "/var/lib/openqa/cache" is 0 Byte, with limit 50GiB
Nov 13 12:05:11 openqaworker4 openqa-worker-cacheservice-minion[3974]: [3974] [i] Resetting all leftover locks after restart
Nov 13 12:05:11 openqaworker4 openqa-worker-cacheservice-minion[3974]: [3974] [i] Worker 3974 started
Nov 13 12:07:43 openqaworker4 systemd[1]: Stopping OpenQA Worker Cache Service Minion...
Nov 13 12:07:46 openqaworker4 openqa-worker-cacheservice-minion[3974]: [3974] [i] Worker 3974 stopped
Nov 13 12:07:46 openqaworker4 systemd[1]: Stopped OpenQA Worker Cache Service Minion.
Nov 13 12:07:46 openqaworker4 systemd[1]: Started OpenQA Worker Cache Service Minion.
Nov 13 12:07:46 openqaworker4 openqa-worker-cacheservice-minion[4002]: [4002] [i] [y4Mp0J15] Cache size of "/var/lib/openqa/cache" is 0 Byte, with limit 50GiB
Nov 13 12:07:46 openqaworker4 openqa-worker-cacheservice-minion[4002]: [4002] [i] Resetting all leftover locks after restart
Nov 13 12:07:46 openqaworker4 openqa-worker-cacheservice-minion[4002]: [4002] [i] Worker 4002 started
Nov 13 12:07:52 openqaworker4 openqa-worker-cacheservice-minion[4002]: [4013] [i] [#1] Downloading: "openSUSE-Staging:F-Tumbleweed-DVD-x86_64-Build463.6-Media.iso.sha256"
Nov 13 12:07:52 openqaworker4 openqa-worker-cacheservice-minion[4002]: [4013] [i] [#1] Cache size of "/var/lib/openqa/cache" is 0 Byte, with limit 50GiB
Nov 13 12:07:52 openqaworker4 openqa-worker-cacheservice-minion[4002]: [4013] [i] [#1] Downloading "openSUSE-Staging:F-Tumbleweed-DVD-x86_64-Build463.6-Media.iso.sha256" from "http://openqa1-opensuse/tests/1470110/asset/other/openSUSE-Staging:F-Tumbleweed-DVD-x86_64-Build463.6-Media.iso.sha256"
Nov 13 12:07:52 openqaworker4 openqa-worker-cacheservice-minion[4002]: [4013] [i] [#1] Size of "/var/lib/openqa/cache/openqa1-opensuse/openSUSE-Staging:F-Tumbleweed-DVD-x86_64-Build463.6-Media.iso.sha256" is 118 Byte, with ETag ""76-5b3fad73dbfeb""
Nov 13 12:07:52 openqaworker4 openqa-worker-cacheservice-minion[4002]: [4013] [i] [#1] Download of "/var/lib/openqa/cache/openqa1-opensuse/openSUSE-Staging:F-Tumbleweed-DVD-x86_64-Build463.6-Media.iso.sha256" successful, new cache size is 118 Byte
Nov 13 12:07:52 openqaworker4 openqa-worker-cacheservice-minion[4002]: [4013] [i] [#1] Finished download

After restarting the -minion service, the openqa-workercache service works again as well:

Nov 13 12:07:46 openqaworker4 systemd[1]: Stopping OpenQA Worker Cache Service...
Nov 13 12:07:46 openqaworker4 openqa-workercache-daemon[3805]: [3805] [w] Stopping worker 3811 immediately
Nov 13 12:07:46 openqaworker4 openqa-workercache-daemon[3805]: [3805] [w] Stopping worker 3812 immediately
Nov 13 12:07:46 openqaworker4 openqa-workercache-daemon[3805]: [3805] [w] Stopping worker 3809 immediately
Nov 13 12:07:46 openqaworker4 openqa-workercache-daemon[3805]: [3805] [w] Stopping worker 3810 immediately
Nov 13 12:07:46 openqaworker4 openqa-workercache-daemon[3805]: [3805] [i] Worker 3810 stopped
Nov 13 12:07:46 openqaworker4 openqa-workercache-daemon[3805]: [3805] [i] Worker 3811 stopped
Nov 13 12:07:46 openqaworker4 openqa-workercache-daemon[3805]: [3805] [i] Worker 3812 stopped
Nov 13 12:07:46 openqaworker4 openqa-workercache-daemon[3805]: [3805] [w] Stopping worker 3809 immediately
Nov 13 12:07:46 openqaworker4 openqa-workercache-daemon[3805]: [3805] [i] Worker 3809 stopped
Nov 13 12:07:46 openqaworker4 openqa-workercache-daemon[3805]: [3805] [i] Manager 3805 stopped
Nov 13 12:07:46 openqaworker4 systemd[1]: Stopped OpenQA Worker Cache Service.
Nov 13 12:07:46 openqaworker4 systemd[1]: Started OpenQA Worker Cache Service.
Nov 13 12:07:46 openqaworker4 openqa-workercache-daemon[4001]: [4001] [i] [sGYWrUvD] Cache size of "/var/lib/openqa/cache" is 0 Byte, with limit 50GiB
Nov 13 12:07:46 openqaworker4 openqa-workercache-daemon[4001]: [4001] [i] Listening at "http://127.0.0.1:9530"
Nov 13 12:07:46 openqaworker4 openqa-workercache-daemon[4001]: [4001] [i] Listening at "http://[::1]:9530"
Nov 13 12:07:46 openqaworker4 openqa-workercache-daemon[4001]: [4001] [i] Manager 4001 started
Nov 13 12:07:46 openqaworker4 openqa-workercache-daemon[4001]: Web application available at http://127.0.0.1:9530
Nov 13 12:07:46 openqaworker4 openqa-workercache-daemon[4001]: Web application available at http://[::1]:9530
Nov 13 12:07:46 openqaworker4 openqa-workercache-daemon[4001]: [4005] [i] Worker 4005 started
Nov 13 12:07:46 openqaworker4 openqa-workercache-daemon[4001]: [4006] [i] Worker 4006 started
Nov 13 12:07:46 openqaworker4 openqa-workercache-daemon[4001]: [4007] [i] Worker 4007 started
Nov 13 12:07:46 openqaworker4 openqa-workercache-daemon[4001]: [4001] [i] Creating process id file "/tmp/prefork.pid"
Nov 13 12:07:46 openqaworker4 openqa-workercache-daemon[4001]: [4008] [i] Worker 4008 started

Purging cache directory because database has been corrupted has never been logged. So the recovery did not involve deleting the SQLite file and the errors occurred during the runtime of the services (and not at startup). At any time I've tried to access the database file via sqlite3 I didn't run into any problems. I also inserted some data for testing the queries my PR used manually. That's the reason for the Purging "foo" messages.

I would not revert the PR but keep monitoring the situation. Likely the problem won't re-occur because the migration only runs once (if the problem was even related to the PR at all). A simple restart of both services (openqa-workercache and openqa-workercache-minion) should help if the issue neverthless re-occurs. I didn't need to remove the SQLite database but if the restart doesn't help one can still try rm /var/lib/openqa/cache/cache.sqlite* (and restart the services again). Before deleting, please backup the old files for investigation purposes. Use a different directory to store the backup because the services will wipe out the cache directory. Also backup the -wal and -shm files.

After OSD is deployed today, this issue happens again.
I backup the sqlite files in openqaworker6
sudo cp cache/cache.sqlite* cache_backup/
If you need to check the files, you could find them in /var/lib/openqa/cache_backup/ on worker6