improve synchronization between test harness runtests.pl script

and test harness servers to minimize risk of false test failures.

http://curl.haxx.se/mail/lib-2008-04/0392.html

7 files changed, 132 insertions, 7 deletions

diff --git a/tests/ftp.pm b/tests/ftp.pm
index b3cc14abb..421fee1a6 100644
--- a/tests/ftp.pm
+++ b/tests/ftp.pm
@@ -5,7 +5,7 @@
 #                            | (__| |_| |  _ <| |___
 #                             \___|\___/|_| \_\_____|
 #
-# Copyright (C) 1998 - 2006, Daniel Stenberg, <daniel@haxx.se>, et al.
+# Copyright (C) 1998 - 2008, Daniel Stenberg, <daniel@haxx.se>, et al.
 #
 # This software is licensed as described in the file COPYING, which
 # you should have received as part of this distribution. The terms
@@ -84,4 +84,25 @@ sub ftpkillslaves {
     }
 }
 
+
+sub set_advisor_read_lock {
+    my ($filename) = @_;
+
+    if(open(FILEH, ">$filename")) {
+        close(FILEH);
+        return;
+    }
+    printf "Error creating lock file $filename error: $!";
+}
+
+
+sub clear_advisor_read_lock {
+    my ($filename) = @_;
+
+    if(-f $filename) {
+        unlink($filename);
+    }
+}
+
+
 1;
diff --git a/tests/ftpserver.pl b/tests/ftpserver.pl
index 02a048f13..ce82d642b 100644
--- a/tests/ftpserver.pl
+++ b/tests/ftpserver.pl
@@ -6,7 +6,7 @@
 #                            | (__| |_| |  _ <| |___
 #                             \___|\___/|_| \_\_____|
 #
-# Copyright (C) 1998 - 2007, Daniel Stenberg, <daniel@haxx.se>, et al.
+# Copyright (C) 1998 - 2008, Daniel Stenberg, <daniel@haxx.se>, et al.
 #
 # This software is licensed as described in the file COPYING, which
 # you should have received as part of this distribution. The terms
@@ -85,6 +85,8 @@ my $port = 8921; # just a default
 my $listenaddr = "127.0.0.1"; # just a default
 my $pidfile = ".ftpd.pid"; # a default, use --pidfile
 
+my $SERVERLOGS_LOCK="log/serverlogs.lock"; # server logs advisor read lock
+
 do {
     if($ARGV[0] eq "-v") {
         $verbose=1;
@@ -121,6 +123,7 @@ sub catch_zap {
     my $signame = shift;
     print STDERR "ftpserver.pl received SIG$signame, exiting\n";
     ftpkillslaves(1);
+    clear_advisor_read_lock($SERVERLOGS_LOCK);
     die "Somebody sent me a SIG$signame";
 }
 $SIG{INT} = \&catch_zap;
@@ -146,6 +149,7 @@ sub sysread_or_die {
         logmsg "Error: ftp$ftpdnum$ext sysread error: $!\n";
         kill(9, $sfpid);
         waitpid($sfpid, 0);
+        clear_advisor_read_lock($SERVERLOGS_LOCK);
         die "Died in sysread_or_die() at $fcaller " .
             "line $lcaller. ftp$ftpdnum$ext sysread error: $!\n";
     }
@@ -155,6 +159,7 @@ sub sysread_or_die {
         logmsg "Error: ftp$ftpdnum$ext read zero\n";
         kill(9, $sfpid);
         waitpid($sfpid, 0);
+        clear_advisor_read_lock($SERVERLOGS_LOCK);
         die "Died in sysread_or_die() at $fcaller " .
             "line $lcaller. ftp$ftpdnum$ext read zero\n";
     }
@@ -176,6 +181,7 @@ sub startsf {
         logmsg "Failed sockfilt command: $cmd\n";
         kill(9, $sfpid);
         waitpid($sfpid, 0);
+        clear_advisor_read_lock($SERVERLOGS_LOCK);
         die "Failed to start sockfilt!";
     }
 }
@@ -784,6 +790,8 @@ while(1) {
     }
     logmsg "====> Client connect\n";
 
+    set_advisor_read_lock($SERVERLOGS_LOCK);
+
     # flush data:
     $| = 1;
 
@@ -888,8 +896,13 @@ while(1) {
             
     } # while(1)
     logmsg "====> Client disconnected\n";
+
+    clear_advisor_read_lock($SERVERLOGS_LOCK);
 }
 
 print SFWRITE "QUIT\n";
 waitpid $sfpid, 0;
+
+clear_advisor_read_lock($SERVERLOGS_LOCK);
+
 exit;
diff --git a/tests/runtests.pl b/tests/runtests.pl
index 606c72dd5..857a28af2 100755
--- a/tests/runtests.pl
+++ b/tests/runtests.pl
@@ -120,6 +120,7 @@ my $SERVERIN="$LOGDIR/server.input"; # what curl sent the server
 my $SERVER2IN="$LOGDIR/server2.input"; # what curl sent the second server
 my $CURLLOG="$LOGDIR/curl.log"; # all command lines run
 my $FTPDCMD="$LOGDIR/ftpserver.cmd"; # copy ftp server instructions here
+my $SERVERLOGS_LOCK="$LOGDIR/serverlogs.lock"; # server logs advisor read lock
 
 # Normally, all test cases should be run, but at times it is handy to
 # simply run a particular one:
@@ -202,6 +203,10 @@ my $sshdvernum;  # for socks server, ssh daemon version number
 my $sshdverstr;  # for socks server, ssh daemon version string
 my $sshderror;   # for socks server, ssh daemon version error
 
+my $EXP_big_delay = 300;
+my $EXP_max_delay = 0;
+my $EXP_max_testn = 0;
+
 #######################################################################
 # variables the command line options may set
 #
@@ -2096,6 +2101,27 @@ sub singletest {
         }
     }
 
+    # If a server logs advisor read lock file exists, it is an indication
+    # that the server has not yet finished writing out all its log files,
+    # including server request log files used for protocol verification.
+    # So, if the lock file exists the script waits here a certain amount
+    # of time until the server removes it, or the given time expires.
+    # Test harness ssh server does not have this synchronization mechanism,
+    # this implies that some ssh server based tests might need a small delay
+    # in the postcheck section to avoid false test failures.
+
+    my $lockretry = ($testnum == 190) ? 10 : $EXP_big_delay ;
+    while((-f $SERVERLOGS_LOCK) && $lockretry--) {
+        sleep(1);
+    }
+
+    if($testnum != 190) {
+        if($EXP_big_delay - $lockretry > $EXP_max_delay) {
+            $EXP_max_delay = $EXP_big_delay - $lockretry;
+            $EXP_max_testn = $testnum;
+        }
+    }
+
     # run the postcheck command
     my @postcheck= getpart("client", "postcheck");
     $cmd = $postcheck[0];
@@ -3120,6 +3146,9 @@ if($skipped) {
         logmsg ")\n";
     }
 }
+
+logmsg "EXPERIMENTAL: lock max delay ($EXP_max_delay seconds) for test # $EXP_max_testn \n";
+
 if($total && ($ok != $total)) {
     exit 1;
 }
diff --git a/tests/server/sws.c b/tests/server/sws.c
index fc4123538..023fe270e 100644
--- a/tests/server/sws.c
+++ b/tests/server/sws.c
@@ -988,6 +988,8 @@ int main(int argc, char *argv[])
       break;
     }
 
+    set_advisor_read_lock(SERVERLOGS_LOCK);
+
 #ifdef CURL_SWS_FORK_ENABLED
     if(use_fork) {
       /* The fork enabled version just forks off the child and don't care
@@ -1063,6 +1065,8 @@ int main(int argc, char *argv[])
     logmsg("====> Client disconnect");
     sclose(msgsock);
 
+    clear_advisor_read_lock(SERVERLOGS_LOCK);
+
     if (req.testno == DOCNUMBER_QUIT)
       break;
 #ifdef CURL_SWS_FORK_ENABLED
@@ -1072,6 +1076,8 @@ int main(int argc, char *argv[])
 
   sclose(sock);
 
+  clear_advisor_read_lock(SERVERLOGS_LOCK);
+
   return 0;
 }
 
diff --git a/tests/server/tftpd.c b/tests/server/tftpd.c
index a98791de6..bafe47cf6 100644
--- a/tests/server/tftpd.c
+++ b/tests/server/tftpd.c
@@ -415,6 +415,7 @@ int main(int argc, char **argv)
   int flag;
   int rc;
   struct testcase test;
+  int result = 0;
 
   while(argc>arg) {
     if(!strcmp("--version", argv[arg])) {
@@ -518,20 +519,25 @@ int main(int argc, char **argv)
                  (struct sockaddr *)&from, &fromlen);
     if (n < 0) {
       logmsg("recvfrom:\n");
-      return 3;
+      result = 3;
+      break;
     }
 
+    set_advisor_read_lock(SERVERLOGS_LOCK);
+
     from.sin_family = AF_INET;
 
     peer = socket(AF_INET, SOCK_DGRAM, 0);
     if (peer < 0) {
       logmsg("socket:\n");
-      return 2;
+      result = 2;
+      break;
     }
 
     if (connect(peer, (struct sockaddr *)&from, sizeof(from)) < 0) {
       logmsg("connect: fail\n");
-      return 1;
+      result = 1;
+      break;
     }
     maxtimeout = 5*TIMEOUT;
 
@@ -545,8 +551,14 @@ int main(int argc, char **argv)
         free(test.buffer);
     }
     sclose(peer);
+
+    clear_advisor_read_lock(SERVERLOGS_LOCK);
+
   } while(1);
-  return 0;
+
+  clear_advisor_read_lock(SERVERLOGS_LOCK);
+
+  return result;
 }
 
 struct formats {
@@ -734,8 +746,10 @@ static void timer(int signum)
   logmsg("alarm!");
 
   timeout += rexmtval;
-  if (timeout >= maxtimeout)
+  if(timeout >= maxtimeout) {
+    clear_advisor_read_lock(SERVERLOGS_LOCK);
     exit(1);
+  }
 #ifdef HAVE_SIGSETJMP
   siglongjmp(timeoutbuf, 1);
 #endif
diff --git a/tests/server/util.c b/tests/server/util.c
index 8a2fa8814..64684545e 100644
--- a/tests/server/util.c
+++ b/tests/server/util.c
@@ -234,3 +234,39 @@ int write_pidfile(const char *filename)
   logmsg("Wrote pid %ld to %s", pid, filename);
   return 1; /* success */
 }
+
+void set_advisor_read_lock(const char *filename)
+{
+  FILE *lockfile;
+  int error;
+  int res;
+
+  do {
+    lockfile = fopen(filename, "wb");
+  } while((lockfile == NULL) && ((error = ERRNO) == EINTR));
+  if(lockfile == NULL) {
+    logmsg("Error creating lock file %s error: %d %s",
+           filename, error, strerror(error));
+    return;
+  }
+
+  do {
+    res = fclose(lockfile);
+  } while(res && ((error = ERRNO) == EINTR));
+  if(res)
+    logmsg("Error closing lock file %s error: %d %s",
+           filename, error, strerror(error));
+}
+
+void clear_advisor_read_lock(const char *filename)
+{
+  int error;
+  int res;
+
+  do {
+    res = unlink(filename);
+  } while(res && ((error = ERRNO) == EINTR));
+  if(res)
+    logmsg("Error removing lock file %s error: %d %s",
+           filename, error, strerror(error));
+}
diff --git a/tests/server/util.h b/tests/server/util.h
index 4f07fcb05..9b9dd598b 100644
--- a/tests/server/util.h
+++ b/tests/server/util.h
@@ -27,6 +27,8 @@ void logmsg(const char *msg, ...);
 
 #define TEST_DATA_PATH "%s/data/test%ld"
 
+#define SERVERLOGS_LOCK "log/serverlogs.lock"
+
 /* global variable, where to find the 'data' dir */
 extern const char *path;
 
@@ -53,4 +55,8 @@ int wait_ms(int timeout_ms);
 
 int write_pidfile(const char *filename);
 
+void set_advisor_read_lock(const char *filename);
+
+void clear_advisor_read_lock(const char *filename);
+
 #endif  /* __SERVER_UTIL_H */