Project

General

Profile

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

Status:
Workable
Priority:
Low
Assignee:
-
Category:
Concrete Bugs
Target version:
QA - future
Start date:
2020-09-26
Due date:
% Done:

75%

Estimated time:
(Total: 0.00 h)
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 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

action #73123: t/14-grutasks.t shows errors but still succeedsResolvedmkittler

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

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

action #73156: test not failing but error showing up t/25-downloader.t: "Cannot determine file type for '/tmp/DptzoOZjyt/test"Resolvedmkittler

Related issues

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

History

#1 Updated by okurz over 2 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).

#2 Updated by okurz over 2 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

#3 Updated by okurz over 2 years ago

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

#4 Updated by kraih over 2 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

#5 Updated by cdywan over 2 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.

#6 Updated by okurz over 2 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?

#7 Updated by cdywan over 2 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.

#8 Updated by okurz over 2 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.

#9 Updated by okurz over 2 years ago

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

#10 Updated by okurz over 2 years ago

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

#11 Updated by okurz over 2 years ago

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

#12 Updated by okurz over 2 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.

#13 Updated by okurz over 2 years ago

  • Description updated (diff)
  • Target version deleted (Ready)

#14 Updated by okurz over 2 years ago

  • Target version set to Ready

#15 Updated by szarate over 2 years ago

  • Tracker changed from action to coordination
  • Status changed from Blocked to New

#17 Updated by okurz over 2 years ago

  • Status changed from New to Blocked

#18 Updated by okurz about 2 years ago

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

see subtask (in future)

Also available in: Atom PDF