QA (public) » openQA Project (public)

I'm seeing at least 3 variants between the clones:

3187414

[2019-07-31T04:34:32.0860 CEST] [info] [pid:39796] Uploading logs_from_installation_system-y2logs.tar.bz2
[2019-07-31T04:34:33.0564 CEST] [info] [pid:39796] Uploading SLED-12-SP5-0206-x86_64_for_regression.qcow2
[2019-07-31T05:05:29.0311 CEST] [error] [pid:39796] Failed uploading chunk
[2019-07-31T05:05:29.0311 CEST] [error] [pid:39796] Error uploading SLED-12-SP5-0206-x86_64_for_regression.qcow2:     502 response: Proxy Error
[2019-07-31T05:05:29.0311 CEST] [error] [pid:39796] Upload failed for chunk 1262
[2019-07-31T05:12:03.0469 CEST] [info] [pid:39796] Uploading video.ogv

3189506 3191057

SLE-12-SP5-Desktop-DVD-x86_64-Build0206-Media1.iso available but no log or other assets

3189714

[2019-07-31T06:06:28.691 CEST] [debug] killing command server 17377 because test execution ended
[2019-07-31T06:06:28.691 CEST] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20123/leIhI7s9iMQRNMaB/broadcast
[2019-07-31T06:06:43.702 CEST] [debug] isotovideo: unable to inform websocket clients about stopping command server: Request timeout at /usr/bin/isotovideo line 172.
[2019-07-31T06:06:44.704 CEST] [error] can_read received kill signal at /usr/lib/os-autoinst/myjsonrpc.pm line 91.
[2019-07-31T06:06:44.711 CEST] [debug] commands process exited: 0
[2019-07-31T06:06:45.712 CEST] [debug] done with command server
[2019-07-31T06:06:45.712 CEST] [debug] isotovideo done

I canceled this job yesterday and restarted it today, and it passed: https://openqa.suse.de/tests/3198655

I wonder if it's related with recent openQA deployment or OSD site asset cleanup.

I have reported a pretty similar problem here: https://progress.opensuse.org/issues/54869, but in this case we do not always have the "502 response" error in the logs.
It is blocking several of our tests because it happens almost everytime on aarch64

By now, Saturday morning, the load has decreased. OSD has a mean load of below 4.0 . Also currently there are no jobs in uploading . I am reviewing new test failures but so far no severe openQA or infrastructure related problems. I can see that all jobs that had problems in uploading, i.e. ones that went incomplete in the end, were restarted and all in the end succeeded so I am not even sure if we have any regression here or just even more tests that were scheduled causing an overload. Especially s390x-kvm-sle12 seems to lag behind and still has some scheduled jobs.

I have the feeling that the problem that we originally wanted to fix with "caching" is not really fixed but moved to the "uploading" side. (IMHO – as I originally raised for caching – this is a problem that openQA should not even originally have tried to solve but the infrastructure. If it would be for me I would not have any caching nor chunk uploading in openQA.)

Ideas I have for improvement:

• Stresstests for openQA, e.g. start 20 workers which all want to upload in parallel
• Serialize the "create_hdd" scenarios to prevent too many parallel jobs
• Limit the number of concurrent upload jobs on the websockets server side
  • Actually reduce the numbers of possible apache workers to prevent I/O overload
  • Queue up jobs for uploading by letting them wait before "Uploading" until there is enough ressource on the webUI host available again
• Allow longer time lingering in "Uploading", e.g. Increase the timeout within the websocket connections (if this makes sense)
• Improve feedback for jobs in "Uploading"
  • prevent the repeating auto-reloads of the webpage
  • provide the current status from logs over the webUI
• Think about more efficient use of assets:
  • Why would a worker host need to upload images to another machine when afterwards the image is only used on the same worker host?
  • Reuse caching for uploading as well?

Discussed with mkittler and he created #55112 in response. Nothing more is planned on short-term so we could even reduce prio again but I think keeping it in "Feedback" on "Urgent" is also ok for now because we all need to be aware of this problem even if not doing anything except for waiting.

I've looked into the chunked upload code a bit, and it does look fairly inefficient. If that's a reason for this issue i'm not sure. But since nobody dares touch the code, it will need to be cleaned up at some point anyway. The worker would also benefit a lot from making the uploader non-blocking, allowing for status updates to the WebSocket server at all times. This would be a new epic ticket though, and okurz made it clear that he would like to collect more data before we do anything, so i'll hold off for now.

Discussed the topic during the team meetup on 2019-08-06 and we have elaborated the point "limit concurrent update jobs on server side" as well as a necessary rework of uploading code vs. downloading.

Still there is very high load on osd. Trying more severe measures to decrease it now: Stopping the service "telegraf" as that daemon seems to have quite some CPU usage and we are currently closely monitoring the instance manually anyway.

after the a bit more lazy weekend osd is back to high load in the 20's, sometimes 30's. As "collectd" is now reporting the error "write_graphite plugin: Connecting to openqa-monitoring.qa.suse.de:2003 via tcp failed. The last error was: failed to connect to remote host: No route to host" and it is very much visible in the CPU time I am also stopping the service for now:

systemctl stop collectd

IMHO both telegraf and collectd should run with higher nice level (CPU+I/O). What could also be done is to run rsyncd with a higher nice same also for vsftpd as the services directly on the instance should have priority over the non-interactive remote access.

In the latest build of SLE 12 job didn't get incomplete, but image was not properly published: https://openqa.suse.de/tests/3245595/file/autoinst-log.txt
This looks worse than before as appears that everything is fine and then it's visible only on child jobs, which should not be triggered at all.

[2019-08-14T01:52:10.0383 UTC] [error] [pid:18763] Failed uploading chunk
[2019-08-14T01:52:10.0384 UTC] [error] [pid:18763] Error uploading sle-12-SP5-aarch64-Build0265-Server-DVD@aarch64-gnome-encrypted.qcow2: 502 response: Proxy Error
[2019-08-14T01:52:10.0384 UTC] [error] [pid:18763] Upload failed for chunk 837

I am trying to reduce the overload by stopping workers, e.g. I stopped all worker instances on openqaworker9 now:

okurz@openqa:~> sudo salt -C 'G@roles:worker' cmd.run 'systemctl status openqa-worker@\* | grep -c "Active: active"'
…
openqaworker9.suse.de:
    24
okurz@openqa:~> sudo salt -C 'openqaworker9*' cmd.run 'systemctl stop openqa-worker.target'
openqaworker9.suse.de:
okurz@openqa:~> sudo salt -C 'G@roles:worker' cmd.run 'systemctl status openqa-worker@\* | grep -c "Active: active"'
…
openqaworker9.suse.de:
    0

Also I temporarily disabled the build view on the index page with an override template:

openqa:/etc/openqa/templates # cat main/index.html.ep
% layout 'bootstrap';
% title '';

%= include 'layouts/info'

% content_for 'ready_function' => begin
    setupIndexPage();
    hideNavbar();
    alignBuildLabels();
% end

<div class="jumbotron">
  <div class='container'>
    <div class="row">
      <div class="col-md-9">
        %= include_branding 'docbox'
      </div>
      <div class="col-md-3 hidden-sm-down">
        %= include_branding 'sponsorbox'
      </div>
    </div>
  </div>
</div>

<div id="build-results">
Temporarily disabled due to performance reasons. See <a href="https://progress.opensuse.org/issues/54902">https://progress.opensuse.org/issues/54902</a> for details
</div>

The page still does not load very fast, probably the lookup of job groups is also not that efficient.

I nice'd rsyncd, salt-master, obslisten, smbd, vsftpd, cupsd (?), salt-minion

Also stopped openqaworker6 now. Problem is that they are re-enabled. Need to change salt config: https://gitlab.suse.de/openqa/salt-pillars-openqa/commit/8f933532b2abca2c324dbb4d3f438464afda6edd but haven't yet restarted workers or something as there so many jobs running.

EDIT (after the night): The change seems to be effective now, less worker instances running

Also stopped many instances on openqaworker13 with https://gitlab.suse.de/openqa/salt-pillars-openqa/commit/d4fb47ae2d7ba74a5aa55ae50a9b919bc2dc933a as I have the feeling this helps.

I created an infra ticket to ask if the nr. of CPUs can be increased.

https://openqa.suse.de/tests/3256416 is a recent example:

openqa:/home/okurz # grep 3256416 /var/log/openqa
[2019-08-16T06:15:17.0953 CEST] [warn] dead job 3256416 aborted and duplicated 3257259
[2019-08-16T06:15:23.0943 CEST] [info] Got status update for job 3256416 with unexpected worker ID 1123 (expected no updates anymore, job is done with result incomplete)
…

cloned https://openqa.suse.de/tests/3257259 is fine but the overall upload process took 1.5h as can be seen in https://openqa.suse.de/tests/3257259/file/worker-log.txt

Seems that at least one person (asmorodskyi) was confused with my message that I put on the index page so I changed the text to "Build results on the index page are temporarily disabled due to performance reasons, Use /tests or the job group pages as usual" instead.

As often, could be the problems we observe are older than the ticket reporting time. I suspect the "worker rework" from Martchus as biggest trigger, e.g. also see #55628 about problems to install packages from osd repos from 21 days ago. But – as always – could also be we had underlying problems, e.g. limited performance of osd, that are just made more obvious or more severe with recent code changes.

As multiple persons were mistaken by the index page replacement we have disabled it again for now. Apparently some have not read the text :(

EDIT: Crosschecking with @mkittler we found out that I did not use it to the full extent as the template simply did not render results which can help a little bit with less perl code executed but the bunch of time saving is when we skip over the complete query in the backend code.

coolo has pointed out that the obs sync plugin was using very inefficient, blocking calls to external tools which can clog the mojo workers completely until the requests are completed which can lead to the severe timeouts as we have seen. Good that the still open PR https://github.com/os-autoinst/openQA/pull/2225 did not really make that obvious :(

This wasn't the culprit though. I pimped up our monitoring, but it didn't help.

The disk just stalls without warning - Rudi and I can see the same on the underlying VM host and it turns out the link to the netapp generates a lot of Tx errors. Let's hope this can be fixed.

collectd and cups are gone and not sure what obslisten is.

vsftpd, smbd and rsyncd have all in common that they are generally very low on CPU usage, so a nice level won't help you. The IO they're doing is going to doom you if your disk bandwith is low - and nice level won't help you there as virtual disks use deadline IO scheduler.

Leaves telegraf - it's using quite a lot of CPU as it's parsing quite some log files all the time. But in case something goes wrong, it's our only hope to find out what's going wrong. It's not hogging the CPU whatsoever as it runs in intervals - and if needed we can enlarge the interval, but increasing its nice level would only result in 'we know something was strange at 14:00 as the load increased but after that we can't say what happened as we have no data'. See https://en.wikipedia.org/wiki/Schrödinger%27s_cat for details

coolo wrote:

[…] not sure what obslisten is.

the obs rsync plugin or daemon (?).

Leaves the suggestions from #54902#note-10

This is an autogenerated message for openQA integration by the openqa_review script:

This bug is still referenced in a failing openQA test: minimal+base+sdk+proxy_SCC-postreg
https://openqa.suse.de/tests/3388694