QA » openQA Project » openQA Infrastructure

https://suse.slack.com/archives/C02CANHLANP/p1720597353583009

@mkittler is looking into restarting affected incompletes.

Apparently we missed at least one job: https://openqa.suse.de/tests/14875989

host=openqa.suse.de ./openqa-advanced-retrigger-jobs

So this script may not be re-triggering deps correctly.

Decided to hotpatch /usr/share/openqa/lib/OpenQA/WebAPI.pm and uncomment the streaming route as the live view seems to be the underlying cause and we can't currently limit it, meaning a high enough number of live viewers is enough to break the web UI.
This is not persistent as of now.

A long-term solution may be making the live view a separate service so it can't block other requests.

This is not persistent as of now.

https://gitlab.suse.de/openqa/osd-deployment/-/pipeline_schedules is also inactive as of right now to avoid the hotpatch from being reverted.

This is not persistent as of now.

https://gitlab.suse.de/openqa/osd-deployment/-/pipeline_schedules is also inactive as of right now to avoid the hotpatch from being reverted.

Also sudo systemctl stop auto-update.timer

https://github.com/os-autoinst/openQA/pull/5754

I'm seeing a lot of these messages:

Jul 11 16:45:01 openqa openqa[1576]: [error] Publishing suse.openqa.job.create failed: Connect timeout (7 attempts left)
[...]
Jul 11 17:24:47 openqa openqa[30656]: [error] Publishing suse.openqa.job.create failed: Connect timeout (5 attempts left)

Also a lot of these errors, which I was also wondering if they were affecting #162038#note-19 except I don't know what they mean:

Jul 11 16:48:21 openqa wickedd[912]: rtnetlink event receive error: Out of memory (No buffer space available)                                                         
Jul 11 16:48:21 openqa wickedd[912]: restarted rtnetlink event listener

There are not many incompletes as of today:

openqa=> select count(id), array_agg(id), reason from jobs where t_finished >= '2024-07-12T00:00:00' and result = 'incomplete' group by reason order by count(id) desc;
 count |                                                                array_agg                                                                 |                                                                                                                                                                         
 reason                                                                                                                                                                           
-------+------------------------------------------------------------------------------------------------------------------------------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
    15 | {14907486,14908052,14908265,14908038,14908189,14907472,14907444,14907764,14908087,14908089,14908013,14908232,14908020,14907691,14907493} | api failure: 502 response: Bad Gateway
    11 | {14911322,14911454,14911321,14911265,14911203,14907686,14910421,14911434,14911437,14911451,14911105}                                     | tests died: unable to load main.pm, check the log for the cause (e.g. syntax error)
     7 | {14912021,14907393,14908650,14907389,14908659,14908639,14908671}                                                                         | cache failure: Failed to download SLE-15-SP5-Full-x86_64-GM-Media1.iso to /var/lib/openqa/cache/openqa.suse.de/SLE-15-SP5-Full-x86_64-GM-Media1.iso [Auto-restarting bec
ause reason matches the configured "auto_clone_regex".]
     7 | {14904395,14908635,14904400,14910543,14907819,14909239,14910628}                                                                         | backend died: QEMU exited unexpectedly, see log for details
     4 | {14908227,14908325,14908716,14908823}                                                                                                    | backend died: QEMU terminated before QMP connection could be established. Check for errors below
     2 | {14907730,14910524}                                                                                                                      | tests died: unable to load tests/network/samba/samba_adcli.pm, check the log for the cause (e.g. syntax error)
     2 | {14909169,14910545}                                                                                                                      | asset failure: Failed to download autoyast_SLES-15-SP5-x86_64-create_hdd_yast_maintenance_minimal-Build20240711-1-Server-DVD-Updates-64bit.qcow2 to /var/lib/openqa/cach
e/openqa.suse.de/autoyast_SLES-15-SP5-x86_64-create_hdd_yast_maintenance_minimal-Build20240711-1-Server-DVD-Updates-64bit.qcow2
     2 | {14908644,14908631}                                                                                                                      | cache failure: Failed to download SLE-15-SP3-Full-x86_64-GM-Media1.iso to /var/lib/openqa/cache/openqa.suse.de/SLE-15-SP3-Full-x86_64-GM-Media1.iso [Auto-restarting bec
ause reason matches the configured "auto_clone_regex".]
     2 | {14908247,14908234}                                                                                                                      | cache failure: Failed to download supp_sles12sp5-x86_64.qcow2 to /var/lib/openqa/cache/openqa.suse.de/supp_sles12sp5-x86_64.qcow2 [Auto-restarting because reason matche
s the configured "auto_clone_regex".]
     2 | {14906823,14906891}                                                                                                                      | died: terminated prematurely, see log output for details
     1 | {14911446}                                                                                                                               | backend died: Error connecting to VNC server <s390kvm110.oqa.prg2.suse.org:5901>: IO::Socket::INET: connect: No route to host
     1 | {14877886}                                                                                                                               | abandoned: associated worker worker29:6 re-connected but abandoned the job
     1 | {14903610}                                                                                                                               | abandoned: associated worker sapworker3:22 re-connected but abandoned the job
     1 | {14909708}                                                                                                                               | backend died: unexpected end of data at /usr/lib/os-autoinst/consoles/VNC.pm line 842.
     1 | {14906618}                                                                                                                               | abandoned: associated worker openqaworker-arm-1:1 re-connected but abandoned the job
     1 | {14906515}                                                                                                                               | abandoned: associated worker openqaworker-arm-1:7 re-connected but abandoned the job
     1 | {14907413}                                                                                                                               | cache failure: Failed to download SLE-15-SP5-x86_64-Build20240711-1-qam-sles4sap-gnome.qcow2 to /var/lib/openqa/cache/openqa.suse.de/SLE-15-SP5-x86_64-Build20240711-1-q
am-sles4sap-gnome.qcow2 [Auto-restarting because reason matches the configured "auto_clone_regex".]
     1 | {14907521}                                                                                                                               | cache failure: Failed to download SLES-12-SP3-x86_64-20240711-1@64bit-minimal_with_sdkGM_xfstests.qcow2 to /var/lib/openqa/cache/openqa.suse.de/SLES-12-SP3-x86_64-20240
711-1@64bit-minimal_with_sdkGM_xfstests.qcow2 [Auto-restarting because reason matches the configured "auto_clone_regex".]
     1 | {14908653}                                                                                                                               | cache failure: Failed to download SLES-15-SP2-x86_64-mru-install-desktop-with-addons-Build20240711-1.qcow2 to /var/lib/openqa/cache/openqa.suse.de/SLES-15-SP2-x86_64-mr
u-install-desktop-with-addons-Build20240711-1.qcow2 [Auto-restarting because reason matches the configured "auto_clone_regex".]
     1 | {14908685}                                                                                                                               | cache failure: Failed to download SLES-15-SP2-x86_64-mru-install-minimal-with-addons-Build20240711-1-Server-DVD-Updates-64bit.qcow2 to /var/lib/openqa/cache/openqa.suse
.de/SLES-15-SP2-x86_64-mru-install-minimal-with-addons-Build20240711-1-Server-DVD-Updates-64bit.qcow2 [Auto-restarting because reason matches the configured "auto_clone_regex".]
     1 | {14907914}                                                                                                                               | cache failure: Failed to download openqa_support_server_sles12sp3_multipath.x86_64.qcow2 to /var/lib/openqa/cache/openqa.suse.de/openqa_support_server_sles12sp3_multipa
th.x86_64.qcow2 [Auto-restarting because reason matches the configured "auto_clone_regex".]
     1 | {14912120}                                                                                                                               | asset failure: Failed to download autoyast-SLES-15-SP5-x86_64-textmode-updated.qcow2 to /var/lib/openqa/cache/openqa.suse.de/autoyast-SLES-15-SP5-x86_64-textmode-update
d.qcow2
     1 | {14895992}                                                                                                                               | abandoned: associated worker openqaworker-arm-1:3 re-connected but abandoned the job
     1 | {14912123}                                                                                                                               | asset failure: Failed to download publiccloud_15-SP2_Azure-BYOS-Updates-x86_64.qcow2 to /var/lib/openqa/cache/openqa.suse.de/publiccloud_15-SP2_Azure-BYOS-Updates-x86_6
4.qcow2
     1 | {14911432}                                                                                                                               | backend died: Error connecting to VNC server <s390kvm105.oqa.prg2.suse.org:5901>: IO::Socket::INET: connect: No route to host
(25 rows)

In particular, there are no further incompletes due to unknown API errors, "premature connection close" or due to timestamp mismatches.

Yesterday it was a whole different story:

openqa=> select count(id), reason from jobs where t_finished >= '2024-07-11T00:00:00' and t_finished < '2024-07-12T00:00:00' and result = 'incomplete' group by reason order by count(id) desc limit 10;
 count |                                                                                                                  reason                                                                                                                   
-------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
   150 | api failure
    67 | api failure: Connection error: Premature connection close
    36 | api failure: 403 response: timestamp mismatch - check whether clocks on the local host and the web UI host are in sync
    24 | quit: worker has been stopped or restarted
    20 | cache failure: Failed to download SLE-15-SP4-Full-x86_64-GM-Media1.iso to /var/lib/openqa/cache/openqa.suse.de/SLE-15-SP4-Full-x86_64-GM-Media1.iso [Auto-restarting because reason matches the configured "auto_clone_regex".]
    15 | isotovideo died: Unable to clone Git repository 'https://github.com/frankenmichl/os-autoinst-distri-opensuse/tree/nfs_baremetal' specified via CASEDIR (see log for details) at /usr/lib/os-autoinst/OpenQA/Isotovideo/Utils.pm line 164.
    14 | cache failure: Failed to download SLE-15-SP5-Full-x86_64-GM-Media1.iso to /var/lib/openqa/cache/openqa.suse.de/SLE-15-SP5-Full-x86_64-GM-Media1.iso [Auto-restarting because reason matches the configured "auto_clone_regex".]
    10 | api failure: Connection error: Connection timed out
     9 | cache failure: Failed to download SLE-15-SP6-Full-x86_64-GM-Media1.iso to /var/lib/openqa/cache/openqa.suse.de/SLE-15-SP6-Full-x86_64-GM-Media1.iso [Auto-restarting because reason matches the configured "auto_clone_regex".]
     9 | asset failure: Failed to download sle-15-SP6-x86_64-GM-with-hpc.qcow2 to /var/lib/openqa/cache/openqa.suse.de/sle-15-SP6-x86_64-GM-with-hpc.qcow2

Note that all timestamps in the following comment from Grafana and the journal are CEST and all timestamps from the database UTC.

The alert was firing again today from 2024-07-15 01:00:09 to 2024-07-15 01:01:02 (https://stats.openqa-monitor.qa.suse.de/d/WebuiDb/webui-summary?orgId=1&viewPanel=78&from=1720993478167&to=1721003987228). Otherwise there were no further alerts over the weekend (also no pending ones).

I investigated the logs which are also attached to #163928.

The websocker server is very verbose so the first thing to notice are the many "Finishing current connection of worker … before accepting new one" messages:

Jul 15 01:04:33 openqa openqa-websockets-daemon[16477]: [debug] [pid:16477] Finishing current connection of worker 3016 before accepting new one
Jul 15 01:04:33 openqa openqa-websockets-daemon[16477]: [debug] [pid:16477] Finishing current connection of worker 2396 before accepting new one
Jul 15 01:04:33 openqa openqa-websockets-daemon[16477]: [info] [pid:16477] Worker 2558 websocket connection closed - 1008: only one connection per worker allowed, finishing old one in favor of new one
Jul 15 01:04:33 openqa openqa-websockets-daemon[16477]: [info] [pid:16477] Worker 3511 websocket connection closed - 1008: only one connection per worker allowed, finishing old one in favor of new one

And also:

Jul 15 01:04:34 openqa openqa-websockets-daemon[16477]: [info] [pid:16477] Received worker 3016 status too close to the last update, websocket server possibly overloaded or worker misconfigured
…
Jul 15 01:04:34 openqa openqa-websockets-daemon[16477]: [info] [pid:16477] Received worker 2559 status too close to the last update, websocket server possibly overloaded or worker misconfigured
…

This could be relevant - although this is just about the web socket server and should not impact normal API queries.

It looks like many services were started at this time and also asset cleanup was enqueued (but of course none of this is very unusual):

Jul 15 01:00:00 openqa systemd[1]: Starting Setup local PostgreSQL database for openQA...
Jul 15 01:00:00 openqa systemd[1]: Started Timeline of Snapper Snapshots.
Jul 15 01:00:00 openqa openqa-websockets-daemon[16477]: [debug] [pid:16477] Started to send message to 3080 for job(s) 14929376
Jul 15 01:00:00 openqa systemd[1]: Starting Rotate openQA log files...
Jul 15 01:00:00 openqa bash[7702]: ++ /usr/bin/systemctl is-active logrotate.service
Jul 15 01:00:00 openqa bash[7697]: + is_active=inactive
Jul 15 01:00:00 openqa bash[7697]: + [[ inactive == active ]]
Jul 15 01:00:00 openqa bash[7697]: + [[ inactive == activating ]]
Jul 15 01:00:00 openqa bash[7697]: + exit 0
Jul 15 01:00:00 openqa logrotate[7711]: reading config file /etc/logrotate.d/openqa
Jul 15 01:00:00 openqa logrotate[7711]: warning: 'size' overrides previously specified 'hourly'
Jul 15 01:00:00 openqa logrotate[7711]: compress_prog is now /usr/bin/xz
Jul 15 01:00:00 openqa logrotate[7711]: compress_ext was changed to .xz
Jul 15 01:00:00 openqa logrotate[7711]: uncompress_prog is now /usr/bin/xzdec
Jul 15 01:00:00 openqa logrotate[7711]: warning: 'size' overrides previously specified 'hourly'
Jul 15 01:00:00 openqa logrotate[7711]: compress_prog is now /usr/bin/xz
Jul 15 01:00:00 openqa logrotate[7711]: compress_ext was changed to .xz
Jul 15 01:00:00 openqa logrotate[7711]: uncompress_prog is now /usr/bin/xzdec
Jul 15 01:00:00 openqa dbus-daemon[813]: [system] Activating via systemd: service name='org.opensuse.Snapper' unit='snapperd.service' requested by ':1.171923' (uid=0 pid=7696 comm="/usr/lib/snapper/systemd-helper --timeline ")
Jul 15 01:00:00 openqa logrotate[7711]: reading config file /etc/logrotate.d/openqa-apache
Jul 15 01:00:00 openqa logrotate[7711]: warning: 'size' overrides previously specified 'hourly'
Jul 15 01:00:00 openqa logrotate[7711]: compress_prog is now /usr/bin/xz
Jul 15 01:00:00 openqa logrotate[7711]: compress_ext was changed to .xz
Jul 15 01:00:00 openqa logrotate[7711]: uncompress_prog is now /usr/bin/xzdec
Jul 15 01:00:00 openqa logrotate[7711]: Reading state from file: /var/lib/misc/logrotate.status
Jul 15 01:00:00 openqa logrotate[7711]: Allocating hash table for state file, size 64 entries
Jul 15 01:00:00 openqa logrotate[7711]: Creating new state
Jul 15 01:00:00 openqa logrotate[7711]: Creating new state
…
Jul 15 01:00:00 openqa logrotate[7711]: Creating new state
Jul 15 01:00:00 openqa openqa-websockets-daemon[16477]: [debug] [pid:16477] Started to send message to 3242 for job(s) 14929949
Jul 15 01:00:00 openqa systemd[1]: Starting DBus interface for snapper...
Jul 15 01:00:00 openqa logrotate[7711]: Creating new state
…
Jul 15 01:00:00 openqa logrotate[7711]: Creating new state
Jul 15 01:00:00 openqa logrotate[7711]: Handling 3 logs
Jul 15 01:00:00 openqa logrotate[7711]: rotating pattern: /var/log/openqa  307200000 bytes (20 rotations)
Jul 15 01:00:00 openqa logrotate[7711]: empty log files are not rotated, old logs are removed
Jul 15 01:00:00 openqa logrotate[7711]: considering log /var/log/openqa
Jul 15 01:00:00 openqa logrotate[7711]:   Now: 2024-07-15 01:00
Jul 15 01:00:00 openqa logrotate[7711]:   Last rotated at 2024-06-17 08:00
Jul 15 01:00:00 openqa logrotate[7711]:   log does not need rotating (log size is below the 'size' threshold)
Jul 15 01:00:00 openqa logrotate[7711]: rotating pattern: /var/log/openqa_scheduler /var/log/openqa_gru  30720000 bytes (20 rotations)
Jul 15 01:00:00 openqa logrotate[7711]: empty log files are not rotated, old logs are removed
Jul 15 01:00:00 openqa logrotate[7711]: considering log /var/log/openqa_scheduler
Jul 15 01:00:00 openqa logrotate[7711]:   Now: 2024-07-15 01:00
Jul 15 01:00:00 openqa logrotate[7711]:   Last rotated at 2024-07-14 08:00
Jul 15 01:00:00 openqa logrotate[7711]:   log does not need rotating (log size is below the 'size' threshold)
Jul 15 01:00:00 openqa logrotate[7711]: considering log /var/log/openqa_gru
Jul 15 01:00:00 openqa logrotate[7711]:   Now: 2024-07-15 01:00
Jul 15 01:00:00 openqa logrotate[7711]:   Last rotated at 2024-07-13 02:00
Jul 15 01:00:00 openqa logrotate[7711]:   log does not need rotating (log size is below the 'size' threshold)
Jul 15 01:00:00 openqa logrotate[7711]: rotating pattern: /var/log/apache2/openqa.access_log  307200000 bytes (20 rotations)
Jul 15 01:00:00 openqa logrotate[7711]: empty log files are not rotated, old logs are removed
Jul 15 01:00:00 openqa logrotate[7711]: considering log /var/log/apache2/openqa.access_log
Jul 15 01:00:00 openqa logrotate[7711]:   Now: 2024-07-15 01:00
Jul 15 01:00:00 openqa logrotate[7711]:   Last rotated at 2024-06-17 08:00
Jul 15 01:00:00 openqa logrotate[7711]:   log does not need rotating (log size is below the 'size' threshold)
Jul 15 01:00:00 openqa systemd[1]: openqa-setup-db.service: Deactivated successfully.
Jul 15 01:00:00 openqa openqa-websockets-daemon[16477]: [debug] [pid:16477] Started to send message to 3074 for job(s) 14929400
Jul 15 01:00:00 openqa systemd[1]: Finished Setup local PostgreSQL database for openQA.
Jul 15 01:00:00 openqa systemd[1]: Starting Enqueues an asset cleanup cleanup task for openQA....
…
Jul 15 01:00:03 openqa openqa-enqueue-asset-cleanup[7767]: {
Jul 15 01:00:03 openqa openqa-enqueue-asset-cleanup[7767]:   "gru_id" => 37922639,
Jul 15 01:00:03 openqa openqa-enqueue-asset-cleanup[7767]:   "minion_id" => 12136654
Jul 15 01:00:03 openqa openqa-enqueue-asset-cleanup[7767]: }
Jul 15 01:00:03 openqa systemd[1]: openqa-enqueue-asset-cleanup.service: Deactivated successfully.
Jul 15 01:00:03 openqa systemd[1]: Finished Enqueues an asset cleanup cleanup task for openQA..
…
Jul 15 01:00:19 openqa openqa-websockets-daemon[16477]: [debug] [pid:16477] Updating seen of worker 3319 from worker_status (free)
Jul 15 01:00:20 openqa telegraf[6820]: 2024-07-14T23:00:20Z E! [inputs.http] Error in plugin: [url=https://openqa.suse.de/admin/influxdb/jobs]: Get "https://openqa.suse.de/admin/influxdb/jobs": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
Jul 15 01:00:20 openqa telegraf[6820]: 2024-07-14T23:00:20Z E! [inputs.http] Error in plugin: [url=https://openqa.suse.de/admin/influxdb/minion]: Get "https://openqa.suse.de/admin/influxdb/minion": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
Jul 15 01:00:20 openqa openqa-websockets-daemon[16477]: [debug] [pid:16477] Updating seen of worker 3469 from worker_status (free)
…

We also had 130 "timestamp mismatch" jobs again over the weekend:

openqa=> select count(id), min(t_finished) as first_t_finished, max(t_finished) as last_t_finished, reason from jobs where t_finished >= '2024-07-12T18:00:00' and result = 'incomplete' group by reason order by count(id) desc; 
 count |  first_t_finished   |   last_t_finished   |                                                                                                                                                 reason                                                                                                                 

-------+---------------------+---------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------
   130 | 2024-07-14 22:48:13 | 2024-07-14 22:54:29 | api failure: 403 response: timestamp mismatch - check whether clocks on the local host and the web UI host are in sync
    16 | 2024-07-12 19:56:18 | 2024-07-15 00:19:31 | backend died: QEMU terminated before QMP connection could be established. Check for errors below
    13 | 2024-07-15 03:41:26 | 2024-07-15 08:39:35 | backend died: Error connecting to VNC server <openqaw5-xen.qe.prg2.suse.org:5905>: IO::Socket::INET: connect: Connection refused [Auto-restarting because reason matches the configured "auto_clone_regex".]
    12 | 2024-07-12 20:20:34 | 2024-07-15 05:02:30 | backend died: QEMU exited unexpectedly, see log for details
     8 | 2024-07-15 06:44:41 | 2024-07-15 08:48:24 | backend died: Error connecting to VNC server <unreal6.qe.nue2.suse.org:5904>: IO::Socket::INET: connect: Connection refused [Auto-restarting because reason matches the configured "auto_clone_regex".]
     8 | 2024-07-12 20:23:07 | 2024-07-14 20:27:58 | died: terminated prematurely, see log output for details
     7 | 2024-07-15 07:16:03 | 2024-07-15 07:49:02 | tests died: unable to load tests/console/validate_partition_table.pm, check the log for the cause (e.g. syntax error)
     7 | 2024-07-12 22:31:06 | 2024-07-15 02:14:06 | tests died: unable to load main.pm, check the log for the cause (e.g. syntax error)
     4 | 2024-07-12 21:54:33 | 2024-07-14 22:00:55 | tests died: unable to load tests/network/samba/samba_adcli.pm, check the log for the cause (e.g. syntax error)
     4 | 2024-07-13 00:39:22 | 2024-07-13 00:42:04 | asset failure: Failed to download sle-15-SP5-x86_64-146.1-gnome_ay_qesec@64bit.qcow2 to /var/lib/openqa/cache/openqa.suse.de/sle-15-SP5-x86_64-146.1-gnome_ay_qesec@64bit.qcow2
     3 | 2024-07-15 05:37:27 | 2024-07-15 06:12:00 | backend died: Error connecting to VNC server <unreal6.qe.nue2.suse.org:5908>: IO::Socket::INET: connect: Connection refused [Auto-restarting because reason matches the configured "auto_clone_regex".]
     3 | 2024-07-12 23:03:33 | 2024-07-12 23:04:04 | asset failure: Failed to download SLES-15-SP5-x86_64-Build146.3-textmode-intel_ipmi.qcow2 to /var/lib/openqa/cache/openqa.suse.de/SLES-15-SP5-x86_64-Build146.3-textmode-intel_ipmi.qcow2

openqa=> select count(jobs.id), min(t_finished) as first_t_finished, max(t_finished) as last_t_finished, array_agg(DISTINCT workers.host) as hosts, reason from jobs join workers on workers.id = jobs.assigned_worker_id where t_finished >= '2024-07-12T18:00:00' and result = 'incomplete' group by reason order by count(jobs.id) desc limit 1; 
 count |  first_t_finished   |   last_t_finished   |                                                                                                                hosts                                                                                                                 |                                 
                        reason                                                         
-------+---------------------+---------------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------
---------------------------------------------------------------------------------------
   130 | 2024-07-14 22:48:13 | 2024-07-14 22:54:29 | {imagetester,openqaworker-arm-1,openqaworker1,openqaworker14,openqaworker17,openqaworker18,qesapworker-prg4,sapworker1,sapworker2,sapworker3,worker-arm1,worker-arm2,worker29,worker30,worker32,worker33,worker34,worker35,worker40} | api failure: 403 response: times
tamp mismatch - check whether clocks on the local host and the web UI host are in sync
(1 row)

EDIT: I adjusted the query to see the exact time range a certain type on incomplete happened. All happened within a very small time window. That window was shortly before the alert fired (you have to add 2 hours to the database timestamps). However, the alert only fired after a grace period. So the "timestamp mismatch" incompletes actually fall into the timeframe were we also had very high response times (https://stats.openqa-monitor.qa.suse.de/d/WebuiDb/webui-summary?orgId=1&viewPanel=78&from=1720984469160&to=1720999670148).

I also added another query to show the relevant worker hosts and it seems all hosts were relevant/affected. That also speaks for a problem on OSD itself and not on the workers.

I restarted relevant jobs via host=openqa.suse.de additional_filters="reason like '%timestamp mismatch%'" failed_since=2024-07-12T18:00:00 ./openqa-advanced-retrigger-jobs.

Just wanted to note down my observation:
The response time slowly and steadily increased some minutes before 00:01. Funnily the response times were all pretty similar, e.g. directly before the gap it was 16s.
Then after the gap it starts at 375s and goes down slowly, until the queue of waiting requests gets down to normal.

According to select count(jobs.id), min(t_finished) as first_t_finished, max(t_finished) as last_t_finished, array_agg(DISTINCT workers.host) as hosts, reason from jobs join workers on workers.id = jobs.assigned_worker_id where t_finished >= '2024-07-15T12:00:00' and result = 'incomplete' group by reason order by count(jobs.id) desc limit 10; there were no new incompletes with "timestamp mismatch".

The alert also didn't fire again (and was not even pending).

/etc/alternatives/pg_dump still points to /bin/true.

Still no problems. Benchmarked with ab -c 40 -n 50000 https://openqa.suse.de/ resulting in

Concurrency Level:      40
Time taken for tests:   1375.128 seconds
Complete requests:      50000
Failed requests:        0
Total transferred:      3756950000 bytes
HTML transferred:       3667700000 bytes
Requests per second:    36.36 [#/sec] (mean)
Time per request:       1100.102 [ms] (mean)
Time per request:       27.503 [ms] (mean, across all concurrent requests)
Transfer rate:          2668.04 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:       50   67  29.7     62    1263
Processing:   246 1032 377.6   1108    6721
Waiting:      202  994 380.7   1072    6694
Total:        311 1099 373.4   1172    6775

Percentage of the requests served within a certain time (ms)
  50%   1172
  66%   1243
  75%   1285
  80%   1311
  90%   1379
  95%   1438
  98%   1518
  99%   1596
 100%   6775 (longest request)

Now reverted back pg_dump, called the database backup from /etc/cron.d/dump-openqa and in parallel started ab again.

As visible in
https://monitor.qa.suse.de/d/WebuiDb/webui-summary?orgId=1&from=1721282166188&to=1721287759948
HTTP response goes up from mean 200ms to 500ms and system load up to 35 but nothing problematic. Results from ab actually happen to be better than in before:

Concurrency Level:      40
Time taken for tests:   513.778 seconds
Complete requests:      50000
Failed requests:        0
Total transferred:      3762350000 bytes
HTML transferred:       3673100000 bytes
Requests per second:    97.32 [#/sec] (mean)
Time per request:       411.023 [ms] (mean)
Time per request:       10.276 [ms] (mean, across all concurrent requests)
Transfer rate:          7151.27 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:       18   33  80.6     25    2069
Processing:   164  377  68.7    369    1383
Waiting:      148  359  61.0    352    1147
Total:        190  411 105.7    395    2502

Percentage of the requests served within a certain time (ms)
  50%    395
  66%    426
  75%    445
  80%    457
  90%    490
  95%    525
  98%    615
  99%    726
 100%   2502 (longest request)

probably the overall time per request decreased as it's currently a less busy time with less users of OSD and pg_dump has no significant impact.

Extended experiment:

echo "### 3x ionice nice pg_dump $(date -Is)"; backup_dir="/var/lib/openqa/backup"; date=$(date -Idate); bf="$backup_dir/$date.dump"; runs=3 count-fail-ratio sudo -u postgres ionice -c3 nice -n19 pg_dump -Fc openqa -f "$bf" ; echo "### 3x not-nice pg_dump $(date -Is)"; backup_dir="/var/lib/openqa/backup"; date=$(date -Idate); bf="$backup_dir/$date.dump"; runs=3 count-fail-ratio sudo -u postgres pg_dump -Fc openqa -f "$bf"

so 3x ionice nice pg_dump followed with 3x not-nice pg_dump. In parallel for i in {1..10}; do echo "### run $i: date -Is while pg_dump is running"; ab -c 40 -n 50000 https://openqa.suse.de/; done

After I encountered that pg_dump was still running after running for more than 1h (0930-1048 CEST) and I observed high stead system load I aborted the experiment for now. From https://monitor.qa.suse.de/d/WebuiDb/webui-summary?orgId=1&from=1721284394731&to=1721301033387 it looks like there is a steady 30-35 system load 0930-1300+CEST and an increase of HTTP response to around 1.2s until I stopped near-continuous runs of ab. CPU usage is maxed outwith the majority being user load. Biggest load contribution is due to "openqa" processes. Attached to such processes using strace and found processes mostly upload openQA test results. Also minion jobs queued increased up to 600 at 1247CEST but dropped after that even though in the mean time a pg_dump process triggered by rsnapshot was started. I/O on filesystems is high but on the same levels as I/O load peaks on the last days. It looks like the big load is caused by a combination of factors including multiple heavy openQA jobs finishing although the overall openQA job queue is below 1k so nothing severe.

My plan is to reconduct two experiments after EOB:

1. DONE Run ab over >1h to observe system load impact -> https://monitor.qa.suse.de/d/WebuiDb/webui-summary?orgId=1&from=1721314889745&to=1721325203745 shows a CPU usage of around 85% and system load first 30, later 15, possibly because other users ended their work day. During that timeframe there was also a short rise in minion jobs to around 30 queued. Increased load on /srv (database) and /results. Increased nginx requests per time and absolute numbers of requests with result 200.
2. Run the "6x pg_dump" experiment but w/o ab in parallel

Right now there are <5 openQA jobs running on OSD and overal system load is about 0.5. Running the pg_dump experiment. Runtime of 3x nice pg_dump 690±97s. Runtime for not-nice pg_dump 609±1.5s so slightly faster but not significantly different. The next question is how ab+pg_dump is doing in parallel.