Project

General

Profile

Actions

action #73126

closed

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 almost 4 years ago. Updated almost 4 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
Category:
Regressions/Crashes
Target version:
Start date:
Due date:
% Done:

0%

Estimated time:

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 1 (0 open1 closed)

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"Resolvedmkittler2020-10-09

Actions
Actions #1

Updated by okurz almost 4 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
Actions #2

Updated by okurz almost 4 years ago

  • Parent task set to #71926
Actions #3

Updated by okurz almost 4 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
Actions #4

Updated by mkittler almost 4 years ago

  • Assignee set to mkittler
Actions #5

Updated by mkittler almost 4 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

Actions #6

Updated by mkittler almost 4 years ago

  • Status changed from Workable to Resolved

PR has been merged

Actions #7

Updated by okurz almost 4 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.

Actions #8

Updated by okurz almost 4 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!

Actions

Also available in: Atom PDF