action #73126
closedcoordination #71926: [epic] t/14-grutasks.t takes multiple minutes within circleCI, only 6s locally (but errors but still succeeds?), and no log output visible in circleCI
No tests show unhandled output in main test summary log
Description
Observation¶
[14:37:26] t/14-grutasks.t ........................................... ok 274117 ms ( 0.22 usr 0.00 sys + 260.33 cusr 9.39 csys = 269.94 CPU)
but locally I have:
[21:33:58] t/14-grutasks.t .. 34/? [2020-09-26 21:34:04.39357] [15810] [error] Gru job error: No job ID specified.
[2020-09-26 21:34:04.44377] [15814] [error] Gru job error: Job 98765 does not exist.
[2020-09-26 21:34:04.51354] [15817] [error] Gru job error: Finalizing results of 1 modules failed
[21:33:58] t/14-grutasks.t .. ok 5976 ms ( 0.08 usr 0.01 sys + 3.34 cusr 0.90 csys = 4.33 CPU)
[21:34:04]
All tests successful.
Files=1, Tests=36, 6 wallclock secs ( 0.10 usr 0.01 sys + 3.34 cusr 0.90 csys = 4.35 CPU)
Result: PASS
so error messages locally which do not fail the test but are also not visible in circleCI. With https://github.com/os-autoinst/openQA/pull/3428 we brought back the output in prove summary log but now we need to crosscheck all tests again if they output anything which is not handled
Acceptance criteria¶
- AC1: No unhandled output in non-verbose output shown
Suggestions¶
- If any messages are expected, catch them with Test::Output, otherwise prevent them (or even better fail tests if there is any unexpected output)
Updated by okurz over 3 years ago
- Copied from coordination #71926: [epic] t/14-grutasks.t takes multiple minutes within circleCI, only 6s locally (but errors but still succeeds?), and no log output visible in circleCI added
Updated by okurz over 3 years ago
- Copied to action #73156: test not failing but error showing up t/25-downloader.t: "Cannot determine file type for '/tmp/DptzoOZjyt/test" added
Updated by mkittler over 3 years ago
The occurrence mentioned in the description has already been fixed but there's still one other occurrence of unhandled output.
Note that the difference between the CI and local run mentioned in the description is actually just caused by OPENQA_LOGFILE being set within the CI. I added an explanation in the documentation some time ago: https://github.com/os-autoinst/openQA/blob/master/docs/Contributing.asciidoc#logging-behavior
If any messages are expected, catch them with Test::Output
That also means one can not just do that without having these checks failing within the CI, see the PR: https://github.com/os-autoinst/openQA/pull/3483
Updated by okurz over 3 years ago
- Status changed from Resolved to Workable
We unfortunately misunderstood. You only fixed one case which was the example mentioned but there are more cases. E.g. following https://app.circleci.com/pipelines/github/os-autoinst/openQA?branch=master I found in "t":
[15:29:37] t/26-controllerrunning.t .................................. [2020-10-23 15:29:38.49997] [527] [debug] [PQOBTPDx] 200 OK (0s, ??/s)
[15:29:37] t/26-controllerrunning.t .................................. ok 4203 ms ( 0.00 usr 0.01 sys + 3.70 cusr 0.33 csys = 4.04 CPU)
[15:30:12] t/31-client_archive.t ..................................... 2+0 records in
2+0 records out
2097152 bytes (2.1 MB, 2.0 MiB) copied, 0.00168701 s, 1.2 GB/s
[15:30:12] t/31-client_archive.t ..................................... ok 9837 ms ( 0.04 usr 0.00 sys + 8.49 cusr 0.58 csys = 9.11 CPU)
so t/26-controllerrunning.t and t/31-client_archive.t need fixing. The other test groups are actually fine.
Updated by okurz over 3 years ago
- Status changed from Workable to Resolved
you created https://github.com/os-autoinst/openQA/pull/3486 which I just merged. Now we are done :) Man, you are fast!