runtests; give each server a unique log lock file

Logs are written by several servers and all of them must be finished
writing before the test results can be determined. This means each
server must have its own lock file rather than sharing a single one,
which is how it was done up to now. Previously, the first server to
complete a test would clear the lock before the other server was done,
which caused flaky tests.

Lock files are now all found in their own directory, so counting locks
equals counting the files in that directory.  The result is that the
proxy logs are now reliably written which actually changes the expected
output for two tests.

Fixes #11231
Closes #11259

tests/data/test1509

@@ -78,6 +78,7 @@ CONNECT the.old.moo.%TESTNUMBER:%HTTPPORT HTTP/1.1
 Host: the.old.moo.%TESTNUMBER:%HTTPPORT
 Proxy-Connection: Keep-Alive
 
+[DISCONNECT]
 </proxy>
 <protocol>
 GET /%TESTNUMBER HTTP/1.1

tests/data/test503

@@ -76,6 +76,7 @@ Host: machine.%TESTNUMBER:%HTTPPORT
 Proxy-Authorization: Basic dGVzdDppbmc=
 Proxy-Connection: Keep-Alive
 
+[DISCONNECT]
 </proxy>
 <protocol>
 GET /%TESTNUMBER HTTP/1.1

tests/ftpserver.pl

@@ -78,6 +78,10 @@ use pathhelp qw(
     exe_ext
     );
 
+use globalconfig qw(
+    $LOCKDIR
+    );
+
 #**********************************************************************
 # global vars...
 #
@@ -114,7 +118,6 @@ my $datasockf_logfile;  # log file for secondary connection sockfilt process
 #**********************************************************************
 # global vars used for server logs advisor read lock handling
 #
-my $SERVERLOGS_LOCK = "serverlogs.lock";
 my $serverlogs_lockfile;
 my $serverlogslocked = 0;
 
@@ -3040,7 +3043,6 @@ if(!$logfile) {
 $mainsockf_pidfile = mainsockf_pidfilename($piddir, $proto, $ipvnum, $idnum);
 $mainsockf_logfile =
     mainsockf_logfilename($logdir, $proto, $ipvnum, $idnum);
-$serverlogs_lockfile = "$logdir/$SERVERLOGS_LOCK";
 
 if($proto eq 'ftp') {
     $datasockf_pidfile = datasockf_pidfilename($piddir, $proto, $ipvnum, $idnum);
@@ -3049,6 +3051,7 @@ if($proto eq 'ftp') {
 }
 
 $srvrname = servername_str($proto, $ipvnum, $idnum);
+$serverlogs_lockfile = "$logdir/$LOCKDIR/${srvrname}.lock";
 
 $idstr = "$idnum" if($idnum > 1);
 

tests/globalconfig.pm

@@ -42,6 +42,7 @@ BEGIN {
         $has_shared
         $LIBDIR
         $listonly
+        $LOCKDIR
         $LOGDIR
         $memanalyze
         $MEMDUMP
@@ -100,6 +101,7 @@ our $memanalyze="$perl $srcdir/memanalyze.pl";
 our $valgrind;     # path to valgrind, or empty if disabled
 
 # paths in $LOGDIR
+our $LOCKDIR = "lock";          # root of the server directory with lock files
 our $PIDDIR = "server";         # root of the server directory with PID files
 our $SERVERIN="server.input";   # what curl sent the server
 our $PROXYIN="proxy.input";     # what curl sent the proxy

tests/runner.pm

@@ -125,7 +125,6 @@ our $tortalloc;
 my %oldenv;       # environment variables before test is started
 my $UNITDIR="./unit";
 my $CURLLOG="$LOGDIR/commands.log"; # all command lines run
-my $SERVERLOGS_LOCK="$LOGDIR/serverlogs.lock"; # server logs advisor read lock
 my $defserverlogslocktimeout = 2; # timeout to await server logs lock removal
 my $defpostcommanddelay = 0; # delay between command and postcheck sections
 my $multiprocess;   # nonzero with a separate test runner process
@@ -202,6 +201,7 @@ sub runner_init {
             # Set this directory as ours
             $LOGDIR = $logdir;
             mkdir("$LOGDIR/$PIDDIR", 0777);
+            mkdir("$LOGDIR/$LOCKDIR", 0777);
 
             # Initialize various server variables
             initserverconfig();
@@ -349,6 +349,20 @@ sub readtestkeywords {
 }
 
 
+#######################################################################
+# Return a list of log locks that still exist
+#
+sub logslocked {
+    opendir(my $lockdir, "$LOGDIR/$LOCKDIR");
+    my @locks;
+    foreach (readdir $lockdir) {
+        if(/^(.*)\.lock$/) {
+            push @locks, $1;
+        }
+    }
+    return @locks;
+}
+
 #######################################################################
 # Memory allocation test and failure torture testing.
 #
@@ -966,13 +980,15 @@ sub singletest_clean {
     }
     if($serverlogslocktimeout) {
         my $lockretry = $serverlogslocktimeout * 20;
-        while((-f $SERVERLOGS_LOCK) && $lockretry--) {
+        my @locks;
+        while((@locks = logslocked()) && $lockretry--) {
             portable_sleep(0.05);
         }
         if(($lockretry < 0) &&
            ($serverlogslocktimeout >= $defserverlogslocktimeout)) {
             logmsg "Warning: server logs lock timeout ",
-                   "($serverlogslocktimeout seconds) expired\n";
+                   "($serverlogslocktimeout seconds) expired (locks: " .
+                   join(", ", @locks) . ")\n";
         }
     }
 

tests/runtests.pl

@@ -330,8 +330,10 @@ sub cleardir {
     opendir(my $dh, $dir) ||
         return 0; # can't open dir
     while($file = readdir($dh)) {
-        # Don't clear the $PIDDIR since those need to live beyond one test
-        if(($file !~ /^(\.|\.\.)\z/) && "$file" ne $PIDDIR) {
+        # Don't clear the $PIDDIR or $LOCKDIR since those need to live beyond
+        # one test
+        if(($file !~ /^(\.|\.\.)\z/) &&
+            "$file" ne $PIDDIR && "$file" ne $LOCKDIR) {
             if(-d "$dir/$file") {
                 if(!cleardir("$dir/$file")) {
                     $done = 0;
@@ -1716,9 +1718,12 @@ sub singletest {
 
     if($singletest_state{$runnerid} == ST_INIT) {
         my $logdir = getrunnerlogdir($runnerid);
-        # first, remove all lingering log files
-        if(!cleardir($logdir) && $clearlocks) {
-            runnerac_clearlocks($runnerid, $logdir);
+        # first, remove all lingering log & lock files
+        if((!cleardir($logdir) || !cleardir("$logdir/$LOCKDIR"))
+            && $clearlocks) {
+            # On Windows, lock files can't be deleted when the process still
+            # has them open, so kill those processes first
+            runnerac_clearlocks($runnerid, "$logdir/$LOCKDIR");
             $singletest_state{$runnerid} = ST_CLEARLOCKS;
         } else {
             $singletest_state{$runnerid} = ST_INITED;
@@ -2432,6 +2437,7 @@ if ($gdbthis) {
 # Maybe create & use & delete a temporary directory in that function
 cleardir($LOGDIR);
 mkdir($LOGDIR, 0777);
+mkdir("$LOGDIR/$LOCKDIR", 0777);
 
 #######################################################################
 # initialize some variables
@@ -2777,6 +2783,7 @@ while () {
     if($ridready) {
         # This runner is ready to be serviced
         my $testnum = $runnersrunning{$ridready};
+        defined $testnum ||  die 'Internal error: test for runner unknown';
         delete $runnersrunning{$ridready};
         my ($error, $again) = singletest($ridready, $testnum, $countforrunner{$ridready}, $totaltests);
         if($again) {

tests/server/mqttd.c

@@ -1016,8 +1016,8 @@ int main(int argc, char *argv[])
     }
   }
 
-  msnprintf(loglockfile, sizeof(loglockfile), "%s/%s",
-            logdir, SERVERLOGS_LOCK);
+  msnprintf(loglockfile, sizeof(loglockfile), "%s/%s/mqtt-%s.lock",
+            logdir, SERVERLOGS_LOCKDIR, ipv_inuse);
 
 #ifdef WIN32
   win32_init();

tests/server/rtspd.c

@@ -1149,8 +1149,8 @@ int main(int argc, char *argv[])
     }
   }
 
-  msnprintf(loglockfile, sizeof(loglockfile), "%s/%s",
-            logdir, SERVERLOGS_LOCK);
+  msnprintf(loglockfile, sizeof(loglockfile), "%s/%s/rtsp-%s.lock",
+            logdir, SERVERLOGS_LOCKDIR, ipv_inuse);
 
 #ifdef WIN32
   win32_init();

tests/server/sws.c

@@ -1964,6 +1964,7 @@ int main(int argc, char *argv[])
   char port_str[11];
   const char *location_str = port_str;
   int keepalive_secs = 5;
+  const char *protocol_type = "HTTP";
 
   /* a default CONNECT port is basically pointless but still ... */
   size_t socket_idx;
@@ -2008,6 +2009,7 @@ int main(int argc, char *argv[])
     else if(!strcmp("--gopher", argv[arg])) {
       arg++;
       use_gopher = TRUE;
+      protocol_type = "GOPHER";
       end_of_headers = "\r\n"; /* gopher style is much simpler */
     }
     else if(!strcmp("--ipv4", argv[arg])) {
@@ -2109,8 +2111,9 @@ int main(int argc, char *argv[])
     }
   }
 
-  msnprintf(loglockfile, sizeof(loglockfile), "%s/%s",
-            logdir, SERVERLOGS_LOCK);
+  msnprintf(loglockfile, sizeof(loglockfile), "%s/%s/sws-%s%s-%s.lock",
+            logdir, SERVERLOGS_LOCKDIR, protocol_type,
+            is_proxy ? "-proxy" : "", socket_type);
 
 #ifdef WIN32
   win32_init();
@@ -2227,7 +2230,7 @@ int main(int argc, char *argv[])
     msnprintf(port_str, sizeof(port_str), "port %hu", port);
 
   logmsg("Running %s %s version on %s",
-         use_gopher?"GOPHER":"HTTP", socket_type, location_str);
+         protocol_type, socket_type, location_str);
 
   /* start accepting connections */
   rc = listen(sock, 5);

tests/server/tftpd.c

@@ -647,8 +647,8 @@ int main(int argc, char **argv)
     }
   }
 
-  msnprintf(loglockfile, sizeof(loglockfile), "%s/%s",
-            logdir, SERVERLOGS_LOCK);
+  msnprintf(loglockfile, sizeof(loglockfile), "%s/%s/tftp-%s.lock",
+            logdir, SERVERLOGS_LOCKDIR, ipv_inuse);
 
 #ifdef WIN32
   win32_init();

tests/server/util.h

@@ -31,8 +31,7 @@ long timediff(struct timeval newer, struct timeval older);
 
 #define TEST_DATA_PATH "%s/data/test%ld"
 #define ALTTEST_DATA_PATH "%s/test%ld"
-
-#define SERVERLOGS_LOCK "serverlogs.lock"
+#define SERVERLOGS_LOCKDIR "lock"  /* within logdir */
 
 /* global variable, where to find the 'data' dir */
 extern const char *path;