fedora-qa / fedora_openqa

#35 workstation_live default_install snapshot upload failing
Closed: Fixed Opened by adamwill.

Closed: Fixed
Reopen Issue

The last few days of Rawhide tests, workstation_live default_install has failed every day. The test completes fine, but it dies while uploading / trying to upload the post-completion hard disk snapshot. From today's attempt:

QEMU: qemu: terminating on signal 15 from pid 30807
sending magic and exit
received magic close
killing commands thread
Scalars leaked: -1
done joining commands thread
preparing hdd 1 for upload as disk_workstation_live_64bit.qcow2
Attempt to free unreferenced scalar: SV 0x4500db0, Perl interpreter: 0x17d6010 during global destruction.
Scalars leaked: 1
+++ worker notes +++
end time: 2016-01-27 15:59:45
result: done
uploading disk_workstation_live_64bit.qcow2
ERROR disk_workstation_live_64bit.qcow2: 502 response: Bad Gateway
uploading video.ogv
uploading vars.json
uploading serial0.txt
uploading autoinst-log.txt

From yesterday's:

QEMU: qemu: terminating on signal 15 from pid 966
sending magic and exit
received magic close
killing commands thread
Scalars leaked: -1
done joining commands thread
preparing hdd 1 for upload as disk_workstation_live_64bit.qcow2
Attempt to free unreferenced scalar: SV 0x3c5e980, Perl interpreter: 0xf34010 during global destruction.
Scalars leaked: 1
+++ worker notes +++
end time: 2016-01-26 16:37:02
result: done
uploading disk_workstation_live_64bit.qcow2
ERROR disk_workstation_live_64bit.qcow2: Connection error: Inactivity timeout
uploading video.ogv
uploading vars.json
uploading serial0.txt
uploading autoinst-log.txt

This seems to have started going wrong exactly at the time we went to openQA / os-autoinst 4.3: 2016-01-23. That was the first day we had 4.3 in production, and every day since then, at least one workstation_live default_install test (there are three, 32-bit BIOS, 64-bit BIOS, UEFI) has failed to upload its disk. We introduced snapshot saving on prod on 2015-12-17 with openQA 4.2, and AFAICS, we never had a single disk upload failure between then and 2016-01-23, so it seems like a fairly strong association.

Another point to note, though, is that the DNF transaction that upgraded openQA on the server also upgraded Apache, from httpd-2.4.17-3.fc23 to 2.4.18-1.fc23. So that could possibly also be involved. Also perl-libnet, from 3.07 to 3.08.

This may not be important, but: the logs from 4.2 runs do not have any messages about unreferenced/leaked scalars.

The generic_boot test upload has only failed once, on 2016-01-23. The generic_boot image is rather smaller; for today, for e.g., we have 00004427-disk_generic_boot_64bit.qcow2 and 00004430-disk_generic_boot_uefi.qcow2 that are ~3.5GiB, while 00004436-disk_workstation_live_uefi.qcow2 (the UEFI workstation upload succeeded today, the 64-bit BIOS failed) is ~6.85GiB. Obviously that's going to be a factor.

Obvious stuff to look into here:

  • do all the workstation generic_boot tests run at more or less the same time and thus wind up trying to upload their images at the same time? This could be a problem (I dunno how Apache / Mojo handle multiple concurrent 6GiB uploads, but I'm guessing 'not well'). This would be substantially easier to figure out if the goddamn logs were timestamped - I'll see if I can send a PR upstream for that.

  • can we identify any actual changes in openQA / os-autoinst 4.3 which might have a bearing here?

  • can we identify any apparently relevant changes in Apache or perl-libnet?

I think the answer to question 1 is 'no'. When the upload attempt fails, the job is cloned and retried (it actually took three attempts for the workstation_live UEFI upload to succeed today, it failed on the first two; even the generic_boot upload failed on the first try). The final attempt at the BIOS workstation_live default_install test today shows end time: 2016-01-27 15:59:45, which is well after all the other default_install tests had finished doing their uploads, so no other snapshot upload should have been going on at that time.

The Apache log has this:

[Wed Jan 27 16:00:49.139705 2016] [proxy_http:error] [pid 31540] (20014)Internal error (specific information not available): [client 10.5.124.155:46760] AH01102: error reading status line from remote server localhost:9526

10.5.124.155 is one of the worker boxes, so that seems like it may well have been the point where that particular attempt failed; i.e. openQA stopped responding to Apache (localhost:9526 is the openQA server, it runs on port 9526).

Unfortunately we don't have load monitoring on the box, apparently, so we can't check what the system load looked like at that point...

So I've twiddled a few things here and I hope it'll be enough to fix stuff.

First, infra wants to run an haproxy availability check for all web services. So I gave them a URL to use for checking if openQA is up. I didn't realize they were going to hit it twelve times every ten seconds. The URL I gave them was a test_overview URL which generates some somewhat complex queries. So I had them switch to using /api/v1/jobs/1 , which should be a lot less work to render. We're also twiddling the frequency of the check, and may possibly turn it off entirely (since we don't have a second server to fail over to in any case, so an haproxy check isn't terribly useful).

I also figured out that Gru had got itself stuck in an endless loop again. I kind of hate Gru's design. What Gru does is look for the highest-priority task in the queue, and try to run it. If it succeeds, it moves on to the next highest priority task immediately. If it exhausts the queue, it starts sleeping 5 seconds between checking the queue. Fine.

The problem is what it does when a task fails: nothing. It just leaves it in the queue and loops back around. So until a higher priority task appears, it just tries the failed task over and over again. If the failure isn't transient, it'll just keep failing over and over and over and over. It never goes to sleep. It never decides "this just isn't working out" and puts the task off to the side and warns the admin or anything. Nope. It just loops around eternally, failing again and again and again. When a higher priority task appears it'll do that, but then go right back to looping on the broken task. Lower priority tasks will never get run until the failing task is cleared out somehow.

This is a crappy design and I should really send them a patch to make it less crappy. But for now, I just figured out why one of the gru tasks was failing; it came down to some JSON files being malformed. openQA doesn't guard against this, so when a gru task which involves reading those files gets run, it barfs on the bad JSON, cue eternal loop of failure. I've sent a PR for this, and applied the fix on openqa01 to get the blocked task cleared out.

The eternal loop of failure was causing quite a lot of load on the server. So with the combination of fixing that problem and mitigating the haproxy availability check load, background load should be down a lot. I'm hoping that will turn out to resolve this problem, i.e. I'm hoping the uploads were failing because of the excessive load on the server from the availability checks and the gru failure.

All the snapshot uploads for today's tests worked. I'm gonna say this is good now, if the problem shows up again I'll re-open.

This issue has been migrated to Fedora Forge:
https://forge.fedoraproject.org/quality/fedora_openqa/issues/35

Please continue any further discussion there.
Metadata
None
None
None
None
Lowest
Static archive. pagure.io was sunset in 2026; this is a read-only snapshot.
Red Hat Logo

Fedora is sponsored by Red Hat. Learn more about the relationship between Red Hat and Fedora »

© Red Hat, Inc. and others.