Project

General

Profile

action #91527

coordination #39719: [saga][epic] Detection of "known failures" for stable tests, easy test results review and easy tracking of known issues

coordination #19720: [epic] Simplify investigation of job failures

Cleanup logging in autoinst-log.txt

Added by okurz 8 months ago. Updated 6 months ago.

Status:
Resolved
Priority:
Normal
Assignee:
Category:
Feature requests
Target version:
Start date:
2021-04-21
Due date:
% Done:

0%

Estimated time:
Difficulty:

Description

Motivation

openQA test reviewers often rely on autoinst-log.txt for investigation on job failures. Not all messages in that log are well structured, e.g. plain "print-statements" as well as crucial information hidden in "debug" messages as well as less relevant information in a too prominent log level. Readability can be improved.

Acceptance criteria

  • AC1: No plain print-statements in a common autoinst-log.txt
  • AC2: The main recurring log messages of a common log file have been reviewed

Suggestions

autoinst-log.txt (597 KB) autoinst-log.txt ilausuch, 2021-05-14 08:56

Related issues

Related to qe-yast - action #89485: Implement feature to use separate log file for REST APIClosed2021-03-04

Related to openQA Project - action #92902: Remove unnecessary linebreaks in cache service loggingWorkable2021-05-20

History

#1 Updated by ilausuch 7 months ago

  • Status changed from Workable to In Progress
  • Assignee set to ilausuch

#2 Updated by ilausuch 7 months ago

Should this case be considered?

The code line https://github.com/os-autoinst/openQA/blob/3cb36e69423ebe3abf9c7f1c23c2906d2f615b91/lib/OpenQA/Worker/Engines/isotovideo.pm#L143
generates this output

[2021-05-03T05:24:40.0419 CEST] [info] Download of openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210502-Media.iso.sha256 processed:
[info] [#70]
Cache size of "/var/lib/openqa/cache" is 21GiB, with limit 180GiB
[info] [#70]
Downloading "openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210502-Media.iso.sha256" from "http://openqa1-opensuse/tests/1724624/asset/other/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210502-Media.iso.sha256"
[info] [#70]
Size of "/var/lib/openqa/cache/openqa1-opensuse/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210502-Media.iso.sha256" is 124 Byte, with ETag ""7c-5c1646608dad8""
[info] [#70]

What is expected in this case? All the output in the same line?

#3 Updated by openqa_review 7 months ago

  • Due date set to 2021-05-18

Setting due date based on mean cycle time of SUSE QE Tools

#4 Updated by cdywan 7 months ago

ilausuch wrote:

Should this case be considered?

The code line https://github.com/os-autoinst/openQA/blob/3cb36e69423ebe3abf9c7f1c23c2906d2f615b91/lib/OpenQA/Worker/Engines/isotovideo.pm#L143
generates this output

[2021-05-03T05:24:40.0419 CEST] [info] Download of openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210502-Media.iso.sha256 processed:
[info] [#70]
Cache size of "/var/lib/openqa/cache" is 21GiB, with limit 180GiB
[info] [#70]
Downloading "openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210502-Media.iso.sha256" from "http://openqa1-opensuse/tests/1724624/asset/other/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210502-Media.iso.sha256"
[info] [#70]
Size of "/var/lib/openqa/cache/openqa1-opensuse/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210502-Media.iso.sha256" is 124 Byte, with ETag ""7c-5c1646608dad8""
[info] [#70]

What is expected in this case? All the output in the same line?

  • What is [info] [#70] here?
  • The line break after the prefix strikes me as wrong. It inflates the log size and hampers filtering e.g. you can't really grep this by prefix

#5 Updated by okurz 7 months ago

cdywan wrote:

  • What is [info] [#70] here?

That's the output of the cache service minion processes which we collect here. I think we should either have a timestamp prefixed on front or – as discussed yesterday with ilausuch – use something like a markdown quotation style to separate the block body from the first log line that encapsulates it. For a start I suggest to simply prepend each line of the body by 2 spaces

  • The line break after the prefix strikes me as wrong. It inflates the log size and hampers filtering e.g. you can't really grep this by prefix

I agree. I don't remember seeing that from the beginning when implemented such log lines. Looks like a regression.

As discussed yesterday with ilausuch I suggest that within this ticket we look for simple solutions where we can and identify hard parts that can not be easily solved and report them into separate tickets for followup.

#6 Updated by okurz 7 months ago

  • Related to action #89485: Implement feature to use separate log file for REST API added

#7 Updated by ilausuch 7 months ago

In logs we can se
Start CPU
This is a print in the os-autoinst/backend/qemu.pm

https://github.com/os-autoinst/os-autoinst/pull/1668

#8 Updated by ilausuch 7 months ago

Previously the new lines appear without indentation. But for a
better reading and parsing the new lines that belongs to a
log entry are indented as markdown style

[2021-05-12T16:34:22.474 CEST] [debug] <<< testapi::assert_screen(mustmatch=[
  "partitioning-edit-proposal-button",
  "before-role-selection",
  "inst-instmode",
  "online-repos"
], timeout=120)

This is the new format:

[2021-05-12T16:34:22.474 CEST] [debug] <<<testapi::assert_screen(mustmatch=[
    "partitioning-edit-proposal-button",
    "before-role-selection",
    "inst-instmode",
    "online-repos"
  ], timeout=120)

https://github.com/os-autoinst/os-autoinst/pull/1669

#9 Updated by ilausuch 7 months ago

Other logs detected

WARNING: cv::norm() returned NaN (poo#68474)
[0mGOT GO
/hdd/openqa-devel/repos/os-autoinst/consoles/vnc_base.pm:62:{
  "hostname" => "localhost",
  "port" => 5991,
  "connect_timeout" => 3
}
[2021-05-13T13:12:01.111 CEST] [debug] tests/installation/system_role.pm:83 called system_role::assert_system_role -> tests/installation/system_role.pm:65 called system_role::change_system_role -> tests/installation/system_role.pm:45 called testapi::send_key_until_needlematch
Web application available at http://0.0.0.0:20013
[2021-05-17T13:49:33.0579 CEST] [info] Download of Tumbleweed.x86_64-1.0-virtualbox-Snapshot20210516.vagrant.virtualbox.box processed:
[info] [#358]
Cache size of "/var/lib/openqa/cache" is 57GiB, with limit 180GiB
[info] [#358]
Downloading "Tumbleweed.x86_64-1.0-virtualbox-Snapshot20210516.vagrant.virtualbox.box" from "http://openqa1-opensuse/tests/1745884/asset/other/Tumbleweed.x86_64-1.0-virtualbox-Snapshot20210516.vagrant.virtualbox.box"
[info] [#358]
Content of "/var/lib/openqa/cache/openqa1-opensuse/Tumbleweed.x86_64-1.0-virtualbox-Snapshot20210516.vagrant.virtualbox.box" has not changed, updating last use

#10 Updated by ilausuch 7 months ago

I would like to share the output log of a job run using:
https://github.com/os-autoinst/os-autoinst/pull/1670

#11 Updated by okurz 7 months ago

looks good. There are things which look like not affected by the indention, e.g.

/hdd/openqa-devel/repos/os-autoinst/consoles/vnc_base.pm:62:{
  "port" => 5991,
  "connect_timeout" => 3,
  "hostname" => "localhost"
}

which I think I can fix myself in https://github.com/os-autoinst/os-autoinst/pull/1673 :)

#12 Updated by ilausuch 7 months ago

  • Status changed from In Progress to Resolved

As https://github.com/os-autoinst/os-autoinst/pull/1670 is merged, this ticket is finished. Remain detected cases will be inserted in https://progress.opensuse.org/issues/65271

#13 Updated by tinita 7 months ago

I was wondering about this:

[info] [#70]
Cache size of "/var/lib/openqa/cache" is 21GiB, with limit 180GiB

I think the linebreak after [info] [#70] comes from a wrong handling of log messages, for example in:

https://github.com/os-autoinst/openQA/blob/master/lib/OpenQA/CacheService/Task/Asset.pm#L50-L54

    $log->on(
        message => sub {
            my ($log, $level, @lines) = @_;
            $output .= "[$level] " . join "\n", @lines, '';
        });

The callback gets [#70] and the actual log message in two lines, so I think the join "\n" should be replaced with join " " here.

It's not really clear from https://metacpan.org/pod/Mojo::Log how multiple arguments to one of the log methods are supposed to behave. But $log->context adds the [#70] as an array item, and I don't think this is supposed to create a new line.

#14 Updated by tinita 7 months ago

  • Related to action #92902: Remove unnecessary linebreaks in cache service logging added

#15 Updated by okurz 6 months ago

  • Due date deleted (2021-05-18)

Also available in: Atom PDF