Project

General

Profile

Actions

action #91527

closed

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 over 3 years ago. Updated over 3 years ago.

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

0%

Estimated time:

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


Files

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

Related issues 2 (0 open2 closed)

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

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

Actions
Actions #1

Updated by ilausuch over 3 years ago

  • Status changed from Workable to In Progress
  • Assignee set to ilausuch
Actions #2

Updated by ilausuch over 3 years 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?

Actions #3

Updated by openqa_review over 3 years ago

  • Due date set to 2021-05-18

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

Actions #4

Updated by livdywan over 3 years 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
Actions #5

Updated by okurz over 3 years 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.

Actions #6

Updated by okurz over 3 years ago

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

Updated by ilausuch over 3 years 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

Actions #8

Updated by ilausuch over 3 years 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

Actions #9

Updated by ilausuch over 3 years 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
Actions #10

Updated by ilausuch over 3 years ago

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

Actions #11

Updated by okurz over 3 years 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 :)

Actions #12

Updated by ilausuch over 3 years 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

Actions #13

Updated by tinita over 3 years 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.

Actions #14

Updated by tinita over 3 years ago

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

Updated by okurz over 3 years ago

  • Due date deleted (2021-05-18)
Actions

Also available in: Atom PDF