action #55238
open
jobs with high amount of log files, thumbnails, test results are incompleted but the job continues with upload attempts
Added by okurz over 4 years ago.
Updated almost 4 years ago.
Category:
Regressions/Crashes
Description
Observation¶
https://openqa.suse.de/tests/3225843# is incomplete. At the time of writing already incomplete since 23 minutes. osd reports in /var/log/openqa:
[2019-08-08T14:33:55.0517 CEST] [info] Got artefact for job with no worker assigned (maybe running job already considered dead): 3225843
[2019-08-08T14:33:55.0744 CEST] [info] Got artefact for job with no worker assigned (maybe running job already considered dead): 3225843
[2019-08-08T14:33:56.0441 CEST] [info] Got artefact for job with no worker assigned (maybe running job already considered dead): 3225843
[2019-08-08T14:33:56.0699 CEST] [info] Got artefact for job with no worker assigned (maybe running job already considered dead): 3225843
[2019-08-08T14:33:57.0285 CEST] [info] Got artefact for job with no worker assigned (maybe running job already considered dead): 3225843
[2019-08-08T14:33:57.0506 CEST] [info] Got artefact for job with no worker assigned (maybe running job already considered dead): 3225843
[…]
On openqaworker8 I can see that the job is actually still active and happily spamming osd with more logs:
openqaworker8:/var/lib/openqa/pool/4 # tail -f autoinst-log.txt worker-log.txt
==> autoinst-log.txt <==
last frame
[2019-08-08T13:44:33.969 CEST] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
[2019-08-08T13:44:33.971 CEST] [debug] QEMU: qemu-system-x86_64: terminating on signal 15 from pid 14865 (/usr/bin/isotovideo: backen)
[2019-08-08T13:44:33.972 CEST] [debug] sending magic and exit
[2019-08-08T13:44:33.972 CEST] [debug] received magic close
[2019-08-08T13:44:33.989 CEST] [debug] backend process exited: 0
[2019-08-08T13:44:34.990 CEST] [debug] killing backend process 14865
[2019-08-08T13:44:34.990 CEST] [debug] done with backend process
14405: EXIT 0
[2019-08-08T13:44:35.0060 CEST] [info] [pid:15638] Isotovideo exit status: 0
==> worker-log.txt <==
[2019-08-08T14:35:07.0115 CEST] [debug] [pid:15638] Uploading pthread_kill_7-1-8.txt
[2019-08-08T14:35:07.0385 CEST] [debug] [pid:15638] Uploading pthread_kill_7-1-9.txt
[2019-08-08T14:35:07.0660 CEST] [debug] [pid:15638] Uploading pthread_kill_7-1-10.txt
[2019-08-08T14:35:16.0179 CEST] [debug] [pid:15638] Uploading pthread_kill_8-1-1.txt
[2019-08-08T14:35:16.0821 CEST] [debug] [pid:15638] Uploading pthread_kill_8-1-2.txt
[…]
Suggestions¶
- Have this as a stress test :) For example "job tries to upload 10k log files with say 1k bytes each"
- If the worker was asked to be stopped make sure it will stop or consider it running from server side as long as it actually is running
- Prevent jobs from even trying to upload a too high amount of log files (or bundle them together to reduce numbers)
Further details¶
I have provided worker-log.txt and autoinst-log.txt from the still running job on
https://w3.nue.suse.com/~okurz/poo55238/
- Copied from action #54902: openQA on osd fails at "incomplete" status when uploading, "502 response: Proxy Error" added
- Description updated (diff)
- Subject changed from LTP jobs with endless amount of logs are killing openQA to [ltp][kernel] LTP jobs with endless amount of logs are killing openQA
- Subject changed from [ltp][kernel] LTP jobs with endless amount of logs are killing openQA to jobs with high amount of log files are incompleted but the job continues with upload attempts
- Description updated (diff)
as discussed with pvorel in IRC #55283 created to prevent this situation for now from test side. This ticket can focus on the openQA side then.
- Subject changed from jobs with high amount of log files are incompleted but the job continues with upload attempts to jobs with high amount of log files, thumbnails, test results are incompleted but the job continues with upload attempts
The worker is actually supposed to stop after the first failure and according to the log the web UI actually rejects the uploads here. I'm trying to reproduce this locally because only by looking at the code I can not figure out why the error handling doesn't work.
I have changed the mocking of _upload_log_file and _upload_asset within t/24-worker-job.t to simulate a failure. The worker aborts the job in this case. So the messed up error handling lies deeper in the upload code itself and the recent worker restructuring is unlikely to cause this.
See PR https://github.com/os-autoinst/openQA/pull/2250 for the test.
- Copied to action #55328: job is considered incomplete by openQA but worker still pushes updates so that "job is not considered dead" added
- Status changed from New to Workable
- Related to action #55904: /status updates are too heavy with external results added
- Priority changed from High to Normal
Right now not high prio - possibly even resolved due to recent changes.
- Status changed from Workable to Blocked
- Assignee set to okurz
I assume https://github.com/os-autoinst/openQA/pull/2270 was the main PR in this direction by making the worker use asynchronous upload as much as possible. Also we recently disabled the mojo monitoring plugin which helped a lot. Further work is also going on in #55904. We can certainly revisit the remaining points but probably we should wait for #55904 first.
The manual tests we have conducted on staging based on the ltp syscall test were helpful enough. Nothing we want to run on PRs of course. Unless we can mock the expensive steps. Potentially we could run more expensive tests as part of openQA-in-openQA however we would need to be very careful to have really stable results. table means it would fail only if it points to reproducible issues that we want to fix. If e.g. a disk is slow the job would just take longer but shouldn't fail. This way eventually we can have openQA "cloud-ready" again ;)
I would be perfectly ok with you setting the ticket to "Resolved". However we need to ensure that on any next incident we do use the potentials of actual tests to tell us where to put our effort.
We could also think about bunching or truncating results, e.g. if there are more than $limit then results would be simply truncated (rather than incomplete or take forever) or create a packed archive on worker side and upload the archive (and optionally unpack on webui host).
Just a note: understand that this must be fixed, but please don't slow down uploading - we've notified that LTP tests on ipmi backend are already terribly slow due uploads like:
[2019-09-24T23:21:24.0481 CEST] [debug] [pid:520421] REST-API call: POST http://openqa.suse.de/api/v1/jobs/3398899/ status
Sorry if this is not related and see #57323 if interested.
It's hard to say for certain that this kind of problem won't ever appear again. But we can now run 10 parallel LTP tests on the staging machines with a single webui without problems, so it should at least be a lot less likely.
- Target version set to future
@pvorel there is no intent on slowing down uploading. Currently there is no further work planned in this ticket until #55904 is done. This ticket should really focus on jobs incompleting during upload while still continuing in the background, #55904 can try to cover performance.
How about the following idea: We already upload thumbnails and module results while the job is running but AFAIK for other log files we only do this after the job is done. Can we upload the log files during execution? Another topic could be worker and autoinst log which are both not complete until the job is done but at we could still upload parts of it and append missing parts later with an intelligent upload.
I think that makes generally sense but I'm not sure whether it will help with that concrete issue, e.g. if the majority of log files is generated at the end of one particular job module. Note that so far the other results are not uploaded continuously while the job is running but only on job module boundaries.
- Status changed from Blocked to New
- Assignee deleted (
okurz)
- Priority changed from Normal to Low
I am not sure if we have had changes in the meantime that would actually help with that but I think this is less important by now and also we are blocked by other tickets which we regard as low prio and do not track on the QA tools team backlog as well so I will put the ticket back to "New" to not need to track it anymore for now.
Also available in: Atom
PDF