QA (public) » openQA Project (public)

Seen the same in the OSD journal:

Feb 08 14:49:52 openqa openqa[13856]: [error] Worker 19842 has no heartbeat (400 seconds), restarting

There is only really one cause for this, and that's a blocking operation (like a database query) running for more than 400 seconds. Which would prevent the worker process from sending a heartbeat to the manager process. The fix would be a) to make sure nothing blocks the process for more than 400 seconds, or b) to increase the heartbeat timeout.

Looking through the OSD logs a bit more, i also found a few seemingly unrelated liveviewhandler 504 errors in the access_log around the same time (guess those might just be that common). The 502 seems suspiciously close to when the 400 second timeout must have started.

Feb 08 14:49:52 openqa openqa[13856]: [error] Worker 19842 has no heartbeat (400 seconds), restarting

[08/Feb/2022:14:43:10 +0100] "GET /tests/overview?build=&distri=sle&version=15-SP1 HTTP/1.1" 502 1071 "https://openqa.suse.de/tests"
[08/Feb/2022:14:58:50 +0100] "GET /liveviewhandler/tests/8119824/developer/ws-proxy/status HTTP/1.1" 504 - "-"
[08/Feb/2022:14:58:37 +0100] "GET /liveviewhandler/tests/8119823/developer/ws-proxy/status HTTP/1.1" 504 - "-"

The last thing the killed worker process logged was:

Feb 08 14:43:10 openqa openqa[19842]: [debug] No build and no group specified, will lookup build based on the other parameters

It does not appear to be a general problem with the request though, when i manually open the URL it finishes loading completely in 4.92s.

From openQA logreport on o3:

[2022-02-17T03:51:53.414618Z] [error] Worker 13242 has no heartbeat (400 seconds), restarting
[2022-02-17T03:52:08.416699Z] [error] Worker 7572 has no heartbeat (400 seconds), restarting
[2022-02-17T03:52:26.022451Z] [error] Worker 7891 has no heartbeat (400 seconds), restarting
[2022-02-17T03:54:41.762629Z] [error] Worker 14719 has no heartbeat (400 seconds), restarting
[2022-02-17T03:54:55.849639Z] [error] Worker 15029 has no heartbeat (400 seconds), restarting
[2022-02-17T03:55:15.120880Z] [error] Worker 13288 has no heartbeat (400 seconds), restarting
[2022-02-17T03:57:08.128696Z] [error] Worker 16322 has no heartbeat (400 seconds), restarting
[2022-02-17T03:59:52.744987Z] [error] Worker 17689 has no heartbeat (400 seconds), restarting

okurz wrote:

You reduced prio to Low but nobody added something to logwarn. This means that every day we receive monitoring alerts about this causing the opposite of "this shouldn't be simply ignored"

That didn't look to be the case when I was on alert duty ;-) (Not disagreeing, answering your question)

Re https://progress.opensuse.org/issues/106759#note-9

I looked for long running HTTP requests in the log from 17/Feb/2022:

% cat long-requests  | grep -v "GET /api/v1/ws/" | grep -v "GET /assets" | grep -v "GET /liveviewhandler/tests" | grep -v "GET .*/streaming " | grep '[0-9][0-9][0-9][0-9][0-9][0-9]$' 
192.168.112.100 - - [17/Feb/2022:00:47:29 +0000] "GET /tests/2192620/investigation_ajax HTTP/1.1" 200 1929881 "-" "openqa-investigate" 101193
192.168.47.46 - - [17/Feb/2022:03:32:41 +0000] "GET /tests/overview HTTP/1.1" 502 1082 "-" "Mozilla/5.0 [en] (X11, U; OpenVAS-VT 21.4.3)" 300102
192.168.47.46 - - [17/Feb/2022:03:32:51 +0000] "GET /tests/overview HTTP/1.1" 502 1082 "-" "Mozilla/5.0 [en] (X11, U; OpenVAS-VT 21.4.3)" 300135
192.168.47.46 - - [17/Feb/2022:03:45:13 +0000] "GET /tests/overview HTTP/1.1" 406 - "-" "Mozilla/5.0 [en] (X11, U; OpenVAS-VT 21.4.3)" 300101
192.168.47.46 - - [17/Feb/2022:03:45:43 +0000] "GET /tests/overview HTTP/1.1" 406 - "-" "Mozilla/5.0 [en] (X11, U; OpenVAS-VT 21.4.3)" 304052
192.168.47.46 - - [17/Feb/2022:03:48:01 +0000] "GET /tests/overview HTTP/1.1" 406 - "-" "Mozilla/5.0 [en] (X11, U; OpenVAS-VT 21.4.3)" 300097
192.168.47.46 - - [17/Feb/2022:03:48:31 +0000] "GET /tests/overview HTTP/1.1" 406 - "-" "Mozilla/5.0 [en] (X11, U; OpenVAS-VT 21.4.3)" 300498
192.168.47.46 - - [17/Feb/2022:03:45:23 +0000] "GET /tests/overview HTTP/1.1" 406 - "-" "Mozilla/5.0 [en] (X11, U; OpenVAS-VT 21.4.3)" 600197
192.168.47.46 - - [17/Feb/2022:03:50:23 +0000] "GET /tests/overview HTTP/1.1" 406 - "-" "Mozilla/5.0 [en] (X11, U; OpenVAS-VT 21.4.3)" 300098
192.168.47.46 - - [17/Feb/2022:03:48:11 +0000] "GET /tests/overview HTTP/1.1" 406 - "-" "Mozilla/5.0 [en] (X11, U; OpenVAS-VT 21.4.3)" 600199
192.168.47.46 - - [17/Feb/2022:03:53:11 +0000] "GET /tests/overview HTTP/1.1" 406 - "-" "Mozilla/5.0 [en] (X11, U; OpenVAS-VT 21.4.3)" 300100

As you can see, most of them are between 3:32 and 3:53, and two of them took over 600 seconds.

So it doesn't exactly match the times from https://progress.opensuse.org/issues/106759#note-9 but still maybe related?

We could try activating slow query logging in Postgres (300 seconds or more) and then match slow query timestamps with the worker has no heartbeat messages.

I enabled slow query logging (>= 300s) on o3.

PR for ignoring the messages for now: https://github.com/os-autoinst/openqa-logwarn/pull/27

Not sure if this is wanted because Oli's statement in https://progress.opensuse.org/issues/106759#note-10 is hard to parse

I changed the slow query threshold to >= 200s yesterday.
So far I can't see a slow query log.

I set the slow query duration to 5s now.
I was able to trigger one with using the search box in the webui (duration: 5119.870 ms).
The slow queries don't land in their own log like in mysql, but in the general log under /var/lib/pgsql/data/log.
I will keep it at 5s and monitor how many we will get.
I did not find any slow queries over 200s for the last days.
Some long running queries seem to be aborted though, e.g. https://openqa.opensuse.org/tests/overview will return with a 502 after 5 minutes.

Had a look at the o3 logs today. No "heartbeat" messages (logs go back to March 9). Very few slow (>=5s) queries.

I'm not actually seeing the error in the logs anymore, perhaps it has been resolved unintentionally by another change.

If this issue pops up again we should maybe try logging all database errors with one of the DBI hook APIs. (Not doing that now since in some cases we intentionally create exceptions and handle them with try/catch, so it could lead to a lot of log output...)

Just noting that we won't really notice it if the message appears because we are ignoring it.

Let's talk about it in tomorrow's mob session

We looked into this together. On o3 with xzgrep heartbeat /var/log/openqa* we found

/var/log/openqa.10.xz:[2022-05-03T01:48:15.126683Z] [error] Worker 324 has no heartbeat (400 seconds), restarting 
/var/log/openqa.19.xz:[2022-04-30T10:12:07.993477Z] [error] Worker 16174 has no heartbeat (400 seconds), restarting

Comparing with apache access logs excluding some services that don't use the main openQA webUI server we found:

xzgrep '[0-9]\{6,\}$' /space/logs/apache2/openqa.access_log-20220504.xz | grep -v '\/v1\/ws' | grep -v '\/assets\/' | grep -v '\/liveviewhandler'                                                                                                                192.168.47.102 - - [03/May/2022:01:41:34 +0000] "GET /tests/overview?version=Tumbleweed&groupid=24 HTTP/1.1" 502 1076 "-" "Mozilla/5.0 (iPad; CPU OS 9_3_4 like Mac OS X) AppleWebKit/601.1.46 (KHTML, like Gecko) Version/9.0 Mobile/13G35 Safari/601.1" 300104

the last number is the time the request took in ms, configured by tinita in apache config.

The funny part is that "groupid=24" is openQA-in-openQA tests but likely the quoting with & is done wrongly here. So likely the real URL that is called is /tests/overview?version=Tumbleweed. If you try to kill the server then one could just call /tests/overview without any filter parameters.

It is also the investigation route:

192.168.112.100 - - [03/May/2022:22:23:54 +0000] "GET /tests/2326528/investigation_ajax HTTP/1.1" 502 1076 "-" "python-requests/2.24.0" 300108

So the investigation should likely be a Minion job and the web UI would poll for the results. As a further optimization we could also cache the results of the investigation (e.g. store it as hidden asset so we can make use of the asset cleanup).

We have replicated the issue on O3 with the path /tests/overview?version=Tumbleweed&groupid=24, which caused a new log entry:

[2022-05-05T12:29:55.485177Z] [error] Worker 22758 has no heartbeat (400 seconds), restarting
[2022-05-05T12:29:55.485366Z] [info] Stopping worker 22758 gracefully (800 seconds)
[2022-05-05T12:29:55.541685Z] [info] Worker 32438 started

For the test results overview page: I'd just put a limit on the database query (configurable). Paging is not useful and would also be very hard to implement. We can just add a hint "Limited to X results. Please use more specific parameters.".

okurz wrote:

not resolved as long as we ignore the error message in openqa-logwarn.

https://github.com/os-autoinst/openqa-logwarn/pull/36

The blocker has been resolved.