QA » openQA Project

https://stats.openqa-monitor.qa.suse.de/d/WebuiDb/webui-summary?orgId=1&from=1568730684720&to=1568733130790 is the relevant hour.

If this is just the webui running out of database connections (and no connections are leaking), it might be fixable by installing a PostgreSQL connection manager. https://progress.opensuse.org/issues/55262

It's not. The database connections ran out 15 minutes after the problem started. The problem is that UPDATE job_locks SET locked_by takes several minutes - hinting a livelock (as postgresql didn't report a deadlock)

I enabled lock logging and there aren't deadlocks (that postgresql detects as some) but some processes keep locks

2019-09-20 04:05:35.461 CEST openqa geekotest [1164]LOG:  process 1164 still waiting for ShareLock on transaction 181474480 after 1000.231 ms
2019-09-20 04:05:35.461 CEST openqa geekotest [1164]DETAIL:  Process holding the lock: 22303. Wait queue: 22510, 19629, 1164.
2019-09-20 04:05:35.461 CEST openqa geekotest [1164]CONTEXT:  while updating tuple (9317,101) in relation "jobs"
2019-09-20 04:05:35.461 CEST openqa geekotest [1164]STATEMENT:  UPDATE jobs SET state = $1, t_updated = $2 WHERE ( id = $3 )
2019-09-20 04:05:45.468 CEST openqa geekotest [21717]LOG:  process 21717 still waiting for ExclusiveLock on tuple (567,4) of relation 16737 of database 16386 after 1000.163 ms
2019-09-20 04:05:45.468 CEST openqa geekotest [21717]DETAIL:  Process holding the lock: 22510. Wait queue: 21717.
2019-09-20 04:05:45.468 CEST openqa geekotest [21717]STATEMENT:  UPDATE workers SET t_updated = $1 WHERE ( id = $2 )
2019-09-20 04:06:53.998 CEST openqa geekotest [3469]LOG:  process 3469 still waiting for ExclusiveLock on tuple (9316,110) of relation 16534 of database 16386 after 1000.245 ms
2019-09-20 04:06:53.998 CEST openqa geekotest [3469]DETAIL:  Process holding the lock: 19629. Wait queue: 3469.
2019-09-20 04:06:53.998 CEST openqa geekotest [3469]STATEMENT:  UPDATE jobs SET skipped_module_count = $1, t_updated = $2 WHERE ( id = $3 )
2019-09-20 04:13:55.581 CEST openqa geekotest [29435]LOG:  process 29435 still waiting for ExclusiveLock on tuple (567,4) of relation 16737 of database 16386 after 1001.942 ms
2019-09-20 04:13:55.581 CEST openqa geekotest [29435]DETAIL:  Process holding the lock: 22510. Wait queue: 21717, 29435.
2019-09-20 04:13:55.581 CEST openqa geekotest [29435]STATEMENT:  UPDATE workers SET t_updated = $1 WHERE ( id = $2 )
2019-09-20 04:15:54.145 CEST openqa geekotest [17418]LOG:  process 17418 still waiting for ExclusiveLock on tuple (9316,110) of relation 16534 of database 16386 after 1000.197 ms
2019-09-20 04:15:54.145 CEST openqa geekotest [17418]DETAIL:  Process holding the lock: 19629. Wait queue: 3469, 17418.
2019-09-20 04:15:54.145 CEST openqa geekotest [17418]STATEMENT:  UPDATE jobs SET skipped_module_count = $1, t_updated = $2 WHERE ( id = $3 )
2019-09-20 04:17:24.952 CEST openqa geekotest [19629]LOG:  process 19629 acquired ShareLock on transaction 181474480 after 1172135.551 ms
2019-09-20 04:17:24.952 CEST openqa geekotest [19629]CONTEXT:  while updating tuple (9316,110) in relation "jobs"
2019-09-20 04:17:24.952 CEST openqa geekotest [19629]STATEMENT:  UPDATE jobs SET skipped_module_count = $1, t_updated = $2 WHERE ( id = $3 )
2019-09-20 04:17:24.952 CEST openqa geekotest [22510]LOG:  process 22510 acquired ShareLock on transaction 181474480 after 1190605.905 ms
2019-09-20 04:17:24.952 CEST openqa geekotest [22510]CONTEXT:  while updating tuple (567,4) in relation "workers"
2019-09-20 04:17:24.952 CEST openqa geekotest [22510]STATEMENT:  UPDATE workers SET t_updated = $1 WHERE ( id = $2 )
2019-09-20 04:17:24.952 CEST openqa geekotest [1164]LOG:  process 1164 acquired ShareLock on transaction 181474480 after 710491.349 ms
2019-09-20 04:17:24.952 CEST openqa geekotest [1164]CONTEXT:  while updating tuple (9317,101) in relation "jobs"
2019-09-20 04:17:24.952 CEST openqa geekotest [1164]STATEMENT:  UPDATE jobs SET state = $1, t_updated = $2 WHERE ( id = $3 )
2019-09-20 04:17:24.952 CEST openqa geekotest [21717]LOG:  process 21717 acquired ExclusiveLock on tuple (567,4) of relation 16737 of database 16386 after 700484.700 ms
2019-09-20 04:17:24.952 CEST openqa geekotest [21717]STATEMENT:  UPDATE workers SET t_updated = $1 WHERE ( id = $2 )
2019-09-20 04:17:24.952 CEST openqa geekotest [19629]LOG:  duration: 1172135.926 ms  execute dbdpg_p19626_23: UPDATE jobs SET skipped_module_count = $1, t_updated = $2 WHERE ( id = $3 )
2019-09-20 04:17:24.952 CEST openqa geekotest [19629]DETAIL:  parameters: $1 = '1', $2 = '2019-09-20 01:57:52', $3 = '3384018'
2019-09-20 04:17:24.952 CEST openqa geekotest [22510]LOG:  duration: 1190606.286 ms  execute dbdpg_p22509_5: UPDATE workers SET t_updated = $1 WHERE ( id = $2 )
2019-09-20 04:17:24.952 CEST openqa geekotest [22510]DETAIL:  parameters: $1 = '2019-09-20 01:57:34', $2 = '1251'
2019-09-20 04:17:24.952 CEST openqa geekotest [29435]LOG:  process 29435 acquired ExclusiveLock on tuple (567,4) of relation 16737 of database 16386 after 210373.646 ms
2019-09-20 04:17:24.952 CEST openqa geekotest [29435]STATEMENT:  UPDATE workers SET t_updated = $1 WHERE ( id = $2 )
2019-09-20 04:17:24.953 CEST openqa geekotest [1164]LOG:  duration: 710492.252 ms  execute dbdpg_p1159_1b: UPDATE jobs SET state = $1, t_updated = $2 WHERE ( id = $3 )
2019-09-20 04:17:24.953 CEST openqa geekotest [1164]DETAIL:  parameters: $1 = 'uploading', $2 = '2019-09-20 02:05:34', $3 = '3384056'
2019-09-20 04:17:24.953 CEST openqa geekotest [3469]LOG:  process 3469 acquired ExclusiveLock on tuple (9316,110) of relation 16534 of database 16386 after 631955.753 ms
2019-09-20 04:17:24.953 CEST openqa geekotest [3469]STATEMENT:  UPDATE jobs SET skipped_module_count = $1, t_updated = $2 WHERE ( id = $3 )
2019-09-20 04:17:24.953 CEST openqa geekotest [17418]LOG:  process 17418 acquired ExclusiveLock on tuple (9316,110) of relation 16534 of database 16386 after 91808.918 ms
2019-09-20 04:17:24.953 CEST openqa geekotest [17418]STATEMENT:  UPDATE jobs SET skipped_module_count = $1, t_updated = $2 WHERE ( id = $3 )
2019-09-20 04:17:24.954 CEST openqa geekotest [29435]LOG:  duration: 210374.886 ms  execute dbdpg_p29427_7: UPDATE workers SET t_updated = $1 WHERE ( id = $2 )
2019-09-20 04:17:24.954 CEST openqa geekotest [29435]DETAIL:  parameters: $1 = '2019-09-20 02:13:54', $2 = '1251'
2019-09-20 04:17:24.955 CEST openqa geekotest [21717]LOG:  duration: 700487.607 ms  execute dbdpg_p21714_5: UPDATE workers SET t_updated = $1 WHERE ( id = $2 )
2019-09-20 04:17:24.955 CEST openqa geekotest [21717]DETAIL:  parameters: $1 = '2019-09-20 02:05:44', $2 = '1251'
2019-09-20 04:17:24.957 CEST openqa geekotest [17418]LOG:  duration: 91812.500 ms  execute dbdpg_p17401_18: UPDATE jobs SET skipped_module_count = $1, t_updated = $2 WHERE ( id = $3 )
2019-09-20 04:17:24.957 CEST openqa geekotest [17418]DETAIL:  parameters: $1 = '1', $2 = '2019-09-20 02:15:53', $3 = '3384018'
2019-09-20 04:17:24.963 CEST openqa geekotest [3469]LOG:  duration: 631965.528 ms  execute dbdpg_p3468_1e: UPDATE jobs SET skipped_module_count = $1, t_updated = $2 WHERE ( id = $3 )
2019-09-20 04:17:24.963 CEST openqa geekotest [3469]DETAIL:  parameters: $1 = '1', $2 = '2019-09-20 02:06:52', $3 = '3384018'

Parallel in the webui:

[2019-09-20T04:17:24.0953 CEST] [debug] [pid:1159] [DBIC] Took 710.49299600 seconds: UPDATE jobs SET state = ?, t_updated = ? WHERE ( id = ? ): 'uploading', '2019-09-20 02:05:34', '3384056'
[2019-09-20T04:17:24.0954 CEST] [debug] [pid:19626] [DBIC] Took 1172.13732700 seconds: UPDATE jobs SET skipped_module_count = ?, t_updated = ? WHERE ( id = ? ): '1', '2019-09-20 01:57:52', '3384018'
[2019-09-20T04:17:24.0954 CEST] [debug] [pid:22509] [DBIC] Took 1190.60780300 seconds: UPDATE workers SET t_updated = ? WHERE ( id = ? ): '2019-09-20 01:57:34', '1251'
[2019-09-20T04:17:24.0955 CEST] [debug] [pid:29427] [DBIC] Took 210.37648600 seconds: UPDATE workers SET t_updated = ? WHERE ( id = ? ): '2019-09-20 02:13:54', '1251'
[2019-09-20T04:17:24.0957 CEST] [debug] [pid:17401] [DBIC] Took 91.81311800 seconds: UPDATE jobs SET skipped_module_count = ?, t_updated = ? WHERE ( id = ? ): '1', '2019-09-20 02:15:53', '3384018'
[2019-09-20T04:17:24.0961 CEST] [debug] [pid:21714] [DBIC] Took 700.49337800 seconds: UPDATE workers SET t_updated = ? WHERE ( id = ? ): '2019-09-20 02:05:44', '1251'
[2019-09-20T04:17:24.0963 CEST] [debug] [pid:3468] [DBIC] Took 631.96631300 seconds: UPDATE jobs SET skipped_module_count = ?, t_updated = ? WHERE ( id = ? ): '1', '2019-09-20 02:06:52', '3384018'

So it blocked 7 mojo workers. the others only did SELECTs and that kept running.

Of course this can be actually 2 bugs, but Marius and I tried for quite some time to make sense out of job_locks itself and it just doesn't make sense.

You're saying the log is "from the journal of websocket service" and the openqa-websockets[22287] prefix says it, too. I'm confused. The messages look like they are from any other daemon which tries to speak with the websocket server. But that could explain why the timeout happens: The websockt server waits for an answer from itself. Seems like I have to look for any code paths reachable from the websocket server which possibly try to send a command to the websocket server.

Theory is that the following nested calls inside the web socket server cause it to block: OpenQA::WebSockets::Model::Status::workers_checker -> OpenQA::Schema::Result::Jobs::auto_duplicate -> OpenQA::Schema::Result::Workers::send_coomand

But this is too obvious. Why haven't we seen this earlier or more often?

It really seems to be that call sequence.

PR for immediate fix: https://github.com/os-autoinst/openQA/pull/2340 (if merged we can lower the priority of the issue)

Note that the problem only occurs when the following conditions are met at the same time:

1. The web socket server incompletes a job because its worker hasn't seen for too long.
2. That job is part of a cluster and other jobs in the cluster need to be aborted.

That's why it only happened rarely.

Marking jobs as incomplete is likely better done in the scheduler because it is possibly an extensive task and the ws server should stay reactive. So maybe create another API route on the scheduler-side to incomplete a job (and figure out which jobs in the cluster need to be rescheduled/aborted and so on). The ws server could call that route in an async manner and wouldn't care much about the response.

So I would create an API on the scheduler side which allows the web socket server to report jobs to be considered incomplete. Since the scheduler already has the "wakeup" API and therefore is already an HTTP server this should not be much to implement.

I'm wondering whether we should add a check in the IPC clients (e.g. on instantiation) to assert that it is never used from the daemon itself. This would allow us to identify problems caused by this type of problem more easily in the future.

I updated the approach: https://github.com/os-autoinst/openQA/pull/2348

So the idea is to rely only on t_updated for the incompleting stale jobs.

But I've discovered another code path in the ws code which incompletes and duplicates jobs. When a worker is online (again) the job the web UI think it is running needs to be incompleted unless the worker reports that it is still working on it. That will really require an IPC call from the ws server to the scheduler. Also the "re-scheduling" logic for assigned jobs should be moved to the scheduler (for consistency).

Draft/PR for the 2nd code path: https://github.com/os-autoinst/openQA/pull/2351

PR for the idea mentioned in previous comment: https://github.com/os-autoinst/openQA/pull/2398

merged