Multiple loggings channels

Sometimes it's required that we are able to log text to multiple
files. Currently the default OpenQA::Setup::app only logs to the
destination specified in the config files.

With these changes if the developer wants or needs to log to
another file/destination, just needs to call the normal logging
functions with an extra parameter, which is the name of the
"channel". Example:

> log_debug($message, 'this is name of channel');

This will work as long as the "channel" already exists. Otherwise,
it will use the default logging mechanism.

To create a new "channel" just invoke add_log_channel with the
**id** as first parameter. The rest of the parameters are the
same as the ones required for Mojo::Log. Example:

> add_log_channel('channel name', path=>'test.log', level=>'debug')
> unless get_channel_handle('autoinst');

This will create a Mojo::Log object that will be associated with
the name 'channel name'

Author: dasantiago

Diff for: cpanfile

@@ -90,7 +90,6 @@ requires 'diagnostics';
 requires 'namespace::clean';
 requires 'strict';
 requires 'warnings';
-requires 'File::Path';
 
 on 'test' => sub {
   requires 'Perl::Tidy';

Diff for: lib/OpenQA/Setup.pm

@@ -30,7 +30,7 @@ use File::Path 'make_path';
 
 has config => sub { {} };
 
-has log => sub { Mojo::Log->new(handle => \*STDOUT, level => "debug"); };
+has log => sub { Mojo::Log->new(handle => \*STDOUT, level => "info"); };
 
 has home => sub { Mojo::Home->new($ENV{MOJO_HOME} || '/') };
 

Diff for: lib/OpenQA/Utils.pm

@@ -25,6 +25,7 @@ use Mojo::File 'path';
 use IO::Handle;
 use Scalar::Util 'blessed';
 use Data::Dump 'pp';
+use Mojo::Log;
 
 require Exporter;
 our ($VERSION, @ISA, @EXPORT, @EXPORT_OK, %EXPORT_TAGS);
@@ -46,6 +47,9 @@ $VERSION = sprintf "%d.%03d", q$Revision: 1.12 $ =~ /(\d+)/g;
   &log_info
   &log_error
   &log_fatal
+  add_log_channel
+  remove_log_channel
+  get_channel_handle
   &save_base64_png
   &run_cmd_with_log
   &run_cmd_with_log_return_error
@@ -111,6 +115,8 @@ our $imagesdir = "$prjdir/images";
 our $hostname  = $ENV{SERVER_NAME};
 our $app;
 
+my %channels = ();
+
 # the desired new folder structure is
 # $testcasedir/<testrepository>
 # with "main.pm" and needles being in a productdir under <testrepository>
@@ -219,8 +225,12 @@ sub needle_info {
 
 # logging helpers
 sub log_debug {
-    my ($msg) = @_;
-    if ($app && $app->log) {
+    my ($msg, $channel) = @_;
+
+    if ($channel && $channels{$channel}) {
+        $channels{$channel}->debug($msg);
+    }
+    elsif ($app && $app->log) {
         $app->log->debug($msg);
     }
     else {
@@ -229,8 +239,11 @@ sub log_debug {
 }
 
 sub log_info {
-    my ($msg) = @_;
-    if ($app && $app->log) {
+    my ($msg, $channel) = @_;
+    if ($channel && $channels{$channel}) {
+        $channels{$channel}->info($msg);
+    }
+    elsif ($app && $app->log) {
         $app->log->info($msg);
     }
     else {
@@ -239,8 +252,11 @@ sub log_info {
 }
 
 sub log_warning {
-    my ($msg) = @_;
-    if ($app && $app->log) {
+    my ($msg, $channel) = @_;
+    if ($channel && $channels{$channel}) {
+        $channels{$channel}->warn($msg);
+    }
+    elsif ($app && $app->log) {
         $app->log->warn($msg);
     }
     else {
@@ -249,8 +265,11 @@ sub log_warning {
 }
 
 sub log_error {
-    my ($msg) = @_;
-    if ($app && $app->log) {
+    my ($msg, $channel) = @_;
+    if ($channel && $channels{$channel}) {
+        $channels{$channel}->error($msg);
+    }
+    elsif ($app && $app->log) {
         $app->log->error($msg);
     }
     else {
@@ -259,8 +278,11 @@ sub log_error {
 }
 
 sub log_fatal {
-    my ($msg) = @_;
-    if ($app && $app->log) {
+    my ($msg, $channel) = @_;
+    if ($channel && $channels{$channel}) {
+        $channels{$channel}->fatal($msg);
+    }
+    elsif ($app && $app->log) {
         $app->log->fatal($msg);
     }
     else {
@@ -269,6 +291,26 @@ sub log_fatal {
     die $msg;
 }
 
+sub add_log_channel {
+    my ($channel, @options) = @_;
+    $channels{$channel} = Mojo::Log->new(@options);
+}
+
+sub remove_log_channel {
+    my ($channel) = @_;
+    delete $channels{$channel} if $channel;
+}
+
+sub get_channel_handle {
+    my ($channel) = @_;
+    if ($channel) {
+        return $channels{$channel}->handle if $channels{$channel};
+    }
+    elsif ($app) {
+        return $app->log->handle;
+    }
+}
+
 sub save_base64_png($$$) {
     my ($dir, $newfile, $png) = @_;
     return unless $newfile;

Diff for: lib/OpenQA/Worker/Cache.pm

@@ -20,7 +20,7 @@ use warnings;
 use File::Basename;
 use Fcntl ':flock';
 use Mojo::UserAgent;
-use OpenQA::Utils qw(log_error log_info log_debug);
+use OpenQA::Utils qw(log_error log_info log_debug get_channel_handle add_log_channel);
 use OpenQA::Worker::Common;
 use List::MoreUtils;
 use File::Spec::Functions 'catdir';
@@ -82,12 +82,11 @@ sub init {
 sub download_asset {
     my ($id, $type, $asset, $etag) = @_;
 
-    open(my $log, '>>', "autoinst-log.txt") or die("Cannot open autoinst-log.txt");
-    local $| = 1;
+    add_log_channel('autoinst', path => 'autoinst-log.txt', level => 'debug') unless get_channel_handle('autoinst');
     my $ua = Mojo::UserAgent->new(max_redirects => 2);
     $ua->max_response_size(0);
     my $url = sprintf '%s/tests/%d/asset/%s/%s', $host, $id, $type, basename($asset);
-    print $log "Downloading " . basename($asset) . " from $url\n";
+    log_debug("Downloading " . basename($asset) . " from $url", 'autoinst');
     my $tx = $ua->build_tx(GET => $url);
     my $headers;
 
@@ -115,7 +114,7 @@ sub download_asset {
                         $last_updated = time;
                         if ($progress < $current) {
                             $progress = $current;
-                            print $log "CACHE: Downloading $asset: ", $size == $len ? 100 : $progress . "%\n";
+                            log_debug("CACHE: Downloading $asset: ", $size == $len ? 100 : $progress . "%", 'autoinst');
                         }
                     }
                 });
@@ -126,20 +125,20 @@ sub download_asset {
     my $size;
     if ($code eq 304) {
         if (toggle_asset_lock($asset, 0)) {
-            print $log "CACHE: Content has not changed, not downloading the $asset but updating last use\n";
+            log_debug("CACHE: Content has not changed, not downloading the $asset but updating last use", 'autoinst');
         }
         else {
-            print $log "CACHE: Abnormal situation, code 304. Retrying download\n";    # poo#19270 might give a hint
+            log_debug("CACHE: Abnormal situation, code 304. Retrying download", 'autoinst');
             $asset = 520;
         }
     }
     elsif ($tx->res->is_server_error) {
         if (toggle_asset_lock($asset, 0)) {
-            print $log "CACHE: Could not download the asset, triggering a retry for $code.\n";
+            log_debug("CACHE: Could not download the asset, triggering a retry for $code.", 'autoinst');
             $asset = $code;
         }
         else {
-            print $log "CACHE: Abnormal situation, server error. Retrying download\n";
+            log_debug("CACHE: Abnormal situation, server error. Retrying download", 'autoinst');
             $asset = $code;
         }
     }
@@ -150,19 +149,18 @@ sub download_asset {
         if ($size == $headers->content_length) {
             check_limits($size);
             update_asset($asset, $etag, $size);
-            print $log "CACHE: Asset download successful to $asset, Cache size is: $cache_real_size\n";
+            log_debug("CACHE: Asset download successful to $asset, Cache size is: $cache_real_size", 'autoinst');
         }
         else {
-            print $log "CACHE: Size of $asset differs, Expected: "
-              . $headers->content_length
-              . " / Downloaded: "
-              . "$size  \n";
+            log_debug(
+                "CACHE: Size of $asset differs, Expected: " . $headers->content_length . " / Downloaded: " . "$size",
+                'autoinst');
             $asset = 598;    # 598 (Informal convention) Network read timeout error
         }
     }
     else {
         my $message = $tx->res->error->{message};
-        print $log "CACHE: Download of $asset failed with: $code - $message\n";
+        log_debug("CACHE: Download of $asset failed with: $code - $message", 'autoinst');
         purge_asset($asset);
         $asset = undef;
     }

Diff for: lib/OpenQA/Worker/Commands.pm

@@ -17,7 +17,7 @@ package OpenQA::Worker::Commands;
 use 5.018;
 use warnings;
 
-use OpenQA::Utils qw(log_error log_warning log_debug);
+use OpenQA::Utils qw(log_error log_warning log_debug add_log_channel remove_log_channel);
 use OpenQA::Worker::Common;
 use OpenQA::Worker::Jobs;
 use POSIX ':sys_wait_h';
@@ -158,6 +158,8 @@ sub websocket_commands {
 
             if ($job && $job->{id}) {
                 $OpenQA::Worker::Common::job = $job;
+                remove_log_channel('autoinst');
+                add_log_channel('autoinst', path => 'autoinst-log.txt', level => 'debug');
                 log_debug("Job " . $job->{id} . " scheduled for next cycle");
                 Mojo::IOLoop->singleton->once(
                     "start_job" => sub {

Diff for: lib/OpenQA/Worker/Engines/isotovideo.pm

@@ -18,7 +18,7 @@ use strict;
 use warnings;
 
 use OpenQA::Worker::Common;
-use OpenQA::Utils qw(locate_asset log_error log_info log_debug);
+use OpenQA::Utils qw(locate_asset log_error log_info log_debug get_channel_handle);
 
 use POSIX qw(:sys_wait_h strftime uname _exit);
 use JSON 'to_json';
@@ -29,6 +29,7 @@ use Errno;
 use Cwd qw(abs_path getcwd);
 use OpenQA::Worker::Cache;
 use Time::HiRes 'sleep';
+use IO::Handle;
 
 my $isotovideo = "/usr/bin/isotovideo";
 my $workerpid;
@@ -119,13 +120,10 @@ sub detect_asset_keys {
 sub engine_workit {
     my ($job) = @_;
 
-    if (open(my $log, '>', "autoinst-log.txt")) {
-        print $log "+++ setup notes +++\n";
-        printf $log "start time: %s\n", strftime("%F %T", gmtime);
-        my ($sysname, $hostname, $release, $version, $machine) = POSIX::uname();
-        printf $log "running on $hostname:%d ($sysname $release $version $machine)\n", $instance;
-        close($log);
-    }
+    my ($sysname, $hostname, $release, $version, $machine) = POSIX::uname();
+    log_debug('+++ setup notes +++', 'autoinst');
+    log_debug(sprintf("start time: %s", strftime("%F %T", gmtime)), 'autoinst');
+    log_debug(sprintf("running on $hostname:%d ($sysname $release $version $machine)", $instance), 'autoinst');
 
     # set base dir to the one assigned with webui
     OpenQA::Utils::change_sharedir($hosts->{$current_host}{dir});
@@ -213,15 +211,14 @@ sub engine_workit {
         setpgrp(0, 0);
         $ENV{TMPDIR} = $tmpdir;
         log_info("$$: WORKING " . $job->{id});
-        if (open(my $log, '>>', "autoinst-log.txt")) {
-            print $log "+++ worker notes +++\n";
-            printf $log "start time: %s\n", strftime("%F %T", gmtime);
-            my ($sysname, $hostname, $release, $version, $machine) = POSIX::uname();
-            printf $log "running on $hostname:%d ($sysname $release $version $machine)\n", $instance;
-            close($log);
-        }
-        open STDOUT, ">>", "autoinst-log.txt";
-        open STDERR, ">&STDOUT";
+        log_debug('+++ worker notes +++', 'autoinst');
+        log_debug(sprintf("start time: %s", strftime("%F %T", gmtime)), 'autoinst');
+
+        my ($sysname, $hostname, $release, $version, $machine) = POSIX::uname();
+        log_debug(sprintf("running on $hostname:%d ($sysname $release $version $machine)", $instance), 'autoinst');
+        my $handle = get_channel_handle('autoinst');
+        STDOUT->fdopen($handle, 'w');
+        STDERR->fdopen($handle, 'w');
         exec "perl", "$isotovideo", '-d';
         die "exec failed: $!\n";
     }

Diff for: lib/OpenQA/Worker/Jobs.pm

@@ -126,7 +126,6 @@ sub check_job {
 
 sub stop_job {
     my ($aborted, $job_id) = @_;
-
     # we call this function in all situations, so better check
     if (!$job || $stop_job_running) {
         # In case there is no job, or if the job was asked to stop
@@ -188,9 +187,7 @@ sub upload {
 
     # we need to open and close the log here as one of the files
     # might actually be autoinst-log.txt
-    open(my $log, '>>', "autoinst-log.txt");
-    printf $log "uploading %s\n", $filename;
-    close $log;
+    log_debug("uploading $filename", 'autoinst');
     log_debug("uploading $filename");
 
     my $regular_upload_failed = 0;
@@ -228,10 +225,8 @@ sub upload {
 
             # Just return if all upload retries have failed
             # this will cause the next group of uploads to be triggered
-            my $msg = "All $retry_limit upload attempts have failed for $filename\n";
-            open(my $log, '>>', "autoinst-log.txt");
-            print $log $msg;
-            close $log;
+            my $msg = "All $retry_limit upload attempts have failed for $filename";
+            log_debug($msg, 'autoinst');
             log_error($msg);
             return 0;
         }
@@ -246,9 +241,7 @@ sub upload {
         else {
             $msg = sprintf "ERROR %s: Connection error: $err->{message}\n", $filename;
         }
-        open(my $log, '>>', "autoinst-log.txt");
-        print $log $msg;
-        close $log;
+        log_debug($msg, 'autoinst');
         log_error($msg);
         return 0;
     }
@@ -267,15 +260,15 @@ sub upload {
             ($csum2, $size2) = split(/ /, <$cfd>);
             close($cfd);
         }
-        open(my $log, '>>', "autoinst-log.txt");
-        print $log "Checksum comparison (actual:expected) $csum1:$csum2 with size (actual:expected) $size1:$size2\n";
+        log_debug("Checksum comparison (actual:expected) $csum1:$csum2 with size (actual:expected) $size1:$size2",
+            'autoinst');
         if ($csum1 eq $csum2 && $size1 eq $size2) {
             my $ua_url = $hosts->{$current_host}{url}->clone;
             $ua_url->path("jobs/$job_id/ack_temporary");
             $hosts->{$current_host}{ua}->post($ua_url => form => {temporary => $res->res->json->{temporary}});
         }
         else {
-            print $log "Checksum/size comparison of $filename FAILED\n";
+            log_debug("Checksum/size comparison of $filename FAILED", 'autoinst');
             return 0;
         }
     }
@@ -318,13 +311,9 @@ sub _stop_job_2 {
     $aborted ||= 'done';
 
     my $job_done;    # undef
-
-    open(my $log, '>>', "autoinst-log.txt");
-    print $log "+++ worker notes +++\n";
-    printf $log "end time: %s\n", strftime("%F %T", gmtime);
-    print $log "result: $aborted\n";
-    close $log;
-
+    log_debug("+++ worker notes +++", 'autoinst');
+    log_debug(sprintf("end time: %s", strftime("%F %T", gmtime)), 'autoinst');
+    log_debug("result: $aborted", 'autoinst');
     if ($aborted ne 'quit' && $aborted ne 'abort' && $aborted ne 'api-failure') {
         # collect uploaded logs
         my @uploaded_logfiles = glob "$pooldir/ulogs/*";
@@ -367,7 +356,6 @@ sub _stop_job_2 {
                 }
             }
         }
-
         for my $file (qw(video.ogv vars.json serial0 autoinst-log.txt virtio_console.log)) {
             next unless -e $file;
             # default serial output file called serial0

Diff for: t/24-worker.t

@@ -63,6 +63,7 @@ ok($hosts->{this_host_should_not_exist}{url}, 'url object created');
 is($hosts->{this_host_should_not_exist}{workerid}, undef, 'worker not registered yet');
 
 # api_call
+print "BEFORE:\n";
 eval { OpenQA::Worker::Common::api_call() };
 ok($@, 'no action or no worker id set');