Project

General

Profile

action #73126

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

No tests show unhandled output in main test summary log

Added by okurz 10 months ago. Updated 9 months ago.

Status:
Resolved
Priority:
Normal
Assignee:
Category:
Concrete Bugs
Target version:
Start date:
Due date:
% Done:

0%

Estimated time:
Difficulty:

Description

Observation

In https://app.circleci.com/pipelines/github/os-autoinst/openQA/4353/workflows/072d1477-46e0-4ae1-88f1-90740da73506/jobs/41809

[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)

Related issues

Copied to openQA Project - action #73156: test not failing but error showing up t/25-downloader.t: "Cannot determine file type for '/tmp/DptzoOZjyt/test"Resolved2020-10-09

History

#1 Updated by okurz 10 months 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

#2 Updated by okurz 10 months ago

  • Parent task set to #71926

#3 Updated by okurz 10 months 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

#4 Updated by mkittler 9 months ago

  • Assignee set to mkittler

#5 Updated by mkittler 9 months 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

#6 Updated by mkittler 9 months ago

  • Status changed from Workable to Resolved

PR has been merged

#7 Updated by okurz 9 months 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.

#8 Updated by okurz 9 months 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!

Also available in: Atom PDF