Project

General

Profile

Actions

action #52235

closed

isotovideo -d broken

Added by apachelogger over 5 years ago. Updated over 5 years ago.

Status:
Resolved
Priority:
Urgent
Assignee:
Category:
Regressions/Crashes
Target version:
Start date:
2019-05-28
Due date:
% Done:

0%

Estimated time:

Description

This supposedly is a regression introduced in fe70160d7134dfa499cae7d47fafd95e5321dcf8

When running with -d to print debug output to stdout the autoinst-log.txt is never written as per

    if ($direct_output) {
        $logger = Mojo::Log->new(level => 'debug');
    }
    else {
        $logger = Mojo::Log->new(level => 'debug', path => catfile(result_dir, 'autoinst-log.txt'));
    }

which bastest.pm will eventually trip over in

    # Detect autoinst failures and override result if die
    try {
        $self->search_for_expected_autoinst_failures();
    }
    catch {
        # Process autoinst dectection failure
        bmwqemu::diag($_);
        $self->record_resultfile('Failed', $_, result => 'fail');
        $died = 1;
    };

output:

[2019-05-28T12:52:46.236 UTC] [debug] Can't open 'autoinst-log.txt' for reading: 'No such file or directory' at /workspace/os-autoinst/basetest.pm line 742
[2019-05-28T12:52:46.237 UTC] [debug] try() encountered an unexpected argument (1) - perhaps a missing semi-colon before or at /workspace/os-autoinst/basetest.pm line 391.
[2019-05-28T12:52:46.237 UTC] [debug] killing autotest process 34

Related issues 2 (1 open1 closed)

Related to openQA Project - action #52247: autoinst-log.txt opened with wrong pathResolveddheidler2019-05-28

Actions
Related to openQA Project - action #45011: Allow detection of known failures at the autoinst-log.txtWorkable2018-12-11

Actions
Actions #1

Updated by coolo over 5 years ago

  • Category set to Regressions/Crashes
  • Assignee set to dheidler
  • Priority changed from Normal to Urgent
  • Target version set to Current Sprint

Then the log file needs to be written unconditionally - in addition to stderr

Actions #2

Updated by dheidler over 5 years ago

  • Status changed from New to In Progress
Actions #3

Updated by dheidler over 5 years ago

  • Status changed from In Progress to Feedback
Actions #4

Updated by szarate over 5 years ago

  • Related to action #52247: autoinst-log.txt opened with wrong path added
Actions #5

Updated by okurz over 5 years ago

so now we have every line doubled in https://openqa.opensuse.org/tests/948392/file/autoinst-log.txt . I don't think this is what you wanted.

Actions #6

Updated by dheidler over 5 years ago

It seems to behave differently depending on how it was started.
I didn't get the double log lines, when I called isotovideo from the commandline.
But it does when isotovideo is called by the openQA-worker.

Actions #7

Updated by dheidler over 5 years ago

I can reproduce the double log entries, when I run my test via openQA webui.
But I don't understand how isotovideo can inherit a log handle from openQA code, as openQA runs isotovideo as a subprocess as a command.
But still this is what seems to happen - when I comment out this lines in the openQA code, the problem with the double log lines goes away:

diff --git a/lib/OpenQA/Worker/Cache.pm b/lib/OpenQA/Worker/Cache.pm
index 5813f791..0a29e625 100644
--- a/lib/OpenQA/Worker/Cache.pm
+++ b/lib/OpenQA/Worker/Cache.pm
@@ -100,7 +100,7 @@ sub download_asset {
         append_channel_to_defaults('autoinst');
     }
     else {
-        add_log_channel('autoinst', path => 'autoinst-log.txt', level => 'debug', default => 'append');
+        #add_log_channel('autoinst', path => 'autoinst-log.txt', level => 'debug', default => 'append');
     }

     my $ua = Mojo::UserAgent->new(max_redirects => 2);
diff --git a/lib/OpenQA/Worker/Commands.pm b/lib/OpenQA/Worker/Commands.pm
index cf007c2a..23727aef 100644
--- a/lib/OpenQA/Worker/Commands.pm
+++ b/lib/OpenQA/Worker/Commands.pm
@@ -145,7 +145,7 @@ sub websocket_commands {
             $OpenQA::Worker::Common::job = $job;
             remove_log_channel('autoinst');
             remove_log_channel('worker');
-            add_log_channel('autoinst', path => 'autoinst-log.txt', level => 'debug');
+            #add_log_channel('autoinst', path => 'autoinst-log.txt', level => 'debug');
             add_log_channel(
                 'worker',
                 path    => 'worker-log.txt',
Actions #8

Updated by dheidler over 5 years ago

This should prevent openQA from getting the logs from isotovideo twice:
https://github.com/os-autoinst/openQA/pull/2092

Now isotovideo will log its own stuff and openQA will put everywhing that isotovideo spits out on stderr into the autoinst log additionally.
So the problem with the double lines should be solved without loosing previously existing log entries.

Actions #9

Updated by okurz over 5 years ago

  • Related to action #45011: Allow detection of known failures at the autoinst-log.txt added
Actions #10

Updated by okurz over 5 years ago

  • Status changed from Feedback to Resolved

We did not use the above PR but I created https://github.com/os-autoinst/os-autoinst/pull/1161 which was approved and merged partially reverting the changes done to get back into working state, that is proper output, no duplication, etc. Now we can try again to bring in the originally intended changes in #45011

Actions

Also available in: Atom PDF