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

diff --git a/tests/devtest.pl b/tests/devtest.pl
index ae6ec090ecae12517dde8cebb305dac9dc6aed51..6c33b242f3a1e5e9fbd2ab7a27f9e469e204c1fe 100755 (executable)
--- a/tests/devtest.pl
+++ b/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();
 }

diff --git a/tests/runner.pm b/tests/runner.pm
index 22f88ae7c27ab062dd7e904d758a245c7a0734b2..5e7c73d7859d399583c443cdfd9b67503b88c1a3 100644 (file)
--- a/tests/runner.pm
+++ b/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;

diff --git a/tests/runtests.pl b/tests/runtests.pl
index fad5c17d0daec1f0b9922dac1c8352adbe0a7745..14dfdffb808c29630336989966325edd8e86531b 100755 (executable)
--- a/tests/runtests.pl
+++ b/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;

diff --git a/tests/servers.pm b/tests/servers.pm
index 1fc1c4800e6081d6fb40ca881c1fd88b195e0083..7c4b36778e69eb4a82feffff82857afedba35723 100644 (file)
--- a/tests/servers.pm
+++ b/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.

diff --git a/tests/testutil.pm b/tests/testutil.pm
index f80ae017699a41e6b5059cb2589225a93c407165..4847878412f6fb77dd0b22610cdb76b906244d6e 100644 (file)
--- a/tests/testutil.pm
+++ b/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) = @_;