runtests: support buffering log messages in runner & servers

Log messages generated with logmsg can now be buffered and returned from
the runner as a return value.  This will be needed with parallel testing
to allow all messages for one test to be displayed together instead of
interspersed with messages of multiple tests. Buffering can be disabled
by setting a logging callback function with setlogfunc, which is
currently being done to preserve existing logging behaviour for now.

Some additional output is generated in verbose and debugprotocol modes,
which don't always use logmsg. These modes also impact some servers
which generate extra messages. No attempt is made to buffer everything
if these modes are enabled.

Ref: #10818
Closes #11016

tests/devtest.pl

@@ -59,6 +59,9 @@ use runner qw(
     readtestkeywords
     singletest_preprocess
 );
+use testutil qw(
+    setlogfunc
+);
 use getpart;
 
 
@@ -119,6 +122,7 @@ sub init_protocols {
 # Initialize the test harness to run tests
 #
 sub init_tests {
+    setlogfunc(\&logmsg);
     init_protocols();
     initserverconfig();
 }

tests/runner.pm

@@ -40,6 +40,7 @@ BEGIN {
         runner_stopservers
         runner_test_preprocess
         runner_test_run
+        setlogfunc
         $DBGCURL
         $gdb
         $gdbthis
@@ -73,7 +74,13 @@ use servers qw(
     );
 use getpart;
 use globalconfig;
-use testutil;
+use testutil qw(
+    clearlogs
+    logmsg
+    runclient
+    subbase64
+    subnewlines
+    );
 
 
 #######################################################################
@@ -98,13 +105,6 @@ my $defserverlogslocktimeout = 2; # timeout to await server logs lock removal
 my $defpostcommanddelay = 0; # delay between command and postcheck sections
 
 
-#######################################################################
-# Log an informational message
-# This just calls main's logmsg for now.
-sub logmsg {
-    return main::logmsg(@_);
-}
-
 #######################################################################
 # Check for a command in the PATH of the machine running curl.
 #
@@ -907,6 +907,10 @@ sub runner_test_preprocess {
     my ($testnum)=@_;
     my %testtimings;
 
+    if(clearlogs()) {
+        logmsg "Warning: log messages were lost\n";
+    }
+
     # timestamp test preparation start
     # TODO: this metric now shows only a portion of the prep time; better would
     # be to time singletest_preprocess below instead
@@ -943,29 +947,32 @@ sub runner_test_preprocess {
             $error = -1;
         }
     }
-    return ($why, $error, \%testtimings);
+    return ($why, $error, clearlogs(), \%testtimings);
 }
 
 
 ###################################################################
 # Run a single test case with an environment that already been prepared
 # Returns 0=success, -1=skippable failure, -2=permanent error,
-#   1=unskippable test failure, as first integer, plus more return
-#   values when error is 0
+#   1=unskippable test failure, as first integer, plus any log messages,
+#   plus more return values when error is 0
 sub runner_test_run {
     my ($testnum)=@_;
 
-    my %testtimings;
+    if(clearlogs()) {
+        logmsg "Warning: log messages were lost\n";
+    }
 
     #######################################################################
     # Prepare the test environment to run this test case
     my $error = singletest_prepare($testnum);
     if($error) {
-        return -2;
+        return (-2, clearlogs());
     }
 
     #######################################################################
     # Run the test command
+    my %testtimings;
     my $cmdres;
     my $dumped_core;
     my $CURLOUT;
@@ -973,29 +980,28 @@ sub runner_test_run {
     my $usedvalgrind;
     ($error, $cmdres, $dumped_core, $CURLOUT, $tool, $usedvalgrind) = singletest_run($testnum, \%testtimings);
     if($error) {
-        return (-2, \%testtimings);
+        return (-2, clearlogs(), \%testtimings);
     }
 
     #######################################################################
     # Clean up after test command
     $error = singletest_clean($testnum, $dumped_core, \%testtimings);
     if($error) {
-        return ($error, \%testtimings);
+        return ($error, clearlogs(), \%testtimings);
     }
 
     #######################################################################
     # Verify that the postcheck succeeded
     $error = singletest_postcheck($testnum);
     if($error) {
-        return ($error, \%testtimings);
+        return ($error, clearlogs(), \%testtimings);
     }
 
     #######################################################################
     # restore environment variables that were modified
     restore_test_env(0);
 
-
-    return (0, \%testtimings, $cmdres, $CURLOUT, $tool, $usedvalgrind);
+    return (0, clearlogs(), \%testtimings, $cmdres, $CURLOUT, $tool, $usedvalgrind);
 }
 
 
@@ -1003,14 +1009,21 @@ sub runner_test_run {
 # Kill the server processes that still have lock files in a directory
 sub runner_clearlocks {
     my ($lockdir)=@_;
+    if(clearlogs()) {
+        logmsg "Warning: log messages were lost\n";
+    }
     clearlocks($lockdir);
+    return clearlogs();
 }
 
 
 ###################################################################
 # Kill all server processes
 sub runner_stopservers {
-    return stopservers($verbose);
+    my $error = stopservers($verbose);
+    my $logs = clearlogs();
+    return ($error, $logs);
 }
 
+
 1;

tests/runtests.pl

@@ -195,7 +195,8 @@ $ENV{'COLUMNS'}=79; # screen width!
 sub catch_zap {
     my $signame = shift;
     logmsg "runtests.pl received SIG$signame, exiting\n";
-    runner_stopservers();
+    my ($unexpected, $logs) = runner_stopservers();
+    logmsg $logs;
     die "Somebody sent me a SIG$signame";
 }
 $SIG{INT} = \&catch_zap;
@@ -1412,7 +1413,8 @@ sub singletest_check {
             if(!$filename) {
                 logmsg "ERROR: section verify=>file$partsuffix ".
                        "has no name attribute\n";
-                runner_stopservers();
+                my ($unexpected, $logs) = runner_stopservers();
+                logmsg $logs;
                 # timestamp test result verification end
                 $timevrfyend{$testnum} = Time::HiRes::time();
                 return -1;
@@ -1626,7 +1628,8 @@ sub singletest {
 
     # first, remove all lingering log files
     if(!cleardir($LOGDIR) && $clearlocks) {
-        runner_clearlocks($LOGDIR);
+        my $logs = runner_clearlocks($LOGDIR);
+        logmsg $logs;
         cleardir($LOGDIR);
     }
 
@@ -1646,7 +1649,8 @@ sub singletest {
     # Register the test case with the CI environment
     citest_starttest($testnum);
 
-    my ($why, $error, $testtimings) = runner_test_preprocess($testnum);
+    my ($why, $error, $logs, $testtimings) = runner_test_preprocess($testnum);
+    logmsg $logs;
     if($error == -2) {
         if($postmortem) {
             # Error indicates an actual problem starting the server, so
@@ -1669,7 +1673,8 @@ sub singletest {
     my $CURLOUT;
     my $tool;
     my $usedvalgrind;
-    ($error, $testtimings, $cmdres, $CURLOUT, $tool, $usedvalgrind) = runner_test_run($testnum);
+    ($error, $logs, $testtimings, $cmdres, $CURLOUT, $tool, $usedvalgrind) = runner_test_run($testnum);
+    logmsg $logs;
     updatetesttimings($testnum, %$testtimings);
     if($error == -1) {
         # no further verification will occur
@@ -2231,6 +2236,8 @@ mkdir($PIDDIR, 0777);
 #
 
 get_disttests();
+# Disable buffered logging for now
+setlogfunc(\&logmsg);
 
 #######################################################################
 # Output curl version and host info being tested
@@ -2546,7 +2553,8 @@ my $sofar = time() - $start;
 citest_finishtestrun();
 
 # Tests done, stop the servers
-my $unexpected = runner_stopservers();
+my ($unexpected, $logs) = runner_stopservers();
+logmsg $logs;
 
 my $numskipped = %skipped ? sum values %skipped : 0;
 my $all = $total + $numskipped;

tests/servers.pm

@@ -114,7 +114,11 @@ use pathhelp qw(
 
 use processhelp;
 use globalconfig;
-use testutil;
+use testutil qw(
+    logmsg
+    runclient
+    runclientoutput
+    );
 
 
 my %serverpidfile; # all server pid file names, identified by server id
@@ -154,13 +158,6 @@ our $err_unexpected; # error instead of warning on server unexpectedly alive
 our $debugprotocol; # nonzero for verbose server logs
 our $stunnel; # path to stunnel command
 
-#######################################################################
-# Log an informational message
-# This just calls main's logmsg for now.
-
-sub logmsg {
-    return main::logmsg(@_);
-}
 
 #######################################################################
 # Check for a command in the PATH of the test server.

tests/testutil.pm

@@ -36,9 +36,15 @@ BEGIN {
     our @EXPORT = qw(
         runclient
         runclientoutput
+        setlogfunc
         subbase64
         subnewlines
     );
+
+    our @EXPORT_OK = qw(
+        clearlogs
+        logmsg
+    );
 }
 
 use MIME::Base64;
@@ -48,6 +54,45 @@ use globalconfig qw(
     $verbose
 );
 
+my $logfunc;      # optional reference to function for logging
+my @logmessages;  # array holding logged messages
+
+
+#######################################################################
+# Log an informational message
+# If a log callback function was set in setlogfunc, it is called. If not,
+# then the log message is buffered until retrieved by clearlogs.
+#
+# logmsg must only be called by one of the runner_* entry points and functions
+# called by them, or else logs risk being lost, since those are the only
+# functions that know about and will return buffered logs.
+sub logmsg {
+    if(!scalar(@_)) {
+        return;
+    }
+    if(defined $logfunc) {
+        &$logfunc(@_);
+        return;
+    }
+    push @logmessages, @_;
+}
+
+#######################################################################
+# Set the function to use for logging
+sub setlogfunc {
+    ($logfunc)=@_;
+}
+
+#######################################################################
+# Clear the buffered log messages after returning them
+sub clearlogs {
+    my $loglines = join('', @logmessages);
+    undef @logmessages;
+    return $loglines;
+}
+
+
+#######################################################################
 sub subbase64 {
     my ($thing) = @_;