controller: better logging feature for dtf-controller

Use logging wrapper functions and log into dedicated file per
sub-task (apart from STDERR/STDOUT as usual).

* controller/bin/dtf-controller (log_info, log_error, log_die)
(log_any): New logging functions.
($log_procid, $log_logfile, @log_buffer): New logging related
variables.
(load_runfile): Remove old comment.
(subcommand): Use log_info instead of print.
(child_task): Open child's logging file.  Better parse check $run
content.
(main): Use log_info instead of print.

1 files changed, 73 insertions, 10 deletions

diff --git a/controller/bin/dtf-controller.in b/controller/bin/dtf-controller.in
index a231270..b670d87 100644
--- a/controller/bin/dtf-controller.in
+++ b/controller/bin/dtf-controller.in
@@ -19,6 +19,57 @@ our @children;
 
 our $opt_runfile = "runfile.yml";
 
+my $log_procid = "dtf-controller";
+my $log_logfile;
+my @log_buffer;
+
+sub log_any
+{
+    my $msg = shift;
+    my $where = shift;
+
+    $msg = "$log_procid: $msg\n";
+
+    if (defined $where and $where eq "stderr") {
+        print STDERR $msg;
+    }
+    else {
+        print STDOUT $msg;
+    }
+
+    # Buffer the output if the log file is not available yet.
+    if (!$log_logfile) {
+        push @log_buffer, $msg;
+    }
+    else {
+        for (@log_buffer) {
+            print { $log_logfile } $_;
+        }
+        @log_buffer = ();
+
+        print { $log_logfile } $msg;
+    }
+}
+
+sub log_info
+{
+    my $msg = "info: " . shift;
+    log_any $msg;
+}
+
+sub log_error
+{
+    my $msg = "error: " . shift;
+    log_any $msg, "stderr";
+}
+
+sub log_die
+{
+    my $msg = "fatal: " . shift;
+    log_any $msg, "stderr";
+    exit (1);
+}
+
 sub load_runfile
 {
     open my $fd, '<', $opt_runfile
@@ -26,13 +77,13 @@ sub load_runfile
     my $config = YAML::Syck::LoadFile($fd)
             or die "can't parse '$opt_runfile'";
 
-    # print Dumper $config;
     return $config;
 }
 
 sub subcommand
 {
     my $cmd = $_[0];
+
     my $out_file = "/dev/null";
     my $err_file = "/dev/null";
 
@@ -43,7 +94,7 @@ sub subcommand
         $err_file = $_[2];
     }
 
-    print STDERR "running: " . join(' ', @$cmd) . "\n";
+    log_info "running: " . join(' ', @$cmd);
 
     my $pid = fork();
     if ($pid eq 0) {
@@ -63,8 +114,23 @@ sub child_task
     my $dir = $_[1];
     my $config = $_[2];
 
+    open ($log_logfile, '>', "$dir/controller.log");
+    log_info "results into $dir";
+
+    my $runfile_err = 0;
+    for (("setup_playbook", "distro_version", "distro", "taskdir")) {
+        my $param = $_;
+        if (!defined $run->{$_}) {
+            log_error "missing parameter '$param' in runfile";
+            $runfile_err ++;
+        }
+    }
+    log_die "failed, nr. of errors: $runfile_err" if ($runfile_err);
+
     my $task = "$run->{distro}-$run->{distro_version}";
 
+    $log_procid = "$log_procid($task)";
+
     my $rc = subcommand [
         '@bindir@/dtf-run-remote',
         '--taskdir',            $run->{taskdir},
@@ -78,7 +144,7 @@ sub child_task
     # Note that the 'dtf-run-remote' must return EXIT_SUCCESS even if some of
     # its tests failed.
     if ($rc ne 0) {
-        print STDERR "$task: failed dtf-run-remote\n";
+        log_error "failed dtf-run-remote";
     }
 
     my $db = $config->{db};
@@ -94,7 +160,7 @@ sub child_task
         "$db"
     ];
     if ($rc ne 0) {
-        print STDERR "$task: failed dtf-commit-results";
+        log_error "failed dtf-commit-results";
         exit (1);
     }
 
@@ -109,7 +175,7 @@ sub main
 {
     my $config = load_runfile;
 
-    print $config->{description}. "\n";
+    log_info "test-description: $config->{description}";
 
     $config->{starttime} = strftime "%Y%m%d_%H%M%S", gmtime;
 
@@ -117,13 +183,10 @@ sub main
         # dies on error - which is OK
         my $dir = File::Temp->newdir("/tmp/dtf-controller-XXXXXX", CLEANUP => 0);
 
-        print "results into $dir\n";
-
         ($run->{stamp} = $dir) =~ s/.*-//;
 
         my $pid = fork();
         if ($pid == 0) {
-
             child_task($run, $dir, $config);
             ## child's successful run ##
             exit (0);
@@ -134,7 +197,7 @@ sub main
     }
 
     $SIG{INT} = sub {
-        print ".. waiting for children SIGINTing\n";
+        log_info ".. waiting for children SIGINTing\n";
     };
 
     # wait for all pseudo sub-processes
@@ -144,7 +207,7 @@ sub main
         $child = waitpid (-1, 0);
     } while ($child > 0);
 
-    print "Finished..\n";
+    log_info "Finished..";
 }
 
 GetOptions(