Project

General

Profile

Actions
Copy link

coordination #71926

open

[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 by okurz over 4 years ago. Updated about 4 years ago.

Status:
Workable
Priority:
Low
Assignee:
-
Category:
Regressions/Crashes
Target version:
QA (public) - future
Start date:
2020-09-26
Due date:
% Done:

75%

Estimated time:
(Total: 0.00 h)

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 two differences: Insane long runtime within circleCI compared to just 6s locally but locally I have errors which do not fail the test. I can reproduce my local observations in 20 reruns with the same observation. I wonder if this is reproducible for anyone else. Comparably small runtime was confirmed by others.

Acceptance criteria

  • AC1: No unhandled error messages in non-verbose output shown #73126
  • AC2: Runtime within CI is comparable to local runtime, e.g. less than 30s #73129

Suggestions

  • DONE: Crosscheck locally if anyone can reproduce the observation from CI or my (okurz's) local one same for others
  • If the error messages are expected, catch them with Test::Output, otherwise prevent them (or even better fail tests if there is any unexpected output)
  • In case excessive runtime is reproducible in any environment, e.g. only within CI, with Devel::Cover, in a container, etc., then find a way to reduce runtime significantly

Subtasks 4 (1 open — 3 closed)

action #73123: t/14-grutasks.t shows errors but still succeedsResolvedmkittler2020-09-26

Actions
action #73126: No tests show unhandled output in main test summary logResolvedmkittler

Actions
action #73129: t/14-grutasks.t takes multiple minutes within circleCI, only 6s locallyWorkable

Actions
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

Related issues 1 (0 open — 1 closed)

Related to openQA Project (public) - action #71464: Show output of failed tests within circleci log view, like on local prove calls, not only "Tests" tabResolvedokurz2020-09-17

Actions
Actions
Copy link
 #1

Updated by okurz over 4 years ago

  • Status changed from Workable to Feedback
  • Assignee set to okurz

Ok, found out the first part already: https://circle-production-customer-artifacts.s3.amazonaws.com/picard/58f7029dc9e77c000129905e/5f6df8cd2a301e095fa7ca33-0-build/artifacts/artifacts/14-grutasks.t?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Date=20200926T213349Z&X-Amz-SignedHeaders=host&X-Amz-Expires=60&X-Amz-Credential=AKIAJR3Q6CR467H7Z55A%2F20200926%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Signature=3248db1660d544b054e93e7ddb7f7e80ca9c066f312e1894f6b932712a3b4db6 shows that the artifact with the complete output has the error message included. This means that any unhandled output is not showing up in circleCI log output at all. I consider this bad and one more reason why the output redirection is flawed. With this I can handle the output using Test::Output as normal: https://github.com/os-autoinst/openQA/pull/3427

This does not cover the excessive runtime part (yet).

Actions
Copy link
 #2

Updated by okurz over 4 years ago

  • Related to action #71464: Show output of failed tests within circleci log view, like on local prove calls, not only "Tests" tab added
Actions
Copy link
 #3

Updated by okurz over 4 years ago

Created https://github.com/os-autoinst/openQA/pull/3428 to make sure unhandled output shows up in the circleci log view again.

Actions
Copy link
 #4

Updated by kraih over 4 years ago

On my machine it takes 7 seconds.

ok
All tests successful.
Files=1, Tests=36,  7 wallclock secs ( 0.10 usr  0.03 sys +  2.70 cusr  2.06 csys =  4.89 CPU)
Result: PASS
Actions
Copy link
 #5

Updated by livdywan over 4 years ago

okurz wrote:

[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
so two differences: Insane long runtime within circleCI compared to just 6s locally but locally I have errors which do not fail the test. I can reproduce my local observations in 20 reruns with the same observation. I wonder if this is reproducible for anyone else.

The above errors are present on the log in CircleCI.

It's 12 wallclock secs for me.

Actions
Copy link
 #6

Updated by okurz over 4 years ago

cdywan wrote:

The above errors are present on the log in CircleCI.

they are? Can you show me where?

It's 12 wallclock secs for me.

ok, good. So as expected the problem is only within circleCI, maybe because of Devel::Cover?

Actions
Copy link
 #7

Updated by livdywan over 4 years ago

okurz wrote:

cdywan wrote:

The above errors are present on the log in CircleCI.

they are? Can you show me where?

In 14-grutasks.t under Artifacts.

Actions
Copy link
 #8

Updated by okurz over 4 years ago

The above errors are present on the log in CircleCI.

they are? Can you show me where?

In 14-grutasks.t under Artifacts.

Yes, correct. This is why I created https://github.com/os-autoinst/openQA/pull/3428 so that we have the same behaviour locally as within circleCI again regarding showing unhandled log output as well as failed test context.

Actions
Copy link
 #9

Updated by okurz about 4 years ago

  • Copied to action #73123: t/14-grutasks.t shows errors but still succeeds added
Actions
Copy link
 #10

Updated by okurz about 4 years ago

  • Copied to action #73126: No tests show unhandled output in main test summary log added
Actions
Copy link
 #11

Updated by okurz about 4 years ago

  • Copied to action #73129: t/14-grutasks.t takes multiple minutes within circleCI, only 6s locally added
Actions
Copy link
 #12

Updated by okurz about 4 years ago

  • Subject changed from t/14-grutasks.t takes multiple minutes within circleCI, only 6s locally (but errors but still succeeds?) to [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
  • Description updated (diff)
  • Status changed from Feedback to Blocked
  • Priority changed from High to Low

PR merged. https://app.circleci.com/pipelines/github/os-autoinst/openQA/4451/workflows/2ba463f6-0465-47ae-b4a5-9c8022eef418/jobs/42666/steps is one example showing that we again have useful output. So we are ready to start with the actual work but I think it's easier if we make that in specific subtasks so that people are better motivated and know when they are done. Tracked in subtasks created.

Actions
Copy link
 #13

Updated by okurz about 4 years ago

  • Description updated (diff)
  • Target version deleted (Ready)
Actions
Copy link
 #14

Updated by okurz about 4 years ago

  • Target version set to Ready
Actions
Copy link
 #15

Updated by szarate about 4 years ago

  • Tracker changed from action to coordination
  • Status changed from Blocked to New
Actions
Copy link
 #17

Updated by okurz about 4 years ago

  • Status changed from New to Blocked
Actions
Copy link
 #18

Updated by okurz about 4 years ago

  • Status changed from Blocked to Workable
  • Assignee deleted (okurz)
  • Target version changed from Ready to future

see subtask (in future)

Actions
Copy link

Also available in: Atom PDF