QA » openQA Project

I did some database stats on osd and o3 which suggest that this happens quite often.

o3:

openqa=> select j.id, js.value from job_settings js join jobs j on js.job_id=j.id where key='OPENQA_INVESTIGATE_ORIGIN' and js.t_created >= '2021-09-30 08:00:00' and test like '%:investigate:retry' order by value;                                 
   id    |                value                
---------+-------------------------------------
 1947052 | http://openqa.opensuse.org/t1945661 <--
 1946990 | http://openqa.opensuse.org/t1946900
 1946998 | http://openqa.opensuse.org/t1946902
 1946969 | http://openqa.opensuse.org/t1946913 <--
 1947002 | http://openqa.opensuse.org/t1946994
 1947006 | http://openqa.opensuse.org/t1946995
 1947010 | http://openqa.opensuse.org/t1946996
 1947014 | http://openqa.opensuse.org/t1946997
 1947079 | http://openqa.opensuse.org/t1947049
 1947054 | http://openqa.opensuse.org/t1947050
 1947098 | http://openqa.opensuse.org/t1947059
(11 rows)

openqa=> select job_id from comments where t_created >= '2021-09-30 08:00:00' and text like 'Automatic investigation jobs%'
 and text like '%:investigate:retry%' order by job_id;
 job_id  
---------
 1946900
 1946902
 1946994
 1946995
 1946996
 1946997
 1947049
 1947050
 1947059
(9 rows)

I needed to exclude the cloned jobs.
This is the query I came up with to list jobs which are retries and where the original job didn't get a comment:

select CONCAT('https://openqa.suse.de/t',js.job_id),CAST(substr(js.value, 25) as int) as jobid, c.job_id, substr(c.text, 0, 30) as comment_text from job_settings js join jobs j on js.job_id=j.id left join jobs jc on j.id=jc.clone_id left j
oin comments c on CAST(substr(js.value, 25) as int) =c.job_id where key='OPENQA_INVESTIGATE_ORIGIN' and js.t_created >= '2021-09-30 00:00:00' and j.test like '%:investigate:retry' and jc.clone_id is null and c.job_id is null order by jobid;

Note that you need to adjust the substr for o3 because of the different url.

I picked one of those jobs in osd and ran openqa-investigate on it, and it posted a comment successfully. So it's not very likely that there is a problem with the logic of the code.

tinita and me continued to investigate a bit further together. Interesting findings:

• There are logfiles /var/log/openqa_gru* which seem to contain the stdout of the gru minion service but neither stderr nor stdout of actual minion job processes. The stderr goes into the journal of the systemd service, see journalctl -u openqa-gru, the stdout of minion job processes is put into the "notes" of minion jobs which are visible in the "minion_jobs" database table as well as over the minion dashboard UI
• There are warnings in the gru system journal about CloneJob.pm. Proposed fix in https://github.com/os-autoinst/scripts/pull/115
• In the case of success we found that minion jobs record the output of openqa-cli with an openQA comment id that is created, e.g. using SQL select * from minion_jobs where args::TEXT like '%7280737%'; there is the row content "hook_result": {"id": 391557}, in case of failure the "hook_result" is empty but there is no non-zero exit code recorded or anything

We have created https://github.com/os-autoinst/scripts/pull/114 for verbose output based on the "verbose" option and with https://gitlab.suse.de/openqa/salt-states-openqa/-/merge_requests/597 we have set that option for all hook scripts on OSD.

Now we can monitor the journal of openqa-gru again and see what should appear in lines matching something like openqa-investigate.*out:

What I can see already is:

Sep 30 20:37:19 openqa openqa-gru[821]: 404 Not Found
Sep 30 20:40:11 openqa openqa-gru[821]: 404 Not Found
Sep 30 20:40:32 openqa openqa-gru[821]: 404 Not Found
Sep 30 20:41:04 openqa openqa-gru[821]: 404 Not Found

I think this comes from the actual openqa-cli command that tries to write a comment on jobs and fails.

EDIT: When calling a command openqa-cli api --osd -X POST jobs/1/comments text="test by okurz" one gets

404 Not Found
{"error":"Job 1 does not exist","error_status":404}

with the first line being stderr and the second stdout. Now I wondered, if we see the line "404 Not Found" in the system journal of openqa-gru I should be able to search for "does not exist" in minion_jobs notes with select * from minion_jobs where notes::TEXT like '%does not exist%' order by started desc limit 1; and I found

https://openqa.suse.de/minion/jobs?id=3060251

which has as "args": "7274792", so corresponding to the openQA job https://openqa.suse.de/tests/7274792 , which by chance, is failed, has no comment, so "needs investigation". So I assume openqa-investigate was triggered for that.
But in notes we have

{"error":"Job 7274554 does not exist","error_status":404}

Ok, in this example the triggering job is a ":retry" which had a chance to run only some hours after the original job and in this case a user actually deleted the original job. That should be fine.

PR for saving the return code of the hook command: https://github.com/os-autoinst/openQA/pull/4256
It's not obvious from the minion dashboard if a command failed or not.

I added some debugging code which echoes something to stderr right before the first clone, and before checking $out before posting the comment.

For today I found two jobs on osd without comments, 7285740 and 7270784.

In the openqa-gru journal I can see the first debug entry, but not the second, meaning that the script finished before (killed by timeout for example) or simply did not get to this code path.

PR https://github.com/os-autoinst/openQA/pull/4256 (log exit code in hook cmd) was merged.

With that we will hopefully gather more information, for example a timeout would result in an exit code of 124.

We can now see which hooks failed:

select id, args, notes->'hook_rc', notes->'hook_result', created, finished from minion_jobs where notes::TEXT like '%hook_rc%' and cast(notes->'hook_rc' as int)  != 0 order by created;

There are several with rc=31744 which is 31744 << 8 ==124, so it got a timeout.
That matches thecreatedandfinished` columns, as the timeout is currently set to 90s.

To get something in stderr, we should catch the TERM signal with trap.
But IMHO we should also increase the timeout, and we need to create an alert of some kind when it still fails. Currently those failures are ignored

https://github.com/os-autoinst/openQA/pull/4274 Run hook script timeout in verbose mode

https://github.com/os-autoinst/openQA/pull/4274 was merged.

New PR:
https://github.com/os-autoinst/scripts/pull/117 Improve error handling

Short statistics about finalize_job_results minion jobs:

openqa=> select count(*) from minion_jobs where task = 'finalize_job_results' and  cast(notes->'hook_rc' as int)  = 0 ;
 count 
-------
  1532
(1 row)

openqa=> select count(*) from minion_jobs where task = 'finalize_job_results' and  cast(notes->'hook_rc' as int)  != 0 ;
 count 
-------
    51
(1 row)
openqa=> select avg(finished - started) from minion_jobs where task = 'finalize_job_results' and  cast(notes->'hook_rc' as int)  = 0 ;
       avg       
-----------------
 00:00:19.716963
(1 row)

So the large majority of the hooks is fast enough.

The slowest job that was killed due to timeout took 8:29 minutes, and I'm actually wondering why it wasn't killed earlier as we have a timeout of 90s. Maybe my calculation of finished - started is wrong.

Setting the timeout to 3 minutes should catch almost all occurrences.

Increase the timeout: https://gitlab.suse.de/openqa/salt-states-openqa/-/merge_requests/601

Increase the timeout to 10 minutes: https://gitlab.suse.de/openqa/salt-states-openqa/-/merge_requests/604

Yesterday we still had 42 timeouts, today 16 so far.

edit 2021-10-13: MR was merged

Note that I set the timeout (so low) because finalize jobs piled up on OSD. I hope this won't be the case again.

mkittler wrote:

Note that I set the timeout (so low) because finalize jobs piled up on OSD. I hope this won't be the case again.

Yeah, but we have an individual timeout for grep, which was the problematic command.