openQA Project (public)

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?

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

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.

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

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

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

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 :)

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.