openQA Project (public)

But the job was autorestarted, no?

it looks like but maybe https://openqa.suse.de/tests/3689370#next_previous shows the problem in a more obvious manner

It appears to me that you're mixing issues again - because this link only shows timeout_exceeded jobs, not incompletes

That's a strange case, apparently the job has been marked as incomplete in the second Dec 10 17:11:58:

Dec 10 17:11:58 openqaworker6 worker[5647]: [debug] [pid:5647] REST-API call: POST http://openqa.suse.de/api/v1/jobs/3687641/status
Dec 10 17:11:58 openqaworker6 worker[5647]: [error] [pid:5647] REST-API error (POST http://openqa.suse.de/api/v1/jobs/3687641/status): 400 response: Got status update for job 3687641 with unexpected worker ID 972 (expected no updates anymore, job is done with result incomplete) (remaining tries: 2)

The behavior on the worker side looks expected (retrying the status update, failing with the reason 'api-failure' and registering again). The question is why the web UI suddenly considered that job incomplete. The worker didn't reconnect at this time so it is unlikely a bug in the incompletion code on worker reconnect.

Before the whole Got status update for job ... with unexpected worker ... spam the following message is logged:

[2019-12-10T16:33:55.0181 CET] [error] [24b15e6c] DBIx::Class::Row::update(): Can't update OpenQA::Schema::Result::JobLocks=HASH(0x560d4a94b0b0): row not found at /usr/share/openqa/script/../lib/OpenQA/Resource/Locks.pm line 151

And it seems the scheduler logs to a different file, indeed. And it was busy marking jobs as incomplete at this time:

[2019-12-10T16:59:20.0644 CET] [warn] Dead job 3687090 aborted as incomplete
[2019-12-10T16:59:21.0159 CET] [warn] Dead job 3686910 aborted and duplicated 3688470
[2019-12-10T16:59:23.0113 CET] [warn] Dead job 3686893 aborted and duplicated 3688471
[2019-12-10T16:59:23.0989 CET] [warn] Dead job 3687049 aborted and duplicated 3688472
[2019-12-10T16:59:24.0232 CET] [warn] Dead job 3685150 aborted and duplicated 3688473
[2019-12-10T16:59:24.0461 CET] [warn] Dead job 3685234 aborted and duplicated 3688474
[2019-12-10T16:59:24.0979 CET] [warn] Dead job 3687000 aborted and duplicated 3688475
[2019-12-10T16:59:25.0886 CET] [warn] Dead job 3686897 aborted and duplicated 3688476
[2019-12-10T16:59:32.0037 CET] [warn] Dead job 3686881 aborted and duplicated 3688477
[2019-12-10T17:01:59.0749 CET] [warn] Dead job 3687849 aborted and duplicated 3688491
[2019-12-10T17:02:01.0023 CET] [warn] Dead job 3688383 aborted and duplicated 3688492
[2019-12-10T17:02:02.0500 CET] [warn] Dead job 3686981 aborted and duplicated 3688495
[2019-12-10T17:02:03.0370 CET] [warn] Dead job 3688463 aborted and duplicated 3688496
[2019-12-10T17:02:03.0819 CET] [warn] Dead job 3688470 aborted and duplicated 3688498
[2019-12-10T17:02:06.0489 CET] [warn] Dead job 3687020 aborted and duplicated 3688500
[2019-12-10T17:02:08.0508 CET] [warn] Dead job 3687093 aborted and duplicated 3688506
[2019-12-10T17:02:10.0760 CET] [warn] Dead job 3688373 aborted and duplicated 3688507
[2019-12-10T17:02:13.0475 CET] [warn] Dead job 3687099 aborted and duplicated 3688513
[2019-12-10T17:02:14.0744 CET] [warn] Dead job 3687030 aborted and duplicated 3688514
[2019-12-10T17:02:17.0834 CET] [warn] Dead job 3687021 aborted and duplicated 3688516
[2019-12-10T17:02:18.0340 CET] [warn] Dead job 3688455 aborted and duplicated 3688520
[2019-12-10T17:02:19.0469 CET] [warn] Dead job 3687031 aborted and duplicate

Suggestions:

• sub handle_worker_reported_back could be moved from the scheduler to the main web UI. That would scale better because the main web UI has preforking.
• But all the Dead job %d aborted and duplicated messages come actually from sub incomplete_and_duplicate_stale_jobs which is executed by the scheduler every 2 minutes. It seems that it kept the scheduler quite busy:

[2019-10-10T19:56:37.0486 CEST] [warn] Dead job 3462679 aborted and duplicated 3464155
[2019-10-10T19:56:37.0941 CEST] [warn] Dead job 3462675 aborted and duplicated 3464156
[2019-10-10T19:56:41.0006 CEST] [warn] Dead job 3462503 aborted and duplicated 3464157
[2019-10-10T19:56:41.0635 CEST] [warn] Dead job 3462596 aborted and duplicated 3464158
[2019-10-10T19:56:42.0334 CEST] [warn] Dead job 3462682 aborted and duplicated 3464159
tons of similar messages and not other messages in between
[2019-10-10T20:14:44.0108 CEST] [warn] Dead job 3464636 aborted as incomplete
[2019-10-10T20:14:44.0635 CEST] [warn] Dead job 3464638 aborted and duplicated 3464671

The incomplete detection requires quite some DB queries and possibly blocking IPC with the web socket server. Considering the log, processing a single job can even take more than a second. We can not easily move that function to the web UI because it is triggered using a recurring timer on the IO loop. However, we could make the IPC non-blocking or outsource it to (yet another) daemon. Or we just interrupt the loop if it is taking too long.

coolo wrote:

It appears to me that you're mixing issues again - because this link only shows timeout_exceeded jobs, not incompletes

yes, sorry. Seems I have copied the wrong job link. This dark red for both incompletes and timeout_exceeded is something we could overhaul with better meta-results now :)

@mkittler your suggestion looks sound to me. Can we do any short-term changes to mitigate and see if your assumption is right? E.g. reduce the interval that this is triggered, increase the "stale detection time" or something?

I think the suggestions "Or we just interrupt the loop if it is taking too long." can be considered a short-term mitigation. And yes, we could also decrease the interval for the stale job detection. By the way, I'm still not quite certain which condition triggered the problem. Maybe there were just too many stale jobs (or at least more than usual) at the same time to be aborted and duplicated?

Note that in the chat it was discussed to remove the stale job detection altogether. This simplification would likely have a lot of implications which we should be clarify before and it would make sense to have a different ticket for that.

Another short-term improvement would be increasing WORKERS_CHECKER_THRESHOLD. So we wouldn't consider jobs dead after just 2 minutes but e.g. keep them around as 'running' for 15 minutes. (If a worker is restarted the aborted job would still immediately be incompleted when the worker reports back again.)

I've just had a look at the recent scheduler log to see how bad it currently is. Luckily it isn't busy incompleting jobs anymore. However, the dead job detection of course runs every 2 minutes. With debug output enabled there are more interesting messages:

[2019-12-11T15:42:08.0797 CET] [error] [pid:15172] Failed dispatching message to websocket server over ipc for worker "openqaworker-arm-2:": Inactivity timeout at /usr/share/openqa/script/../lib/OpenQA/WebSockets/Client.pm line 55.

[2019-12-11T15:52:08.0845 CET] [error] [pid:15172] Failed dispatching message to websocket server over ipc for worker "openqaworker-arm-2:": Inactivity timeout at /usr/share/openqa/script/../lib/OpenQA/WebSockets/Client.pm line 55.

[2019-12-11T15:52:08.0880 CET] [debug] [pid:15172] Jobs to duplicate {
  3695052 => {
               chained_children          => [],
               chained_parents           => [3694658],
               directly_chained_children => [],
               directly_chained_parents  => [],
               parallel_children         => [3695053, 3695054],
               parallel_parents          => [],
             },
  3695053 => {
               chained_children          => [],
               chained_parents           => [],
               directly_chained_children => [],
               directly_chained_parents  => [],
               parallel_children         => [],
               parallel_parents          => [3695052],
             },
  3695054 => {
               chained_children          => [],
               chained_parents           => [],
               directly_chained_children => [],
               directly_chained_parents  => [],
               parallel_children         => [],
               parallel_parents          => [3695052],
             },
}
[2019-12-11T15:52:09.0466 CET] [debug] [pid:15172] new job 3695250
[2019-12-11T15:52:09.0469 CET] [warn] [pid:15172] Dead job 3695053 aborted and duplicated 3695250
[2019-12-11T15:52:09.0548 CET] [debug] [pid:15172] Jobs to duplicate {
  3695060 => {
               chained_children          => [],
               chained_parents           => [3694658],
               directly_chained_children => [],
               directly_chained_parents  => [],
               parallel_children         => [],
               parallel_parents          => [],
             },
  3695062 => {
               chained_children          => [],
               chained_parents           => [],
               directly_chained_children => [],
               directly_chained_parents  => [],
               parallel_children         => [],
               parallel_parents          => [3695060],
             },
}
[2019-12-11T15:52:09.0699 CET] [debug] [pid:15172] rollback duplicate: {UNKNOWN}: There is already a clone! at /usr/share/openqa/script/../lib/OpenQA/Schema/Result/Jobs.pm line 635. at /usr/share/openqa/script/../lib/OpenQA/Schema/Result/Jobs.pm line 849

[2019-12-11T15:52:09.0700 CET] [debug] [pid:15172] duplication failed
[2019-12-11T15:52:09.0700 CET] [warn] [pid:15172] Dead job 3695062 aborted as incomplete
[2019-12-11T15:52:09.0740 CET] [debug] [pid:15172] Jobs to duplicate {
  3695075 => {
    chained_children          => [],
    chained_parents           => [],
    directly_chained_children => [],
    directly_chained_parents  => [],
    parallel_children         => [],
    parallel_parents          => [],
  },
}
[2019-12-11T15:52:09.0906 CET] [debug] [pid:15172] new job 3695253
[2019-12-11T15:52:09.0910 CET] [warn] [pid:15172] Dead job 3695075 aborted and duplicated 3695253
[2019-12-11T15:52:09.0981 CET] [debug] [pid:15172] Jobs to duplicate {
  3695052 => {
               chained_children          => [],
               chained_parents           => [3694658],
               directly_chained_children => [],
               directly_chained_parents  => [],
               parallel_children         => [],
               parallel_parents          => [],
             },
  3695054 => {
               chained_children          => [],
               chained_parents           => [],
               directly_chained_children => [],
               directly_chained_parents  => [],
               parallel_children         => [],
               parallel_parents          => [3695052],
             },
}
[2019-12-11T15:52:10.0205 CET] [debug] [pid:15172] rollback duplicate: {UNKNOWN}: There is already a clone! at /usr/share/openqa/script/../lib/OpenQA/Schema/Result/Jobs.pm line 635. at /usr/share/openqa/script/../lib/OpenQA/Schema/Result/Jobs.pm line 849

So apparently timeouts happen when sending commands to the worker via the web socket service (part of the dead job detection).

And then there are also these There is already a clone! messages from sub create_clone. The code looks like that this is an expected condition. However, I'm wondering whether it is normal that it happens so often.

This sounds to me as if some checks regarding openqaworker-arm-2 would cause delays and timeouts which would lead to other workers being unable to send an update to the webui causing chain-effects.

Yes, it slows down the scheduler. It is generally not nice that a slow worker possibly slows down one of the global daemons - that's why I brought it up.

PR for increasing WORKERS_CHECKER_THRESHOLD: https://github.com/os-autoinst/openQA/pull/2591

I'm currently preparing another PR for moving handle_worker_reported_back to the main web UI so it is done when the worker registers via the API.

As I manually increased the WORKERS_CHECKER_THRESHOLD to 15m on osd I checked today for related, incomplete jobs. As auto-review tries to label all incompletes we can query for the used label:

openqa=> select distinct jobs.id,t_finished from jobs, comments where (result='incomplete' and t_finished >= (NOW() - interval '96 hour') and jobs.id in (select job_id from comments where text ~ 'poo#60866')) order by t_finished desc limit 10;
   id    |     t_finished      
---------+---------------------
 3700775 | 2019-12-12 21:17:12
 3700343 | 2019-12-12 20:02:53
 3700339 | 2019-12-12 20:02:14
 3700544 | 2019-12-12 20:00:32
 3700755 | 2019-12-12 19:50:36
 3700727 | 2019-12-12 19:48:04
 3700701 | 2019-12-12 19:47:31
 3700749 | 2019-12-12 19:45:29
 3700611 | 2019-12-12 19:44:38
 3700748 | 2019-12-12 19:44:31

I don't have a graph of incomplete jobs over time but at least we can say for sure that the patch to WORKERS_CHECKER_THRESHOLD did not fix all ;)

To get an overview of all incompletes by type, only the most severe from the last 96 hours:

openqa=> select left(text, 80), count(text) from jobs, comments where (result='incomplete' and t_finished >= (NOW() - interval '96 hour') and jobs.id in (select job_id from comments where id is not null)) and jobs.id = job_id group by text having count(text) > 5 order by count(text) desc;
                                       left                                       | count 
----------------------------------------------------------------------------------+-------
 poo#60866 Again many incomplete jobs with no logs at all                         |   998
 label:setup_failure, probably wrong settings or missing asset                    |   344
 poo#59852 auto_review:"Failed to find an available port: Address already in use" |    41
 poo#46742 premature deletion of files from cache                                 |    32
 poo#57620 job is incomplete if websockets server (or webui?) is unreachable for  |    11
 poo#60161 test incompletes in t20_teaming_ab_all_link                            |     8
 poo#60200 job incompletes just after VNC stall detection, no clear error         |     8
 poo#43631 Job ending up incomplete but everything else looks fine                |     8

Too early to be sure but at least I did not see any degradation. What I did now for analysis, trigger a pipeline on https://gitlab.suse.de/openqa/auto-review/pipelines to mark the unreviewed incompletes from today and then in osd SQL:

select left(text, 80), count(text) from jobs, comments where (result='incomplete' and t_finished >= (NOW() - interval '13 hour') and jobs.id in (select job_id from comments where id is not null)) and jobs.id = job_id group by text having count(text) > 5 order by count(text) desc;
                                       left                                       | count 
----------------------------------------------------------------------------------+-------
 label:setup_failure, probably wrong settings or missing asset                    |    56
 poo#60443 job incomplete with auto_review:"(?s)isotovideo failed.*EXIT 1" but no |    22
 poo#60866 Again many incomplete jobs with no logs at all                         |    11

so (just) 11 jobs with no logs at all. Still something to look at, e.g. one from that list: https://openqa.suse.de/tests/3721672 . I looked up the service journal for the job at the time from openqaworker8:2 and found:

Dec 18 13:08:22 openqaworker8 worker[33797]: [debug] [pid:33797] Updating status so job 3721672 is not considered dead.
Dec 18 13:08:22 openqaworker8 worker[33797]: [debug] [pid:33797] REST-API call: POST http://openqa.suse.de/api/v1/jobs/3721672/status
Dec 18 13:08:23 openqaworker8 worker[33797]: [debug] [pid:33797] Download of SLE-12-SP3-Server-DVD-x86_64-GM-DVD1.iso processed:
Dec 18 13:08:23 openqaworker8 worker[33797]: [info] [#220622] Cache size of "/var/lib/openqa/cache" is 48GiB, with limit 50GiB
Dec 18 13:08:23 openqaworker8 worker[33797]: [info] [#220622] Downloading "SLE-12-SP3-Server-DVD-x86_64-GM-DVD1.iso" from "openqa.suse.de/tests/3721672/asset/iso/SLE-12-SP3-Server-DVD-x86_64-GM-DVD1.iso"
Dec 18 13:08:23 openqaworker8 worker[33797]: [info] [#220622] Content of "/var/lib/openqa/cache/openqa.suse.de/SLE-12-SP3-Server-DVD-x86_64-GM-DVD1.iso" has not changed, updating last use
Dec 18 13:13:23 openqaworker8 worker[33797]: Mojo::Reactor::Poll: I/O watcher failed: Inactivity timeout at /usr/share/openqa/script/../lib/OpenQA/CacheService/Client.pm line 57.
Dec 18 13:13:23 openqaworker8 worker[33797]: [error] [pid:33797] Stopping because a critical error occurred.
Dec 18 13:13:23 openqaworker8 worker[33797]: [debug] [pid:33797] Stopping job 3721672 from openqa.suse.de: 03721672-sle-12-SP3-Server-DVD-Updates-x86_64-Build20191218-2-qam-gnome@64bit - reason: exception
Dec 18 13:13:23 openqaworker8 worker[33797]: [debug] [pid:33797] REST-API call: POST http://openqa.suse.de/api/v1/jobs/3721672/status
Dec 18 13:13:23 openqaworker8 worker[33797]: [error] [pid:33797] Another error occurred when trying to stop gracefully due to an error. Trying to kill ourself forcefully now.
Dec 18 14:04:50 openqaworker8 systemd[1]: Starting openQA Worker #2...

so the cache service client failed with inactivity timeout and the worker instance terminated itself. I don't know what restarted it later at 14:04:50.

The Mojo::Reactor::Poll: I/O watcher failed: Inactivity timeout at /usr/share/openqa/script/../lib/OpenQA/CacheService/Client.pm line 57. is interesting. It means that the cache service API server was longer unavailable than i expected, and we can probably resolve that issue by extending the default timeout a bit.

mkittler wrote:

@okurz The incompletes job you have found is certainly caused by something else than the series of incompletes which lead to creating this issue. I'm concertizing the ticket description because it makes no sense to handle any kind of incomplete job within that ticket.

yes, you can do that but https://github.com/os-autoinst/scripts/blob/master/openqa-label-known-issues#L68 will continue to use this ticket as label unless we change the detection within there or at least update the ticket reference. The problem with "no logs at all" is though that the detection of what is going is pretty hard. This is why we should try really hard to avoid this generic problem of "no logs at all". And this is what this ticket was and is about, despite what we identified as just one part of a bigger problem area.

What we can do is keep this ticket as epic and split out any identified sub-problem.

@mkittler I don't have hard feeling how you handle this ticket but as stated in #60866#note-21 the ticket is still used as a label in https://github.com/os-autoinst/scripts/blob/master/openqa-label-known-issues#L68 . You closing this ticket does not change that. Meaning, without changing the script this closed ticket will be used as label in incomplete jobs.

For the record, the script has been changed to point to the related epic.