action #52235

isotovideo -d broken

Added by apachelogger 6 months ago. Updated 6 months ago.

Status:ResolvedStart date:28/05/2019
Priority:UrgentDue date:
Assignee:dheidler% Done:

0%

Category:Concrete Bugs
Target version:Current Sprint
Difficulty:
Duration:

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

Related to openQA Project - action #52247: autoinst-log.txt opened with wrong path Resolved 28/05/2019
Related to openQA Project - action #45011: [tools] Allow detection of known failures at the autoinst... Workable 11/12/2018

History

#1 Updated by coolo 6 months ago

  • Category set to Concrete Bugs
  • 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

#2 Updated by dheidler 6 months ago

  • Status changed from New to In Progress

#3 Updated by dheidler 6 months ago

  • Status changed from In Progress to Feedback

#4 Updated by szarate 6 months ago

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

#5 Updated by okurz 6 months 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.

#6 Updated by dheidler 6 months 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.

#7 Updated by dheidler 6 months 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',

#8 Updated by dheidler 6 months 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.

#9 Updated by okurz 6 months ago

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

#10 Updated by okurz 6 months 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

Also available in: Atom PDF