TLS: rework error logging to pass more string back to caller for logging

[users/jgh/exim.git] / test / runtest

diff --git a/test/runtest b/test/runtest
index d9500cb5f8c33f3d969bf2f90d61ff9c0a2272f7..15631dfeb4273d789ec460b40ede416fa967d871 100755 (executable)
--- a/test/runtest
+++ b/test/runtest
@@ -50,7 +50,7 @@ my $cf = 'bin/cf -exact';
 my $cr = "\r";
 my $debug = 0;
 my $flavour = do {
 my $cr = "\r";
 my $debug = 0;
 my $flavour = do {

-  my $f = Exim::Runtest::flavour();
+  my $f = Exim::Runtest::flavour() // '';

   (grep { $f eq $_ } Exim::Runtest::flavours()) ? $f : 'FOO';
 };
 my $force_continue = 0;
   (grep { $f eq $_ } Exim::Runtest::flavours()) ? $f : 'FOO';
 };
 my $force_continue = 0;


@@ -358,6 +358,7 @@ open(IN, "$file") || tests_exit(-1, "Failed to open $file: $!");
 my($is_log) = $file =~ /log/;
 my($is_stdout) = $file =~ /stdout/;
 my($is_stderr) = $file =~ /stderr/;
 my($is_log) = $file =~ /log/;
 my($is_stdout) = $file =~ /stdout/;
 my($is_stderr) = $file =~ /stderr/;

+my($is_mail) = $file =~ /mail/;

 
 # Date pattern
 
 
 # Date pattern
 


@@ -420,12 +421,6 @@ RESET_AFTER_EXTRA_LINE_READ:
   s?prvs=([^/]+)/[\da-f]{10}@?prvs=$1/xxxxxxxxxx@?g;    # Old form
   s?prvs=[\da-f]{10}=([^@]+)@?prvs=xxxxxxxxxx=$1@?g;    # New form
 
   s?prvs=([^/]+)/[\da-f]{10}@?prvs=$1/xxxxxxxxxx@?g;    # Old form
   s?prvs=[\da-f]{10}=([^@]+)@?prvs=xxxxxxxxxx=$1@?g;    # New form
 

-  # Error lines on stdout from SSL contain process id values and file names.
-  # They also contain a source file name and line number, which may vary from
-  # release to release.
-  s/^\d+:error:/pppp:error:/;
-  s/:(?:\/[^\s:]+\/)?([^\/\s]+\.c):\d+:/:$1:dddd:/;
-

   # There are differences in error messages between OpenSSL versions
   s/SSL_CTX_set_cipher_list/SSL_connect/;
 
   # There are differences in error messages between OpenSSL versions
   s/SSL_CTX_set_cipher_list/SSL_connect/;
 


@@ -805,7 +800,10 @@ RESET_AFTER_EXTRA_LINE_READ:
   # numbers, or handle specific bad conditions in different ways, leading to
   # different wording in the error messages, so we cannot compare them.
 
   # numbers, or handle specific bad conditions in different ways, leading to
   # different wording in the error messages, so we cannot compare them.
 

-  s/(TLS error on connection (?:from .* )?\(SSL_\w+\): error:)(.*)/$1 <<detail omitted>>/;
+#XXX This loses any trailing "deliving unencypted to" which is unfortunate
+#    but I can't work out how to deal with that.
+  s/(TLS session: \(SSL_\w+\): error:)(.*)(?!: delivering)/$1 <<detail omitted>>/;
+  s/(TLS error on connection from .* \(SSL_\w+\): error:)(.*)/$1 <<detail omitted>>/;

   next if /SSL verify error: depth=0 error=certificate not trusted/;
 
   # ======== Maildir things ========
   next if /SSL verify error: depth=0 error=certificate not trusted/;
 
   # ======== Maildir things ========


@@ -889,15 +887,25 @@ RESET_AFTER_EXTRA_LINE_READ:
         }
       }
 
         }
       }
 

+    # remote IPv6 addrs vary
+    s/^(Connection request from) \[.*:.*:.*\]$/$1 \[ipv6\]/;
+

     # openssl version variances
     # openssl version variances

-    next if /^SSL info: unknown state/;
-    next if /^SSL info: SSLv2\/v3 write client hello A/;
-    next if /^SSL info: SSLv3 read server key exchange A/;
+  # Error lines on stdout from SSL contain process id values and file names.
+  # They also contain a source file name and line number, which may vary from
+  # release to release.
+
+    next if /^SSL info:/;

     next if /SSL verify error: depth=0 error=certificate not trusted/;
     s/SSL3_READ_BYTES/ssl3_read_bytes/i;
     next if /SSL verify error: depth=0 error=certificate not trusted/;
     s/SSL3_READ_BYTES/ssl3_read_bytes/i;

+    s/^\d+:error:\d+(:SSL routines:ssl3_read_bytes:[^:]+:).*(:SSL alert number \d\d)$/pppp:error:dddddddd$1\[...\]$2/;

 
     # gnutls version variances
     next if /^Error in the pull function./;
 
     # gnutls version variances
     next if /^Error in the pull function./;

+
+    # optional IDN2 variant conversions.  Accept either IDN1 or IDN2
+    s/conversion  strasse.de/conversion  xn--strae-oqa.de/;
+    s/conversion: german.xn--strae-oqa.de/conversion: german.straße.de/;

     }
 
   # ======== stderr ========
     }
 
   # ======== stderr ========


@@ -963,7 +971,7 @@ RESET_AFTER_EXTRA_LINE_READ:
     }
     next if /^tls_validate_require_cipher child \d+ ended: status=0x0/;
 
     }
     next if /^tls_validate_require_cipher child \d+ ended: status=0x0/;
 

-    # We invoke Exim with -D, so we hit this new messag as of Exim 4.73:
+    # We invoke Exim with -D, so we hit this new message as of Exim 4.73:

     next if /^macros_trusted overridden to true by whitelisting/;
 
     # We have to omit the localhost ::1 address so that all is well in
     next if /^macros_trusted overridden to true by whitelisting/;
 
     # We have to omit the localhost ::1 address so that all is well in


@@ -1076,6 +1084,10 @@ RESET_AFTER_EXTRA_LINE_READ:
     # Not all platforms build with DKIM enabled
     next if /^PDKIM >> Body data for hash, canonicalized/;
 
     # Not all platforms build with DKIM enabled
     next if /^PDKIM >> Body data for hash, canonicalized/;
 

+    #  Parts of DKIM-specific debug output depend on the time/date
+    next if /^date:\w+,\{SP\}/;
+    next if /^PDKIM \[[^[]+\] (Header hash|b) computed:/;
+

     # Not all platforms support TCP Fast Open, and the compile omits the check
     if (s/\S+ in hosts_try_fastopen\? no \(option unset\)\n$//)
       {
     # Not all platforms support TCP Fast Open, and the compile omits the check
     if (s/\S+ in hosts_try_fastopen\? no \(option unset\)\n$//)
       {


@@ -1506,14 +1518,14 @@ $munges =
                   )($|[ ]=)/x' },
 
     'sys_bindir' =>
                   )($|[ ]=)/x' },
 
     'sys_bindir' =>

-    { 'mainlog' => 's%/(usr/)?bin/%SYSBINDIR/%' },
+    { 'mainlog' => 's%/(usr/(local/)?)?bin/%SYSBINDIR/%' },

 
     'sync_check_data' =>
     { 'mainlog'   => 's/^(.* SMTP protocol synchronization error .* next input=.{8}).*$/$1<suppressed>/',
       'rejectlog' => 's/^(.* SMTP protocol synchronization error .* next input=.{8}).*$/$1<suppressed>/'},
 
     'debuglog_stdout' =>
 
     'sync_check_data' =>
     { 'mainlog'   => 's/^(.* SMTP protocol synchronization error .* next input=.{8}).*$/$1<suppressed>/',
       'rejectlog' => 's/^(.* SMTP protocol synchronization error .* next input=.{8}).*$/$1<suppressed>/'},
 
     'debuglog_stdout' =>

-    { 'stdout' => 's/^\d\d:\d\d:\d\d\s+\d+ //;
+    { 'stdout' => 's/^[ .]*\d\d:\d\d:\d\d\s+\d+ //;

                   s/Process \d+ is ready for new message/Process pppp is ready for new message/'
     },
 
                   s/Process \d+ is ready for new message/Process pppp is ready for new message/'
     },
 


@@ -1780,7 +1792,7 @@ system("$cmd");
 # The <SCRIPT> file is open for us to read an optional return code line,
 # followed by the command line and any following data lines for stdin. The
 # command line can be continued by the use of \. Data lines are not continued
 # The <SCRIPT> file is open for us to read an optional return code line,
 # followed by the command line and any following data lines for stdin. The
 # command line can be continued by the use of \. Data lines are not continued

-# in this way. In all lines, the following substutions are made:
+# in this way. In all lines, the following substitutions are made:

 #
 # DIR    => the current directory
 # CALLER => the caller of this script
 #
 # DIR    => the current directory
 # CALLER => the caller of this script


@@ -1789,14 +1801,14 @@ system("$cmd");
 #            reference to the subtest number, holding previous value
 #            reference to the expected return code value
 #            reference to where to put the command name (for messages)
 #            reference to the subtest number, holding previous value
 #            reference to the expected return code value
 #            reference to where to put the command name (for messages)

-#            auxilliary information returned from a previous run
+#            auxiliary information returned from a previous run

 #
 #

-# Returns:   0 the commmand was executed inline, no subprocess was run
+# Returns:   0 the command was executed inline, no subprocess was run

 #            1 a non-exim command was run and waited for
 #            2 an exim command was run and waited for
 #            3 a command was run and not waited for (daemon, server, exim_lock)
 #            4 EOF was encountered after an initial return code line
 #            1 a non-exim command was run and waited for
 #            2 an exim command was run and waited for
 #            3 a command was run and not waited for (daemon, server, exim_lock)
 #            4 EOF was encountered after an initial return code line

-# Optionally alse a second parameter, a hash-ref, with auxilliary information:
+# Optionally also a second parameter, a hash-ref, with auxiliary information:

 #            exim_pid: pid of a run process
 #            munge: name of a post-script results munger
 
 #            exim_pid: pid of a run process
 #            munge: name of a post-script results munger
 


@@ -2257,14 +2269,20 @@ elsif (/^((?i:[A-Z\d_]+=\S+\s+)+)?(\d+)?\s*(sudo(?:\s+-u\s+(\w+))?\s+)?exim(_\S+
 
   if ($args =~ /\$msg/)
     {
 
   if ($args =~ /\$msg/)
     {

-    my($listcmd) = "$parm_cwd/eximdir/exim -bp " .
-                   "-DEXIM_PATH=$parm_cwd/eximdir/exim " .
-                   "-C $parm_cwd/test-config |";
-    print ">> Getting queue list from:\n>>    $listcmd\n" if ($debug);
-    open (QLIST, $listcmd) || tests_exit(-1, "Couldn't run \"exim -bp\": $!\n");
-    my(@msglist) = ();
-    while (<QLIST>) { push (@msglist, $1) if /^\s*\d+[smhdw]\s+\S+\s+(\S+)/; }
-    close(QLIST);
+    my @listcmd  = ("$parm_cwd/eximdir/exim", '-bp',
+                   "-DEXIM_PATH=$parm_cwd/eximdir/exim",
+                   -C => "$parm_cwd/test-config");
+    print ">> Getting queue list from:\n>>    @listcmd\n" if $debug;
+    # We need the message ids sorted in ascending order.
+    # Message id is: <timestamp>-<pid>-<fractional-time>. On some systems (*BSD) the
+    # PIDs are randomized, so sorting just the whole PID doesn't work.
+    # We do the Schartz' transformation here (sort on
+    # <timestamp><fractional-time>). Thanks to Kirill Miazine
+    my @msglist =
+      map { $_->[1] }                                   # extract the values
+      sort { $a->[0] cmp $b->[0] }                      # sort by key
+      map { [join('.' => (split /-/, $_)[0,2]) => $_] } # key (timestamp.fractional-time) => value(message_id)
+      map { /^\s*\d+[smhdw]\s+\S+\s+(\S+)/ } `@listcmd` or tests_exit(-1, "No output from `exim -bp` (@listcmd)\n");

 
     # Done backwards just in case there are more than 9
 
 
     # Done backwards just in case there are more than 9
 


@@ -2612,9 +2630,12 @@ close(IN);
 close(OUT);
 
 print("Probing with config file: $parm_cwd/test-config\n");
 close(OUT);
 
 print("Probing with config file: $parm_cwd/test-config\n");

+

 my $eximinfo = "$parm_exim -d -C $parm_cwd/test-config -DDIR=$parm_cwd -bP exim_user exim_group";
 chomp(my @eximinfo = `$eximinfo 2>&1`);
 my $eximinfo = "$parm_exim -d -C $parm_cwd/test-config -DDIR=$parm_cwd -bP exim_user exim_group";
 chomp(my @eximinfo = `$eximinfo 2>&1`);

-die "$0: got $? from $eximinfo\n" if $?;
+die "$0: Can't run $eximinfo\n" if $? == -1;
+
+warn 'Got ' . $?>>8 . " from $eximinfo\n" if $?;

 foreach (@eximinfo)
   {
   if (my ($version) = /^Exim version (\S+)/) {
 foreach (@eximinfo)
   {
   if (my ($version) = /^Exim version (\S+)/) {


@@ -2796,7 +2817,7 @@ if (defined $parm_support{Content_Scanning})
     # This test for an active SpamAssassin is courtesy of John Jetmore.
     # The tests are hard coded to localhost:783, so no point in making
     # this test flexible like the clamav test until the test scripts are
     # This test for an active SpamAssassin is courtesy of John Jetmore.
     # The tests are hard coded to localhost:783, so no point in making
     # this test flexible like the clamav test until the test scripts are

-    # changed.  spamd doesn't have the nice PING/PONG protoccol that
+    # changed.  spamd doesn't have the nice PING/PONG protocol that

     # clamd does, but it does respond to errors in an informative manner,
     # so use that.
 
     # clamd does, but it does respond to errors in an informative manner,
     # so use that.
 


@@ -3928,7 +3949,8 @@ foreach $test (@test_list)
       if ($? != 0)
         {
         if (($? & 0xff) == 0)
       if ($? != 0)
         {
         if (($? & 0xff) == 0)

-          { printf("Server return code %d", $?/256); }
+          { printf("Server return code %d for test %d starting line %d", $?/256,
+               $testno, $subtest_startline); }

         elsif (($? & 0xff00) == 0)
           { printf("Server killed by signal %d", $? & 255); }
         else
         elsif (($? & 0xff00) == 0)
           { printf("Server killed by signal %d", $? & 255); }
         else