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
75%
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 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 onesame 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
Related issues
History
#1
Updated by okurz 7 months 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 7 months 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 7 months ago
Created https://github.com/os-autoinst/openQA/pull/3428 to make sure unhandled output shows up in the circleci log view again.
#5
Updated by cdywan 7 months 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.
#7
Updated by cdywan 7 months 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 7 months 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 6 months ago
- Copied to action #73123: t/14-grutasks.t shows errors but still succeeds added
#10
Updated by okurz 6 months ago
- Copied to action #73126: No tests show unhandled output in main test summary log added
#11
Updated by okurz 6 months ago
- Copied to action #73129: t/14-grutasks.t takes multiple minutes within circleCI, only 6s locally added
#12
Updated by okurz 6 months 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.
#16
Updated by szarate 6 months ago
See for the reason of tracker change: http://mailman.suse.de/mailman/private/qa-sle/2020-October/002722.html