diff --git a/tests/devtest.pl b/tests/devtest.pl index ae6ec090ec..6c33b242f3 100755 --- 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 22f88ae7c2..5e7c73d785 100644 --- 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 fad5c17d0d..14dfdffb80 100755 --- 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 1fc1c4800e..7c4b36778e 100644 --- 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 f80ae01769..4847878412 100644 --- 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) = @_;