QA » openQA Project

190775 is even more brutal:


no change 1551
MATCH(rebootnow-20131217:0.00)
MATCH(rebootnow-20141204:0.00)
MATCH(rebootnow-20150409:0.00)
MATCH(rebootnow-390x-20150709:0.00)
no match 1550
MATCH(rebootnow-20131217:0.00)
MATCH(rebootnow-20141204:0.00)
MATCH(rebootnow-20150409:0.00)
MATCH(rebootnow-390x-20150709:0.00)
no match 1526
MATCH(rebootnow-20131217:0.00)
MATCH(rebootnow-20141204:0.00)
MATCH(rebootnow-20150409:0.00)
MATCH(rebootnow-390x-20150709:0.00)
no match 1360
no change 1350
no change 1350
no change 1349


We're missing 166 seconds there! This is an environment error we need to error on - instead of pretending.

I reduced it to capture_screenshot taking way too long. Normally it's done in < 0.1s, but the highscore in my tests was 33.4s. capture_screenshot is creating a new file and it seems problematic to the filesystem ;(

Reenabled the workers as it a) didn't really change anything and b) we now reschedule the job if it happens.

But it breaks in all kind of places ;(

Debug: /var/lib/openqa/share/tests/sle/tests/console/curl_https.pm:17 called testapi::validate_script_output
<<< wait_serial(regex='SCRIPT_FINISHED', timeout=10)
WARNING: capture_screenshot took 9.93 seconds - slow IO?
>>> wait_serial: SCRIPT_FINISHED: fail
test curl_https died at /usr/lib/os-autoinst/basetest.pm line 274.

maybe this is a regression because of changes within os-autoinst || openQA || test distri. You should have observed this earlier if not…

we did notice strange "overload" problems before. We just couldn't name the reason so far.

We should improve the error checking, e.g. in cases like these:

MATCH(bootmenu-20141112:0.00)
no match 15
MATCH(bootmenu-20141112:0.00)
no match 14
MATCH(bootmenu-20141112:0.00)
no match 13
MATCH(bootmenu-20141112:0.00)
no match 11
MATCH(bootmenu-20141112:0.00)
no match 11
WARNING: capture_screenshot took 49.06 seconds - slow IO?
MATCH(bootmenu-20141112:0.00)
>>> assert_screen: match=inst-bootmenu timed out after 15
test rescuesystem failed at /usr/lib/os-autoinst/basetest.pm line 274.
WARNING: capture_screenshot took 0.55 seconds - slow IO?
test rescuesystem failed

bad luck that the capture die happened in second 0, the warning is correct - but it doesn't abort the test where it should have been incomplete here, too.
IMHO it must be as complicated as "if we fail in an assert_screen AND we reported stalls in before, judge this as a reason and return incomplete. To make the "WARNING" memorable to os-autoinst we could probably use a leaky bucket error counter and check the bucket fill grade at test outcome to decide if it should be incomplete or pass. I know, sounds "too intelligent" but I am sure this is correct.

Of course, it is more important to fix the gaps appearing rather than get lost in statistical analysis but the same problem might appear again anyway in the future because of differing reasons as long as we don't use a hard-realtime system for monitoring the SUTs.

looks like https://openqa.suse.de/tests/200116/file/autoinst-log.txt fails because of "stall", I will retrigger the test. Tell me if I am wrong.

https://openqa.suse.de/tests/200116 doesn't appear failed to me

the job did not fail but the zypper_in test module: https://openqa.suse.de/tests/200116/modules/zypper_in/steps/3 From the logs it looked like because of the issue at hand but I don't remember in detail why.

from
https://openqa.suse.de/tests/204149/file/autoinst-log.txt

WARNING: enqueue_screenshot took 62.81 seconds - slow IO? (opencv: 0.01 - encoder: 62.80)

and then dies shortly after with

WARNING: check_asserted_screen took 1.34 seconds - make your needles more specific
>>> assert_screen: match=generic-desktop timed out after 30