action #95024
closedopenQA test t/ui/26-jobs_restart.t very unstable (already marked as unstable) size:M
Description
Observation¶
RETRY=5 timeout -s SIGINT -k 5 -v $((5 * (5 + 1) ))m tools/retry prove -l --harness TAP::Harness::JUnit --timer t/ui/26-jobs_restart.t
Retry 1 of 5 …
[19:34:35] t/ui/26-jobs_restart.t .. All 10 subtests passed
[19:35:36]
Test Summary Report
-------------------
t/ui/26-jobs_restart.t (Wstat: 14 Tests: 10 Failed: 0)
Non-zero wait status: 14
Files=1, Tests=10, 60.7488 wallclock secs ( 0.36 usr 0.05 sys + 49.70 cusr 1.54 csys = 51.65 CPU)
Result: FAIL
Retry 2 of 5 …
[19:35:37] t/ui/26-jobs_restart.t .. All 10 subtests passed
[19:36:37]
Test Summary Report
-------------------
t/ui/26-jobs_restart.t (Wstat: 14 Tests: 10 Failed: 0)
Non-zero wait status: 14
Files=1, Tests=10, 60.8001 wallclock secs ( 0.36 usr 0.03 sys + 49.43 cusr 1.59 csys = 51.41 CPU)
Result: FAIL
Retry 3 of 5 …
[19:36:38] t/ui/26-jobs_restart.t .. All 10 subtests passed
[19:37:39]
Test Summary Report
-------------------
t/ui/26-jobs_restart.t (Wstat: 14 Tests: 10 Failed: 0)
Non-zero wait status: 14
Files=1, Tests=10, 60.7867 wallclock secs ( 0.36 usr 0.02 sys + 49.28 cusr 1.55 csys = 51.21 CPU)
Result: FAIL
Retry 4 of 5 …
[19:37:40] t/ui/26-jobs_restart.t .. All 10 subtests passed
[19:38:41]
Test Summary Report
-------------------
t/ui/26-jobs_restart.t (Wstat: 14 Tests: 10 Failed: 0)
Non-zero wait status: 14
Files=1, Tests=10, 60.8044 wallclock secs ( 0.35 usr 0.03 sys + 49.73 cusr 1.48 csys = 51.59 CPU)
Result: FAIL
Retry 5 of 5 …
[19:38:42] t/ui/26-jobs_restart.t .. All 10 subtests passed
[19:39:42]
Test Summary Report
-------------------
t/ui/26-jobs_restart.t (Wstat: 14 Tests: 10 Failed: 0)
Non-zero wait status: 14
Files=1, Tests=10, 60.8018 wallclock secs ( 0.38 usr 0.02 sys + 49.00 cusr 1.59 csys = 50.99 CPU)
Result: FAIL
make[2]: *** [Makefile:188: test-unit-and-integration] Error 1
make[2]: Leaving directory '/home/squamata/project'
make[1]: *** [Makefile:183: test-with-database] Error 2
make[1]: Leaving directory '/home/squamata/project'
make: *** [Makefile:168: test-unstable] Error 2
Exited with code exit status 2
Expected result¶
- At least back to 1/3 failures, not more, better less than 0/100 failures
Suggestions¶
The tests report "All 10 subtests passed" but then fail with "Non-zero wait status: 14". We had similar cases in the past. This has likely something to do with the cleanup of background processes. Maybe we introduced a regression lately so that this background handling behaves different
- I suggest to try to reproduce locally, bisect between "last good" and "first bad" to find the culprit
- docs/Contributing.asciidoc explains that "Non-zero wait status: 14" just means that the test consistently times out now so something makes it super-slow or the test effectively never ends. This can be easily checked locally by just executing the test some times
Updated by okurz over 3 years ago
- Subject changed from openQA test t/ui/26-jobs_restart.t very unstable (already marked as unstable) to openQA test t/ui/26-jobs_restart.t very unstable (already marked as unstable) size:M
- Description updated (diff)
- Status changed from New to Workable
Updated by okurz over 3 years ago
- Related to action #95009: unstable/flaky test t/ui/12-needle-edit.t size:M added
Updated by ilausuch over 3 years ago
- Status changed from Workable to In Progress
- Assignee set to ilausuch
Updated by ilausuch over 3 years ago
I am having an other kind of error
Bailout called. Further testing stopped: clickElement: Server returned error message Label not found for "last T2_SUBTEST_WRAPPER" at /usr/lib/perl5/5.32.1/Test2/Hub/Subtest.pm line 67. at /home/openqa/openQA-dev/repos/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:95
Bail out! clickElement: Server returned error message Label not found for "last T2_SUBTEST_WRAPPER" at /usr/lib/perl5/5.32.1/Test2/Hub/Subtest.pm line 67. at /home/openqa/openQA-dev/repos/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:95
Updated by okurz over 3 years ago
I have seen the same in other test modules I think. Likely this is also a symptom of recent slowdown. Seems like something in 2021-06 made computers slow everywhere :( Be sure to be rebased on recent changes of timeout bumps by tinita.
Updated by tinita over 3 years ago
@ilausuch if this is what you get locally, try disabling the time limit. I have the feeling that this kind of error is related to our timeout settings.
Updated by ilausuch over 3 years ago
Yes is a timeout problem, if I add 10s extra it works. But I cannot get the described error locally
Updated by ilausuch over 3 years ago
I cannot reproduce this error locally, any ideas?
Updated by okurz over 3 years ago
well, have you read the suggestions? We know that the error in production means "timeout exceeded" and you just confirmed with the help of Tina that you also run into timeouts. As the suggestions state we should try to bisect to find out if any of our changes within our repo caused a slow-down, assuming you can identify a "last good". If you can't then we can accept the hypothesis of "other dependant factors that we can't control made everything slower" and we just bump the timeout in the test file.
Updated by tinita over 3 years ago
It doesn't look like the error in CircleCI is a timeout
or TimeLimit issue. Looking at the timestamps, the test doesn't run very long.
But it could of course be a different kind of timeout.
Something that happens at the end when Test::More has already reported that all tests were successful, but still the exit code is non-zero.
Maybe ssh into CircleCI to play around would be helpful. (As soon as CircleCI starts running actual tests again).
Updated by tinita over 3 years ago
Oh wait, I didn't look at the TimeLimit value. It's 10. So yeah, bumping the timeout would be my suggestion.
Updated by okurz over 3 years ago
tinita wrote:
It doesn't look like the error in CircleCI is a
timeout
or TimeLimit issue. Looking at the timestamps, the test doesn't run very long.
Have you read https://progress.opensuse.org/issues/95024#Suggestions ? We already found out that "Non-zero wait status: 14" effectively means that the program ends after handling SIGALRM, which means "test timeout" for us.
Updated by openqa_review over 3 years ago
- Due date set to 2021-07-22
Setting due date based on mean cycle time of SUSE QE Tools
Updated by okurz over 3 years ago
- Assignee changed from ilausuch to okurz
- Priority changed from Urgent to High
As suggested by ilausuch I am taking over for him.
Seems this does not fail in CI anymore since recent timeout bumps. I am investigating locally how long the test takes now.
Without changes in current state locally count_fail_ratio prove -l t/ui/26-jobs_restart.t
## Run 1
t/ui/26-jobs_restart.t .. 4/? Bailout called. Further testing stopped: findElement: Server returned error message Label not found for "last T2_SUBTEST_WRAPPER" at /usr/lib/perl5/vendor_perl/5.26.1/Test2/Hub/Subtest.pm line 67. at /home/okurz/local/os-autoinst/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:95
FAILED--Further testing stopped: findElement: Server returned error message Label not found for "last T2_SUBTEST_WRAPPER" at /usr/lib/perl5/vendor_perl/5.26.1/Test2/Hub/Subtest.pm line 67. at /home/okurz/local/os-autoinst/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:95
## count_fail_ratio: Run: 1. Fails: 1. Fail ratio 100%
## Run 2
t/ui/26-jobs_restart.t .. 5/? Bailout called. Further testing stopped: executeScript: Server returned error message Label not found for "last T2_SUBTEST_WRAPPER" at /usr/lib/perl5/vendor_perl/5.26.1/Test2/Hub/Subtest.pm line 67. at /home/okurz/local/os-autoinst/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:95
FAILED--Further testing stopped: executeScript: Server returned error message Label not found for "last T2_SUBTEST_WRAPPER" at /usr/lib/perl5/vendor_perl/5.26.1/Test2/Hub/Subtest.pm line 67. at /home/okurz/local/os-autoinst/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:95
## count_fail_ratio: Run: 2. Fails: 2. Fail ratio 100%
## Run 3
t/ui/26-jobs_restart.t .. 4/? Bailout called. Further testing stopped: getElementText: Server returned error message Label not found for "last T2_SUBTEST_WRAPPER" at /usr/lib/perl5/vendor_perl/5.26.1/Test2/Hub/Subtest.pm line 67. at /home/okurz/local/os-autoinst/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:95
FAILED--Further testing stopped: getElementText: Server returned error message Label not found for "last T2_SUBTEST_WRAPPER" at /usr/lib/perl5/vendor_perl/5.26.1/Test2/Hub/Subtest.pm line 67. at /home/okurz/local/os-autoinst/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:95
## count_fail_ratio: Run: 3. Fails: 3. Fail ratio 100%
Bumping timeout from 10s to 20s:
## Run 1
t/ui/26-jobs_restart.t .. ok
All tests successful.
Files=1, Tests=10, 16 wallclock secs ( 0.11 usr 0.01 sys + 6.60 cusr 0.55 csys = 7.27 CPU)
Result: PASS
## count_fail_ratio: Run: 1. Fails: 0. Fail ratio 0%
## Run 2
t/ui/26-jobs_restart.t .. ok
All tests successful.
Files=1, Tests=10, 17 wallclock secs ( 0.13 usr 0.00 sys + 6.63 cusr 0.61 csys = 7.37 CPU)
Result: PASS
## count_fail_ratio: Run: 2. Fails: 0. Fail ratio 0%
## Run 3
t/ui/26-jobs_restart.t .. ok
All tests successful.
Files=1, Tests=10, 17 wallclock secs ( 0.12 usr 0.01 sys + 6.72 cusr 0.60 csys = 7.45 CPU)
Result: PASS
## count_fail_ratio: Run: 3. Fails: 0. Fail ratio 0%
## Run 4
t/ui/26-jobs_restart.t .. ok
All tests successful.
Files=1, Tests=10, 16 wallclock secs ( 0.11 usr 0.02 sys + 6.73 cusr 0.51 csys = 7.37 CPU)
Result: PASS
## count_fail_ratio: Run: 4. Fails: 0. Fail ratio 0%
## Run 5
t/ui/26-jobs_restart.t .. ok
All tests successful.
Files=1, Tests=10, 17 wallclock secs ( 0.12 usr 0.01 sys + 6.61 cusr 0.57 csys = 7.31 CPU)
Result: PASS
## count_fail_ratio: Run: 5. Fails: 0. Fail ratio 0%
Crosscheck on an older commit state of openQA, 80f3d69ae from 2021-06-11 reproduces the timeout problems so our codebase did not recently introduce such problems. Reproduced again on 627798bec from 2021-03-05 the last time when I was working on the same test file myself:
## Run 1
t/ui/26-jobs_restart.t .. 2/? Bailout called. Further testing stopped: getElementText: Server returned error message Label not found for "last T2_SUBTEST_WRAPPER" at /usr/lib/perl5/vendor_perl/5.26.1/Test2/Hub/Subtest.pm line 67. at /home/okurz/local/os-autoinst/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:93
FAILED--Further testing stopped: getElementText: Server returned error message Label not found for "last T2_SUBTEST_WRAPPER" at /usr/lib/perl5/vendor_perl/5.26.1/Test2/Hub/Subtest.pm line 67. at /home/okurz/local/os-autoinst/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:93
## count_fail_ratio: Run: 1. Fails: 1. Fail ratio 100%
## Run 2
t/ui/26-jobs_restart.t .. 6/? Bailout called. Further testing stopped: close: Server returned error message Label not found for "last T2_SUBTEST_WRAPPER" at /usr/lib/perl5/vendor_perl/5.26.1/Test2/Hub/Subtest.pm line 67. at /home/okurz/local/os-autoinst/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:93
FAILED--Further testing stopped: close: Server returned error message Label not found for "last T2_SUBTEST_WRAPPER" at /usr/lib/perl5/vendor_perl/5.26.1/Test2/Hub/Subtest.pm line 67. at /home/okurz/local/os-autoinst/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:93
## count_fail_ratio: Run: 2. Fails: 2. Fail ratio 100%
## Run 3
t/ui/26-jobs_restart.t .. 5/? Bailout called. Further testing stopped: switchToWindow: Server returned error message Label not found for "last T2_SUBTEST_WRAPPER" at /usr/lib/perl5/vendor_perl/5.26.1/Test2/Hub/Subtest.pm line 67. at /home/okurz/local/os-autoinst/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:93
FAILED--Further testing stopped: switchToWindow: Server returned error message Label not found for "last T2_SUBTEST_WRAPPER" at /usr/lib/perl5/vendor_perl/5.26.1/Test2/Hub/Subtest.pm line 67. at /home/okurz/local/os-autoinst/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:93
## count_fail_ratio: Run: 3. Fails: 3. Fail ratio 100%
## Run 4
t/ui/26-jobs_restart.t .. 6/? Bailout called. Further testing stopped: findElement: Server returned error message Label not found for "last T2_SUBTEST_WRAPPER" at /usr/lib/perl5/vendor_perl/5.26.1/Test2/Hub/Subtest.pm line 67. at /home/okurz/local/os-autoinst/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:93
FAILED--Further testing stopped: findElement: Server returned error message Label not found for "last T2_SUBTEST_WRAPPER" at /usr/lib/perl5/vendor_perl/5.26.1/Test2/Hub/Subtest.pm line 67. at /home/okurz/local/os-autoinst/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:93
## count_fail_ratio: Run: 4. Fails: 4. Fail ratio 100%
so it's slower on CI and on other people's computers as well as mine (Leap 15.2, not quite up-to-date right now). So most likely hypothesis (not entirely serious) is that the climate change caused this.
https://github.com/os-autoinst/openQA/pull/4020
Still running a longer statistics evaluation in my local env with runs=100 count_fail_ratio prove -l t/ui/26-jobs_restart.t
to decide if we can mark the test as stable again for CI. Testing for CI in https://github.com/os-autoinst/openQA/pull/4021
In some cases in between I got
## Run 36
t/ui/26-jobs_restart.t .. 2/?
# Failed test 'job is marked as restarted'
# at t/ui/26-jobs_restart.t line 125.
# got: 'minimalx@32bit'
# expected: 'minimalx@32bit (restarted)'
Bailout called. Further testing stopped: findChildElement: no such element: Unable to locate element: {"method":"xpath","selector":"./a[@title='new test']"} at /home/okurz/local/os-autoinst/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:95
FAILED--Further testing stopped: findChildElement: no such element: Unable to locate element: {"method":"xpath","selector":"./a[@title='new test']"} at /home/okurz/local/os-autoinst/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:95
## count_fail_ratio: Run: 36. Fails: 1. Fail ratio 2%
## Run 37
t/ui/26-jobs_restart.t .. ok
All tests successful.
Files=1, Tests=10, 19 wallclock secs ( 0.13 usr 0.01 sys + 7.82 cusr 0.77 csys = 8.73 CPU)
Result: PASS
## count_fail_ratio: Run: 37. Fails: 1. Fail ratio 2%
## Run 38
t/ui/26-jobs_restart.t .. ok
All tests successful.
Files=1, Tests=10, 18 wallclock secs ( 0.13 usr 0.01 sys + 7.87 cusr 0.67 csys = 8.68 CPU)
Result: PASS
## count_fail_ratio: Run: 38. Fails: 1. Fail ratio 2%
## Run 39
t/ui/26-jobs_restart.t .. ok
All tests successful.
Files=1, Tests=10, 20 wallclock secs ( 0.12 usr 0.02 sys + 8.20 cusr 0.72 csys = 9.06 CPU)
Result: PASS
## count_fail_ratio: Run: 39. Fails: 1. Fail ratio 2%
## Run 40
t/ui/26-jobs_restart.t .. ok
All tests successful.
Files=1, Tests=10, 19 wallclock secs ( 0.12 usr 0.02 sys + 8.14 cusr 0.76 csys = 9.04 CPU)
Result: PASS
## count_fail_ratio: Run: 40. Fails: 1. Fail ratio 2%
## Run 41
t/ui/26-jobs_restart.t .. 3/?
# Failed test 'job is marked as restarted'
# at t/ui/26-jobs_restart.t line 125.
# got: 'minimalx@32bit'
# expected: 'minimalx@32bit (restarted)'
Bailout called. Further testing stopped: findChildElement: no such element: Unable to locate element: {"method":"xpath","selector":"./a[@title='new test']"} at /home/okurz/local/os-autoinst/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:95
FAILED--Further testing stopped: findChildElement: no such element: Unable to locate element: {"method":"xpath","selector":"./a[@title='new test']"} at /home/okurz/local/os-autoinst/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:95
## count_fail_ratio: Run: 41. Fails: 2. Fail ratio 4%
## Run 42
t/ui/26-jobs_restart.t .. 2/?
# Failed test 'job is marked as restarted'
# at t/ui/26-jobs_restart.t line 125.
# got: 'minimalx@32bit'
# expected: 'minimalx@32bit (restarted)'
Bailout called. Further testing stopped: findChildElement: no such element: Unable to locate element: {"method":"xpath","selector":"./a[@title='new test']"} at /home/okurz/local/os-autoinst/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:95
FAILED--Further testing stopped: findChildElement: no such element: Unable to locate element: {"method":"xpath","selector":"./a[@title='new test']"} at /home/okurz/local/os-autoinst/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:95
## count_fail_ratio: Run: 42. Fails: 3. Fail ratio 7%
## Run 43
t/ui/26-jobs_restart.t .. 2/?
# Failed test 'job is marked as restarted'
# at t/ui/26-jobs_restart.t line 125.
# got: 'minimalx@32bit'
# expected: 'minimalx@32bit (restarted)'
Bailout called. Further testing stopped: findChildElement: no such element: Unable to locate element: {"method":"xpath","selector":"./a[@title='new test']"} at /home/okurz/local/os-autoinst/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:95
FAILED--Further testing stopped: findChildElement: no such element: Unable to locate element: {"method":"xpath","selector":"./a[@title='new test']"} at /home/okurz/local/os-autoinst/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:95
Updated by okurz over 3 years ago
- Status changed from In Progress to Feedback
other tests timed out as well, included fixes in https://github.com/os-autoinst/openQA/pull/4020 for now.
Updated by okurz over 3 years ago
https://github.com/os-autoinst/openQA/pull/4020 merged. Waiting for statistics from https://github.com/os-autoinst/openQA/pull/4021
Updated by okurz over 3 years ago
- Status changed from Feedback to Resolved
https://app.circleci.com/pipelines/github/os-autoinst/openQA/6976/workflows/bbb48a15-a74b-420d-ac57-36468b3833c9/jobs/65813?invite=true#step-108-110 reproduced after 9 runs the problem I saw locally. With this we are better than 1/3 failures