Logging: convert an internal element from static to allocated buffer
[exim.git] / test / runtest
index e77a4afaed14ed3bc90d94b113c480c5d0014ad9..ae2d929fd901a5472f7c05f80e83e8daa6f01e5c 100755 (executable)
@@ -254,9 +254,11 @@ die "** runtest error: $_[1]\n";
 sub new_value {
 my($oldid, $base, $sequence) = @_;
 my($newid) = $cache{$oldid};
+print ">> replace  $oldid -> $newid\n" if ($debug && defined $newid);
 if (! defined $newid)
   {
   $newid = sprintf($base, $$sequence++);
+  print ">> new      $oldid -> $newid\n" if $debug;
   $cache{$oldid} = $newid;
   }
 return $newid;
@@ -342,7 +344,7 @@ return @yield;
 # into the same standard values throughout the data from a single test.
 # Message ids get this treatment (can't be made reliable for times), and
 # times in dumped retry databases are also handled in a special way, as are
-# incoming port numbers.
+# incoming port numbers and PIDs.
 
 # On entry to the subroutine, the file to write to is already opened with the
 # name MUNGED. The input file name is the only argument to the subroutine.
@@ -385,11 +387,23 @@ $spid = "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx";
 LINE: while(<IN>)
   {
 RESET_AFTER_EXTRA_LINE_READ:
+  if ($munge_skip)
+    {
+    # Munging is a no-op, except for exim_msgdate specials.
+    # Useful when testing exim_msgdate so that
+    # we compare unmunged dates and message-ids.
+    s%^localhost \d+ from message-id != given number \d+ at \K/.+(?=/test/eximdir/exim_msgdate line 387.$)%DIR%;
+
+    print MUNGED;
+    next;
+    }
+
   # Custom munges
   if ($extra)
     {
     next if $extra =~ m%^/%  &&  eval $extra;
     eval $extra if $extra =~ m/^s/;
+    eval substr($extra, 1) if $extra =~ m/^R/;
     }
 
   # Check for "*** truncated ***"
@@ -411,9 +425,12 @@ RESET_AFTER_EXTRA_LINE_READ:
   # patchexim should have fixed this for us
   #s/Exim \K\d+[._]\d+[\w_-]*/x.yz/i;
 
-  # Replace Exim message ids by a unique series
+  # Replace Exim message ids by a unique series.
+  # Both old and new formats, with separate replace series, for now.
   s/(\d[^\W_]{5}-[^\W_]{6}-[^\W_]{2})
-    /new_value($1, "10Hm%s-0005vi-00", \$next_msgid)/egx;
+    /new_value($1, "10Hm%s-0005vi-00", \$next_msgid_old)/egx;
+  s/(\d[^\W_]{5}-[^\W_]{11}-[^\W_]{4})
+    /new_value($1, "10Hm%s-000000005vi-0000", \$next_msgid)/egx;
 
   # The names of lock files appear in some error and debug messages
   s/\.lock(\.[-\w]+)+(\.[\da-f]+){2}/.lock.test.ex.dddddddd.pppppppp/;
@@ -507,7 +524,7 @@ RESET_AFTER_EXTRA_LINE_READ:
 
   # Date/time in logs and in one instance of a filter test
   s/^\d{4}-\d\d-\d\d\s\d\d:\d\d:\d\d(\s[+-]\d\d\d\d)?\s/1999-03-02 09:44:33 /gx;
-  s/^\d{4}-\d\d-\d\d\s\d\d:\d\d:\d\d\.\d{3}(\s[+-]\d\d\d\d)?\s/2017-07-30 18:51:05.712 /gx;
+  s/^\d{4}-\d\d-\d\d\s\d\d:\d\d:\d\d\.\d{3}(?:\s(?:[+-]\d\d\d\d|[A-Z]{2}T))?\s/2017-07-30 18:51:05.712 /gx;
   s/^Logwrite\s"\d{4}-\d\d-\d\d\s\d\d:\d\d:\d\d/Logwrite "1999-03-02 09:44:33/gx;
   # Date/time in syslog test
   s/^SYSLOG:\s\'\K\d{4}-\d\d-\d\d\s\d\d:\d\d:\d\d\s/2017-07-30 18:51:05 /gx;
@@ -747,7 +764,7 @@ RESET_AFTER_EXTRA_LINE_READ:
 
   s/\bgid=\d+/gid=gggg/;
   s/\begid=\d+/egid=gggg/;
-  s/\b(pid=|pid |PID: )\d+/$1pppp/;
+  s/\b(?:pid=|pid\s|PID:\s|Process\s|child\s)\K(\d+)/new_value($1, "p%s", \$next_pid)/gxe;
   s/\buid=\d+/uid=uuuu/;
   s/\beuid=\d+/euid=uuuu/;
   s/set_process_info:\s+\d+/set_process_info: pppp/;
@@ -835,10 +852,10 @@ RESET_AFTER_EXTRA_LINE_READ:
 
   # ======== IP error numbers and messages ========
   # These vary between operating systems
-  s/Can(no|')t assign requested address/Network Error/;
+  s/Can(no|')t assign requested address/Netwk addr not available/;
   s/Operation timed out/Connection timed out/;
   s/Address family not supported by protocol family/Network Error/;
-  s/Network( is)? unreachable/Network Error/;
+  s/Network( is)? unreachable/Network unreachable/;
   s/Invalid argument/Network Error/;
 
   s/\(\d+\): Network/(dd): Network/;
@@ -874,7 +891,7 @@ RESET_AFTER_EXTRA_LINE_READ:
 
   s/([\s,])S=\d+\b/$1S=sss/;
   s/:S\d+\b/:Ssss/;
-  s/^(\s*\d+m\s+)\d+(\s+[a-z0-9-]{16} <)/$1sss$2/i if $is_stdout;
+  s/^(\s*\d+[mhd]\s+)\d+(\s+(?:[a-z0-9-]{23}|[a-z0-9-]{18}) <)/TTT   sss$2/i if $is_stdout;
   s/\sSIZE=\d+\b/ SIZE=ssss/;
   s/\ssize=\d+\b/ size=sss/ if $is_stderr;
   s/old size = \d+\b/old size = sssss/;
@@ -918,6 +935,11 @@ RESET_AFTER_EXTRA_LINE_READ:
   # OpenSSL 3.0.0
   s/TLS error \(D-H param setting .* error:\K.*dh key too small/xxxxxxxx:SSL routines::dh key too small/;
 
+  # OpenSSL 1.1.1
+  s/error:\K0B080074:x509 certificate routines:X509_check_private_key(?=:key values mismatch$)/05800074:x509 certificate routines:/;
+  s/error:\K02001002:system library:fopen(?=:No such file or directory$)/80000002:system library:/;
+  s/error:\K0909006C:PEM routines:get_name(?=:no start line$)/0480006C:PEM routines:/;
+
   # ======== Maildir things ========
   # timestamp output in maildir processing
   s/(timestamp=|\(timestamp_only\): )\d+/$1ddddddd/g;
@@ -1043,9 +1065,13 @@ RESET_AFTER_EXTRA_LINE_READ:
     # TLS resumption is not always supported by the build
     next if /^tls_resumption_hosts =/;
     next if /^-tls_resumption/;
+    next if /^host_name_extract = /;
 
     # gsasl library version may not support some methods
     s/250-AUTH ANONYMOUS PLAIN SCRAM-SHA-1\K SCRAM-SHA-256//;
+
+    # mailq times change with when the run is done, vs. static-source spoolfiles
+    s/\s*\d*[hd](?=   317 [0-9A-Za-z\-]{23} <nobody\@test.ex>)/DDd/;
     }
 
   # ======== stderr ========
@@ -1053,14 +1079,33 @@ RESET_AFTER_EXTRA_LINE_READ:
   elsif ($is_stderr)
     {
     # The very first line of debugging output will vary
-
     s/^Exim version .*/Exim version x.yz ..../;
 
-    # Debugging lines for Exim terminations and process-generation
+    # Skip some lines that Exim puts out at the start of debugging output
+    # because they will be different in different binaries.
+
+    next if /^$time_pid?
+               (?: Berkeley\ DB:\s
+                 | Probably\ (?:Berkeley\ DB|ndbm|GDBM)
+                 | Using\ tdb
+                 | Authenticators:
+                 | Lookups(?:\(built-in\))?:
+                 | Support\ for:
+                 | Routers:
+                 | Transports:
+                 | Malware:
+                 | log\ selectors\ =
+                 | cwd=
+                 | Fixed\ never_users
+                 | Configure\ owner
+                 | Size\ of\ off_t:
+               )
+             /x;
+
+    # Lines with a leading pid.  Only handle >= 4-digit PIDs to avoid converting SMTP respose codes
+    s/^\s*(\d{4,})\s(?!(?:previous message|in\s|bytes remain in|SMTP accept process running))/new_value($1, "p%s", \$next_pid) . ' '/e;
 
-    s/(?<=^>>>>>>>>>>>>>>>> Exim pid=)\d+(?= terminating)/pppp/;
-    s/^(proxy-proc \w{5}-pid) \d+$/$1 pppp/;
-    s/^(?:\s*\d+ )(exec .* -oPX)$/pppp $1/;
+    # Debugging lines for Exim terminations and process-generation
     next if /(?:postfork: | fork(?:ing|ed) for )/;
 
     # IP address lookups use gethostbyname() when IPv6 is not supported,
@@ -1074,6 +1119,14 @@ RESET_AFTER_EXTRA_LINE_READ:
     # we don't care what TZ enviroment the testhost was running
     next if /^Reset TZ to/;
 
+    # port numbers
+    s/(?:\[[^\]]*\]:|V4NET\.0\.0\.0:|localhost::?|127\.0\.0\.1[.:]:?|port[= ])\K$parm_port_d/PORT_D/;
+    s/(?:\[[^\]]*\]:|V4NET\.0\.0\.0:|localhost::?|127\.0\.0\.1[.:]:?|port[= ])\K$parm_port_d2/PORT_D2/;
+    s/(?:\[[^\]]*\]:|V4NET\.0\.0\.0:|localhost::?|127\.0\.0\.1[.:]:?|port[= ])\K$parm_port_d3/PORT_D3/;
+    s/(?:\[[^\]]*\]:|V4NET\.0\.0\.0:|localhost::?|127\.0\.0\.1[.:]:?|port[= ])\K$parm_port_d4/PORT_D4/;
+    s/(?:\[[^\]]*\]:|V4NET\.0\.0\.0:|localhost::?|127\.0\.0\.1[.:]:?|port[= ])\K$parm_port_s/PORT_S/;
+    s/(?:\[[^\]]*\]:|V4NET\.0\.0\.0:|localhost::?|127\.0\.0\.1[.:]:?|port[= ])\K$parm_port_n/PORT_N/;
+
     # ========= Exim lookups ==================
     # Lookups have a char which depends on the number of lookup types compiled in,
     # in stderr output.  Replace with a "0".  Recognising this while avoiding
@@ -1086,6 +1139,8 @@ RESET_AFTER_EXTRA_LINE_READ:
     # and unwanted debug
     next if /^GnuTLS<2>: FIPS140-2 (context is not set|operation mode switched from initial to not-approved)$/;
     next if /^GnuTLS<3>: ASSERT: sign.c\[_gnutls_sign_is_secure2\]:\d+$/;
+    next if /^GnuTLS<3>: ASSERT: \.\.\/\.\.\/lib\/pkcs11.c\[find_multi_objs_cb\]:/;
+    next if /^GnuTLS<3>: ASSERT: \.\.\/\.\.\/lib\/pkcs11.c\[gnutls_pkcs11_obj_list_import_url3\]:/;
 
     # drop openssl version strings
     next if /OpenSSL compile-time version: OpenSSL \d+[\.\da-z]+/;
@@ -1097,10 +1152,10 @@ RESET_AFTER_EXTRA_LINE_READ:
 
     # TLS preload
     # only OpenSSL speaks of these
-    next if /^TLS: (preloading (DH params|ECDH curve|CA bundle) for server|generating selfsigned server cert)/;
-    next if /^Diffie-Hellman initialized from default/;
-    next if /^ECDH OpenSSL (< )?[\d.+]+: temp key parameter settings:/;
-    next if /^ECDH: .*'prime256v1'/;
+    next if /^TLS: (preloading (DH params \S+|ECDH curve \S+|CA bundle) for server|generating selfsigned server cert)/;
+    next if /^ Diffie-Hellman initialized from default/;
+    next if /^ ECDH OpenSSL (< )?[\d.+]+: temp key parameter settings:/;
+    next if /^ ECDH: .*'prime256v1'/;
     next if /^tls_verify_certificates: system$/;
     next if /^tls_set_watch: .*\/cert.pem/;
     next if /^Generating 2048 bit RSA key/;
@@ -1135,6 +1190,9 @@ RESET_AFTER_EXTRA_LINE_READ:
     next if /^TLS: not preloading (CA bundle|cipher list) for server$/;
     next if /^TLS: not preloading server certs$/;
 
+    # some plaatforms are missing the standard CA bundle file
+    next if /^tls_set_watch\(\) fail on '\/usr\/lib\/ssl\/cert.pem': No such file or directory$/;
+
     # drop lookups
     next if /^$time_pid?(?: Lookups\ \(built-in\):
                                        | Loading\ lookup\ modules\ from
@@ -1219,6 +1277,7 @@ RESET_AFTER_EXTRA_LINE_READ:
     # Skip tls_advertise_hosts and hosts_require_tls checks when the options
     # are unset, because tls ain't always there.
 
+    next if /^((>>>)?\s*host)? in tls_advertise_hosts\?$/;
     next if /in\s(?:tls_advertise_hosts\?|hosts_require_tls\?)
                 \sno\s\((option\sunset|end\sof\slist)\)/x;
 
@@ -1290,9 +1349,7 @@ RESET_AFTER_EXTRA_LINE_READ:
     next if /in\shosts_require_dane\?\sno\s\(option\sunset\)/x;
 
     # daemon notifier socket
-    s/^(\s*\d+|ppppp) (creating notifier socket)$/ppppp $2/;
-    s/^ \@(.*exim_daemon_notify)$/ $1/;
-    s/^(\s*\d+|ppppp)  \@?(.*exim_daemon_notify)$/ppppp  $2/;
+    s% \@(?=[^ @]+/spool/exim_daemon_notify$)% %;
     next if /unlinking notifier socket/;
 
     # daemon notifier socket
@@ -1306,6 +1363,9 @@ RESET_AFTER_EXTRA_LINE_READ:
 
     # Different builds will have different lookup types included
     s/^\s*search_type \K\d+ \((\w+)\) quoting -1 \(none\)$/NN ($1) quoting -1 (none)/;
+    # and different numbers of lookup types result in different type-code letters,
+    # so convert them all to "0"
+    s%(?<!lsearch)[^ ](?=TESTSUITE/aux-fixed/(?:0414.list[12]|0464.domains)$)%0%;
 
     # DISABLE_OCSP
     next if /in hosts_requ(est|ire)_ocsp\? (no|yes)/;
@@ -1314,7 +1374,13 @@ RESET_AFTER_EXTRA_LINE_READ:
     next if /host in hosts_proxy\?/;
 
     # PIPE_CONNECT
-    next if / in (pipelining_connect_advertise_hosts|hosts_pipe_connect)?\? no /;
+    if ( /^(>>>)?\s*host in pipelining_connect_advertise_hosts\?$/ )
+      {
+      $_ = <IN>;
+      while ( /^(>>>)?\s*list element:/ ) { $_ = <IN>; }
+      goto RESET_AFTER_EXTRA_LINE_READ;
+      }
+    next if / in (?:pipelining_connect_advertise_hosts|hosts_pipe_connect)?\? no /;
 
     # Experimental_International
     next if / in smtputf8_advertise_hosts\? no \(option unset\)/;
@@ -1323,11 +1389,25 @@ RESET_AFTER_EXTRA_LINE_READ:
     next if / in tls_advertise_requiretls?\? no \(end of list\)/;
 
     # Experimental_LIMITS
+    if ( /^((>>>)?\s*host)? in limits_advertise_hosts\?$/ )
+      {
+      $_ = <IN>;
+      while ( /^(>>>)?\s*list element: !\*$/ ) { $_ = <IN>; }
+      goto RESET_AFTER_EXTRA_LINE_READ;
+      }
     next if / in limits_advertise_hosts?\? no \(matched "!\*"\)/;
 
+    # Experimental_XCLIENT
+    next if / in hosts_xclient?\? no \(option unset\)/;
+
     # TCP Fast Open
     next if /^(ppppp )?setsockopt FASTOPEN: Network Error/;
 
+    # DISABLE_TLS_RESUME
+    # TLS resumption is not always supported by the build
+    next if /in tls_resumption_hosts\?/;
+    next if /RE '.outlook.com/;
+
     # Environment cleaning
     next if /\w+ in keep_environment\? (yes|no)/;
 
@@ -1372,7 +1452,7 @@ RESET_AFTER_EXTRA_LINE_READ:
       s/Address family not supported by protocol family/Network Error/;
       s/Network is unreachable/Network Error/;
       }
-    next if /^(ppppp )?setsockopt FASTOPEN: Protocol not available$/;
+    next if /^(ppppp |\d+ )?setsockopt FASTOPEN: Protocol not available$/;
     s/^(Connecting to .* \.\.\. sending) \d+ (nonTFO early-data)$/$1 dd $2/;
 
     if (/^([0-9: ]*                                            # possible timestamp
@@ -1413,13 +1493,12 @@ RESET_AFTER_EXTRA_LINE_READ:
 
     # Postgres version-dependent differences
     s/^initdb: warning: (enabling "trust" authentication for local connections)$/\nWARNING: $1/;
+    # Postgre DB server PID
+    s/ \[\d+\] (?=(LOG:  redirecting log|HINT:  Future log output))/ [pppp] /;
 
     # Not all builds include DMARC
     next if /^DMARC: no (dmarc_tld_file|sender_host_address)$/ ;
 
-    # TLS resumption is not always supported by the build
-    next if /in tls_resumption_hosts\?/;
-
     # Platform differences in errno strings
     s/  SMTP\(Operation timed out\)<</  SMTP(Connection timed out)<</;
 
@@ -1432,8 +1511,11 @@ RESET_AFTER_EXTRA_LINE_READ:
     s/^\d\d:\d\d:\d\d\s+/01:01:01 /mg;
 
     # pid in debug lines
-    s/^(\d\d:\d\d:\d\d)(\s+\d+\s)/"$1 " . new_value($2, "%s", \$next_pid) . " "/mgxe;
-    s/(?<!post-)[Pp]rocess\K(\s\d+ )/new_value($1, "%s", \$next_pid) . " "/gxe;
+    s/^(\d\d:\d\d:\d\d\s+)(\d+)/$1 . new_value($2, "p%s", \$next_pid) . " "/mgxe;
+    s/(?<!post-)[Pp]rocess\K(\s\d+ )/new_value($1, "p%s", \$next_pid) . " "/gxe;
+
+    # Path in environment varies
+    s/ PATH=\K.*$/<munged>/;
 
     # When Exim is checking the size of directories for maildir, it uses
     # the check_dir_size() function to scan directories. Of course, the order
@@ -1456,27 +1538,6 @@ RESET_AFTER_EXTRA_LINE_READ:
         @saved = ();
         }
 
-      # Skip some lines that Exim puts out at the start of debugging output
-      # because they will be different in different binaries.
-
-      next if /^$time_pid?
-                 (?: Berkeley\ DB:\s
-                   | Probably\ (?:Berkeley\ DB|ndbm|GDBM)
-                   | Using\ tdb
-                   | Authenticators:
-                   | Lookups(?:\(built-in\))?:
-                   | Support\ for:
-                   | Routers:
-                   | Transports:
-                   | Malware:
-                   | log\ selectors\ =
-                   | cwd=
-                   | Fixed\ never_users
-                   | Configure\ owner
-                   | Size\ of\ off_t:
-                 )
-               /x;
-
       print MUNGED;
       }
 
@@ -1493,13 +1554,15 @@ RESET_AFTER_EXTRA_LINE_READ:
     # CHUNKING: exact sizes depend on hostnames in headers
     s/(=>.* K C="250- \d)\d+ (byte chunk, total \d)\d+/$1nn $2nn/;
 
-    # openssl version variances
-    s/(TLS error on connection [^:]*: error:)[0-9A-F]{8}(:system library):(?:fopen|func\(4095\)):(No such file or directory)$/$1xxxxxxxx$2:fopen:$3/;
-    s/(DANE attempt failed.*error:)[0-9A-F]{8}(:SSL routines:)(?:(?i)ssl3_get_server_certificate|tls_process_server_certificate|CONNECT_CR_CERT)(?=:certificate verify failed$)/$1xxxxxxxx$2ssl3_get_server_certificate/;
+    # OpenSSL version variances
+    s/(TLS error on connection [^:]*: error:)[0-9A-F]{8}(:system library):(?:fopen|func\(4095\)|):(No such file or directory)$/$1xxxxxxxx$2:fopen:$3/;
+    next if /TLS error \(SSL_read\): .*error:0A000126:SSL routines::unexpected eof while reading$/ ;
+    s/EVDATA: \K\(SSL_accept\): error:0A000126:SSL routines::unexpected eof while reading/SSL_accept: TCP connection closed by peer/;
+    s/(DANE attempt failed.*error:)[0-9A-F]{8}(:SSL routines:)(?:(?i)ssl3_get_server_certificate|tls_process_server_certificate|CONNECT_CR_CERT|)(?=:certificate verify failed$)/$1xxxxxxxx$2ssl3_get_server_certificate/;
     s/(DKIM: validation error: )error:[0-9A-F]{8}:rsa routines:(?:(?i)int_rsa_verify|CRYPTO_internal):(?:bad signature|algorithm mismatch)$/$1Public key signature verification has failed./;
     s/ARC: AMS signing: privkey PEM-block import: error:\K[0-9A-F]{8}:(PEM routines):get_name:(no start line)/0906D06C:$1:PEM_read_bio:$2/;
 
-    # gnutls version variances
+    # GnuTLS version variances
     if (/TLS error on connection \(recv\): .* (Decode error|peer did not send any certificate)/)
       {
       my $prev = $_;
@@ -1512,8 +1575,10 @@ RESET_AFTER_EXTRA_LINE_READ:
       else
        { $_ = $prev; }
       }
-    # translate gnutls error into the openssl one
+    # translate GnuTLS error into the OpenSSL one
     s/ARC: AMS signing: privkey PEM-block import: \KThe requested data were not available.$/error:0906D06C:PEM routines:PEM_read_bio:no start line/;
+    # and then both into the OpenSSL 3.x one
+    s/ARC: AMS signing: privkey PEM-block import: error:\K[0-9A-F]{8}:PEM routines:PEM_read_bio:no start line$/1E08010C:DECODER routines::unsupported/;
 
     # DKIM timestamps
     if ( /(DKIM: d=.*) t=([0-9]*) x=([0-9]*) / )
@@ -1525,6 +1590,9 @@ RESET_AFTER_EXTRA_LINE_READ:
     s/signer: [^ ]* bits:\K 256/ 253/;
     s/public key too short:\K 256 bits/ 253 bits/;
 
+    # with GnuTLS we cannot log single bad ALPN.  So ignore the with-OpenSSL log line.
+    # next if /TLS ALPN (http) rejected$/;
+
     # port numbers
     s/(?:\[[^\]]*\]:|port )\K$parm_port_d/PORT_D/;
     s/(?:\[[^\]]*\]:|port )\K$parm_port_d2/PORT_D2/;
@@ -1544,7 +1612,7 @@ RESET_AFTER_EXTRA_LINE_READ:
     s/session: \K\((SSL_connect|gnutls_handshake)\): timed out/(tls lib connect fn): timed out/;
     s/TLS error on connection from .*\K\((SSL_accept|gnutls_handshake)\): timed out/(tls lib accept fn): timed out/;
     s/TLS error on connection from .*\K(SSL_accept: TCP connection closed by peer|\(gnutls_handshake\): The TLS connection was non-properly terminated.)/(tls lib accept fn): TCP connection closed by peer/;
-    s/TLS session: \K\(gnutls_handshake\): No supported application protocol could be negotiated/(SSL_connect): error: <<detail omitted>>/;
+    s/TLS session: \K\(gnutls_handshake\): rxd alert: No supported application protocol could be negotiated/(SSL_connect): error: <<detail omitted>>/;
     s/\(gnutls_handshake\): No common application protocol could be negotiated./(SSL_accept): error: <<detail omitted>>/;
     }
 
@@ -1796,13 +1864,13 @@ if (-e $sf_current)
 
     for (my $i = 0; $i < @munged; $i++)
       {
-      if ($munged[$i] =~ /^[-\d]{10}\s[:\d]{8}\s[-A-Za-z\d]{16}\s[-=*]>/)
+      if ($munged[$i] =~ /^[-\d]{10}\s[:\d]{8}(\.\d{3})?\s[-A-Za-z\d]{23}\s[-=*]>/)
         {
         my $j;
         for ($j = $i + 1; $j < @munged; $j++)
           {
           last if $munged[$j] !~
-            /^[-\d]{10}\s[:\d]{8}\s[-A-Za-z\d]{16}\s[-=*]>/;
+            /^[-\d]{10}\s[:\d]{8}(\.\d{3})?\s[-A-Za-z\d]{23}\s[-=*]>/;
           }
         @temp = splice(@munged, $i, $j - $i);
         @temp = sort(@temp);
@@ -1872,7 +1940,8 @@ return 2;
 # Usable files are:
 #  paniclog, rejectlog, mainlog, stdout, stderr, msglog, mail
 # Search strings starting with 's' do substitutions;
-# with '/' do line-skips.
+# with '/' do line-skips,
+# with 'R' run given code.
 # Triggered by a scriptfile line "munge <name>"
 ##################################################
 $munges =
@@ -1918,11 +1987,14 @@ $munges =
       'rejectlog' => 's/ X=TLS\S+ / X=TLS_proto_and_cipher /',
     },
 
-    'debug_pid' =>
-    { 'stderr' => 's/(^\s{0,4}|(?<=Process )|(?<=child ))\d+/ppppp/g' },
-
     'optional_dsn_info' =>
-    { 'mail' => '/^(X-(Remote-MTA-(smtp-greeting|helo-response)|Exim-Diagnostic|(body|message)-linecount):|Remote-MTA: X-ip;)/'
+    { 'mail' => 'Rif (/^(X-(Remote-MTA-(smtp-greeting|helo-response)|Exim-Diagnostic|(body|message)-linecount):|Remote-MTA: X-ip;)/) {
+                   while (1) {
+                     $_ = <IN>;
+                     next if /^ /;
+                     goto RESET_AFTER_EXTRA_LINE_READ;
+                   }
+                 }'
     },
 
     'optional_config' =>
@@ -2131,9 +2203,15 @@ if (! $msglog_skip)
     foreach $msglog (@msglogs)
       {
       next if ($msglog eq "." || $msglog eq ".." || $msglog eq "CVS");
+
       ($munged_msglog = $msglog) =~
         s/((?:[^\W_]{6}-){2}[^\W_]{2})
-          /new_value($1, "10Hm%s-0005vi-00", \$next_msgid)/egx;
+          /new_value($1, "10Hm%s-0005vi-00", \$next_msgid_old)/egx;
+
+      $munged_msglog =~
+        s/([^\W_]{6}-[^\W_]{11}-[^\W_]{4})
+          /new_value($1, "10Hm%s-000000005vi-0000", \$next_msgid)/egx;
+
       $yield = max($yield,  check_file("spool/msglog/$msglog", undef,
         "test-msglog-munged", "msglog/$testno.$munged_msglog", 0,
         $munge->{msglog}));
@@ -2245,10 +2323,11 @@ my($yield) = 1;
 
 our %ENV = map { $_ => $ENV{$_} } grep { /^(?:USER|SHELL|PATH|TERM|EXIM_TEST_.*)$/ } keys %ENV;
 
-if (/^(\d+)\s*$/)                # Handle unusual return code
+if (/^(\d+)\s*(?:([A-Z]+)=(\S+))?$/)                # Handle unusual return code
   {
   my($r) = $_[2];
   $$r = $1 << 8;
+  $ENV{$2} = $3 if (defined $2);
   $_ = <SCRIPT>;
   return 4 if !defined $_;       # Missing command
   $lineno++;
@@ -2448,6 +2527,17 @@ if (/^eximstats\s+(.*)/)
   }
 
 
+# The "exim_id_update" command runs exim_id_update on the current spool
+
+if (/^exim_id_update(\s+.*)?$/)
+  {
+  run_system("(sudo ./eximdir/exim_id_update" . ($1 || '') . " $parm_cwd/spool/input;" .
+    "echo exim_id_update exit code = \$?)" .
+    ">>test-stdout 2>>test-stderr");
+  return 1;
+  }
+
+
 # The "gnutls" command makes a copy of saved GnuTLS parameter data in the
 # spool directory, to save Exim from re-creating it each time.
 
@@ -2539,7 +2629,7 @@ if (/^sleep\s+(.*)$/)
 # Various Unix management commands are recognized
 
 if (/^(ln|ls|du|mkdir|mkfifo|touch|cp|cat)\s/ ||
-    /^sudo\s(rmdir|rm|mv|chown|chmod)\s/)
+    /^sudo\s(mkdir|rmdir|rm|mv|cp|chown|chmod)\s/)
   {
   run_system("$_ >>test-stdout 2>>test-stderr");
   return 1;
@@ -2941,6 +3031,245 @@ return $yield;            # Ran command and waited
 
 
 
+###############################################################################
+###############################################################################
+
+##################################################
+#    Check for SpamAssassin and ClamAV           #
+##################################################
+
+# These are crude tests. If they aren't good enough, we'll have to improve
+# them, for example by actually passing a message through spamc or clamscan.
+
+sub check_running_spamassassin
+{
+my $sock = new FileHandle;
+
+if (system("spamc -h 2>/dev/null >/dev/null") == 0)
+  {
+  print "The spamc command works:\n";
+
+  # 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 protocol that
+  # clamd does, but it does respond to errors in an informative manner,
+  # so use that.
+
+  my($sint,$sport) = ('127.0.0.1',783);
+  eval
+    {
+    my $sin = sockaddr_in($sport, inet_aton($sint))
+       or die "** Failed packing $sint:$sport\n";
+    socket($sock, PF_INET, SOCK_STREAM, getprotobyname('tcp'))
+       or die "** Unable to open socket $sint:$sport\n";
+
+    local $SIG{ALRM} =
+       sub { die "** Timeout while connecting to socket $sint:$sport\n"; };
+    alarm(5);
+    connect($sock, $sin)
+       or die "** Unable to connect to socket $sint:$sport\n";
+    alarm(0);
+
+    select((select($sock), $| = 1)[0]);
+    print $sock "bad command\r\n";
+
+    $SIG{ALRM} =
+       sub { die "** Timeout while reading from socket $sint:$sport\n"; };
+    alarm(10);
+    my $res = <$sock>;
+    alarm(0);
+
+    $res =~ m|^SPAMD/|
+       or die "** Did not get SPAMD from socket $sint:$sport. "
+             ."It said: $res\n";
+    };
+  alarm(0);
+  if($@)
+    {
+    print "  $@";
+    print "  Assume SpamAssassin (spamd) is not running\n";
+    }
+  else
+    {
+    $parm_running{SpamAssassin} = ' ';
+    print "  SpamAssassin (spamd) seems to be running\n";
+    }
+  }
+else
+  {
+  print "The spamc command failed: assume SpamAssassin (spamd) is not running\n";
+  }
+}
+
+sub check_running_clamav
+{
+my $sock;
+
+# For ClamAV, we need to find the clamd socket for use in the Exim
+# configuration. Search for the clamd configuration file.
+
+if (system("clamscan -h 2>/dev/null >/dev/null") == 0)
+  {
+  my($f, $clamconf, $test_prefix);
+
+  print "The clamscan command works";
+
+  $test_prefix = $ENV{EXIM_TEST_PREFIX};
+  $test_prefix = '' if !defined $test_prefix;
+
+  foreach $f ("$test_prefix/etc/clamd.conf",
+             "$test_prefix/usr/local/etc/clamd.conf",
+             "$test_prefix/etc/clamav/clamd.conf", '')
+    {
+    if (-e $f)
+      {
+      $clamconf = $f;
+      last;
+      }
+    }
+
+  # Read the ClamAV configuration file and find the socket interface.
+
+  if ($clamconf ne '')
+    {
+    my $socket_domain;
+    open(IN, "$clamconf") || die "\n** Unable to open $clamconf: $!\n";
+    while (<IN>)
+      {
+      if (/^LocalSocket\s+(.*)/)
+       {
+       $parm_clamsocket = $1;
+       $socket_domain = AF_UNIX;
+       last;
+       }
+      if (/^TCPSocket\s+(\d+)/)
+       {
+       if (defined $parm_clamsocket)
+         {
+         $parm_clamsocket .= " $1";
+         $socket_domain = AF_INET;
+         last;
+         }
+       else
+         {
+         $parm_clamsocket = " $1";
+         }
+       }
+      elsif (/^TCPAddr\s+(\S+)/)
+       {
+       if (defined $parm_clamsocket)
+         {
+         $parm_clamsocket = $1 . $parm_clamsocket;
+         $socket_domain = AF_INET;
+         last;
+         }
+       else
+         {
+         $parm_clamsocket = $1;
+         }
+       }
+      }
+    close(IN);
+
+    if (defined $socket_domain)
+      {
+      print ":\n  The clamd socket is $parm_clamsocket\n";
+      # This test for an active ClamAV is courtesy of Daniel Tiefnig.
+      eval
+       {
+       my $socket;
+       if ($socket_domain == AF_UNIX)
+         {
+         $socket = sockaddr_un($parm_clamsocket) or die "** Failed packing '$parm_clamsocket'\n";
+         }
+       elsif ($socket_domain == AF_INET)
+         {
+         my ($ca_host, $ca_port) = split(/\s+/,$parm_clamsocket);
+         my $ca_hostent = gethostbyname($ca_host) or die "** Failed to get raw address for host '$ca_host'\n";
+         $socket = sockaddr_in($ca_port, $ca_hostent) or die "** Failed packing '$parm_clamsocket'\n";
+         }
+       else
+         {
+         die "** Unknown socket domain '$socket_domain' (should not happen)\n";
+         }
+       socket($sock, $socket_domain, SOCK_STREAM, 0) or die "** Unable to open socket '$parm_clamsocket'\n";
+       local $SIG{ALRM} = sub { die "** Timeout while connecting to socket '$parm_clamsocket'\n"; };
+       alarm(5);
+       connect($sock, $socket) or die "** Unable to connect to socket '$parm_clamsocket'\n";
+       alarm(0);
+
+       my $ofh = select $sock; $| = 1; select $ofh;
+       print $sock "PING\n";
+
+       $SIG{ALRM} = sub { die "** Timeout while reading from socket '$parm_clamsocket'\n"; };
+       alarm(10);
+       my $res = <$sock>;
+       alarm(0);
+
+       $res =~ /PONG/ or die "** Did not get PONG from socket '$parm_clamsocket'. It said: $res\n";
+       };
+      alarm(0);
+
+      if($@)
+       {
+       print "  $@";
+       print "  Assume ClamAV is not running\n";
+       }
+      else
+       {
+       $parm_running{ClamAV} = ' ';
+       print "  ClamAV seems to be running\n";
+       }
+      }
+    else
+      {
+      print ", but the socket for clamd could not be determined\n";
+      print "Assume ClamAV is not running\n";
+      }
+    }
+
+  else
+    {
+    print ", but I can't find a configuration for clamd\n";
+    print "Assume ClamAV is not running\n";
+    }
+  }
+}
+
+
+sub check_running_redis
+{
+if (defined $parm_lookups{redis})
+  {
+  if (system("redis-server -v 2>/dev/null >/dev/null") == 0)
+    {
+    print "The redis-server command works\n";
+    $parm_running{redis} = ' ';
+    }
+  else
+    {
+    print "The redis-server command failed: assume Redis not installed\n";
+    }
+  }
+}
+
+sub check_running_dovecot
+{
+system('dovecot --version >/dev/null');
+if ($? == 0)
+  {
+  print "Dovecot appears to be available\n";
+  $parm_running{dovecot} = ' ';
+  }
+else
+  {
+  print "Dovecot not found\n";
+  }
+}
+
+
+
 ###############################################################################
 ###############################################################################
 
@@ -3293,220 +3622,15 @@ print "-" x 78, "\n";
 
 unlink("$parm_cwd/test-config");
 
-##################################################
-#    Check for SpamAssassin and ClamAV           #
-##################################################
 
-# These are crude tests. If they aren't good enough, we'll have to improve
-# them, for example by actually passing a message through spamc or clamscan.
 
 if (defined $parm_support{Content_Scanning})
   {
-  my $sock = new FileHandle;
-
-  if (system("spamc -h 2>/dev/null >/dev/null") == 0)
-    {
-    print "The spamc command works:\n";
-
-    # 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 protocol that
-    # clamd does, but it does respond to errors in an informative manner,
-    # so use that.
-
-    my($sint,$sport) = ('127.0.0.1',783);
-    eval
-      {
-      my $sin = sockaddr_in($sport, inet_aton($sint))
-          or die "** Failed packing $sint:$sport\n";
-      socket($sock, PF_INET, SOCK_STREAM, getprotobyname('tcp'))
-          or die "** Unable to open socket $sint:$sport\n";
-
-      local $SIG{ALRM} =
-          sub { die "** Timeout while connecting to socket $sint:$sport\n"; };
-      alarm(5);
-      connect($sock, $sin)
-          or die "** Unable to connect to socket $sint:$sport\n";
-      alarm(0);
-
-      select((select($sock), $| = 1)[0]);
-      print $sock "bad command\r\n";
-
-      $SIG{ALRM} =
-          sub { die "** Timeout while reading from socket $sint:$sport\n"; };
-      alarm(10);
-      my $res = <$sock>;
-      alarm(0);
-
-      $res =~ m|^SPAMD/|
-          or die "** Did not get SPAMD from socket $sint:$sport. "
-                ."It said: $res\n";
-      };
-    alarm(0);
-    if($@)
-      {
-      print "  $@";
-      print "  Assume SpamAssassin (spamd) is not running\n";
-      }
-    else
-      {
-      $parm_running{SpamAssassin} = ' ';
-      print "  SpamAssassin (spamd) seems to be running\n";
-      }
-    }
-  else
-    {
-    print "The spamc command failed: assume SpamAssassin (spamd) is not running\n";
-    }
-
-  # For ClamAV, we need to find the clamd socket for use in the Exim
-  # configuration. Search for the clamd configuration file.
-
-  if (system("clamscan -h 2>/dev/null >/dev/null") == 0)
-    {
-    my($f, $clamconf, $test_prefix);
-
-    print "The clamscan command works";
-
-    $test_prefix = $ENV{EXIM_TEST_PREFIX};
-    $test_prefix = '' if !defined $test_prefix;
-
-    foreach $f ("$test_prefix/etc/clamd.conf",
-                "$test_prefix/usr/local/etc/clamd.conf",
-                "$test_prefix/etc/clamav/clamd.conf", '')
-      {
-      if (-e $f)
-        {
-        $clamconf = $f;
-        last;
-        }
-      }
-
-    # Read the ClamAV configuration file and find the socket interface.
-
-    if ($clamconf ne '')
-      {
-      my $socket_domain;
-      open(IN, "$clamconf") || die "\n** Unable to open $clamconf: $!\n";
-      while (<IN>)
-        {
-        if (/^LocalSocket\s+(.*)/)
-          {
-          $parm_clamsocket = $1;
-          $socket_domain = AF_UNIX;
-          last;
-          }
-        if (/^TCPSocket\s+(\d+)/)
-          {
-          if (defined $parm_clamsocket)
-            {
-            $parm_clamsocket .= " $1";
-            $socket_domain = AF_INET;
-            last;
-            }
-          else
-            {
-            $parm_clamsocket = " $1";
-            }
-          }
-        elsif (/^TCPAddr\s+(\S+)/)
-          {
-          if (defined $parm_clamsocket)
-            {
-            $parm_clamsocket = $1 . $parm_clamsocket;
-            $socket_domain = AF_INET;
-            last;
-            }
-          else
-            {
-            $parm_clamsocket = $1;
-            }
-          }
-        }
-      close(IN);
-
-      if (defined $socket_domain)
-        {
-        print ":\n  The clamd socket is $parm_clamsocket\n";
-        # This test for an active ClamAV is courtesy of Daniel Tiefnig.
-        eval
-          {
-          my $socket;
-          if ($socket_domain == AF_UNIX)
-            {
-            $socket = sockaddr_un($parm_clamsocket) or die "** Failed packing '$parm_clamsocket'\n";
-            }
-          elsif ($socket_domain == AF_INET)
-            {
-            my ($ca_host, $ca_port) = split(/\s+/,$parm_clamsocket);
-            my $ca_hostent = gethostbyname($ca_host) or die "** Failed to get raw address for host '$ca_host'\n";
-            $socket = sockaddr_in($ca_port, $ca_hostent) or die "** Failed packing '$parm_clamsocket'\n";
-            }
-          else
-            {
-            die "** Unknown socket domain '$socket_domain' (should not happen)\n";
-            }
-          socket($sock, $socket_domain, SOCK_STREAM, 0) or die "** Unable to open socket '$parm_clamsocket'\n";
-          local $SIG{ALRM} = sub { die "** Timeout while connecting to socket '$parm_clamsocket'\n"; };
-          alarm(5);
-          connect($sock, $socket) or die "** Unable to connect to socket '$parm_clamsocket'\n";
-          alarm(0);
-
-          my $ofh = select $sock; $| = 1; select $ofh;
-          print $sock "PING\n";
-
-          $SIG{ALRM} = sub { die "** Timeout while reading from socket '$parm_clamsocket'\n"; };
-          alarm(10);
-          my $res = <$sock>;
-          alarm(0);
-
-          $res =~ /PONG/ or die "** Did not get PONG from socket '$parm_clamsocket'. It said: $res\n";
-          };
-        alarm(0);
-
-        if($@)
-          {
-          print "  $@";
-          print "  Assume ClamAV is not running\n";
-          }
-        else
-          {
-          $parm_running{ClamAV} = ' ';
-          print "  ClamAV seems to be running\n";
-          }
-        }
-      else
-        {
-        print ", but the socket for clamd could not be determined\n";
-        print "Assume ClamAV is not running\n";
-        }
-      }
-
-    else
-      {
-      print ", but I can't find a configuration for clamd\n";
-      print "Assume ClamAV is not running\n";
-      }
-    }
-  }
-
-
-##################################################
-#       Check for redis                          #
-##################################################
-if (defined $parm_lookups{redis})
-  {
-  if (system("redis-server -v 2>/dev/null >/dev/null") == 0)
-    {
-    print "The redis-server command works\n";
-    $parm_running{redis} = ' ';
-    }
-  else
-    {
-    print "The redis-server command failed: assume Redis not installed\n";
-    }
+  check_running_spamassassin();
+  check_running_clamav();
   }
+check_running_redis();
+check_running_dovecot();
 
 ##################################################
 #         Test for the basic requirements        #
@@ -3818,7 +3942,7 @@ if (defined $parm_lookups{dbm} && not cp("$parm_exim_dir/exim_dbmbuild", "eximdi
   $dbm_build_deleted = 1;
   }
 
-foreach my $tool (qw(exim_dumpdb exim_lock exinext exigrep eximstats exiqgrep)) {
+foreach my $tool (qw(exim_dumpdb exim_lock exinext exigrep eximstats exiqgrep exim_msgdate exim_id_update)) {
   cp("$parm_exim_dir/$tool" => "eximdir/$tool")
     or tests_exit(-1, "Failed to make a copy of $tool: $!");
 }
@@ -3826,7 +3950,7 @@ foreach my $tool (qw(exim_dumpdb exim_lock exinext exigrep eximstats exiqgrep))
 # Collect some version information
 print '-' x 78, "\n";
 print "Perl version for runtest: $]\n";
-foreach (map { "./eximdir/$_" } qw(exigrep exinext eximstats exiqgrep)) {
+foreach (map { "./eximdir/$_" } qw(exigrep exinext eximstats exiqgrep exim_msgdate)) {
   # fold (or unfold?) multiline output into a one-liner
   print join(', ', map { chomp; $_ } `$_ --version`), "\n";
 }
@@ -3957,10 +4081,10 @@ DIR: for (my $i = 0; $i < @test_dirs; $i++)
         {
         if (!defined $parm_malware{$1}) { $wantthis = 0; last; }
         }
-      elsif (/^feature (.*)$/)
+      elsif (/^(not )?feature (.*)$/)
         {
        # move to a subroutine?
-       my $eximinfo = "$parm_exim -C $parm_cwd/test-config -DDIR=$parm_cwd -bP macro $1";
+       my $eximinfo = "$parm_exim -C $parm_cwd/test-config -DDIR=$parm_cwd -bP macro $2";
 
        open (IN, "$parm_cwd/confs/0000") ||
          tests_exit(-1, "Couldn't open $parm_cwd/confs/0000: $!\n");
@@ -3975,10 +4099,10 @@ DIR: for (my $i = 0; $i < @test_dirs; $i++)
        close(OUT);
 
        system($eximinfo . " >/dev/null 2>&1");
-       if ($? != 0) {
-         unlink("$parm_cwd/test-config");
+       if (!defined $1 && $? != 0 || defined $1 && $? == 0) {
          $wantthis = 0;
-         $_ = "feature $1";
+         unlink("$parm_cwd/test-config");
+         $_ = $1 || "" . "feature $2";
          last;
        }
        unlink("$parm_cwd/test-config");
@@ -4276,11 +4400,13 @@ foreach $test (@test_list)
   # set up the initial sequence strings.
 
   undef %cache;
+  $next_msgid_old = "aX";
   $next_msgid = "aX";
   $next_pid = 1234;
   $next_port = 1111;
   $message_skip = 0;
   $msglog_skip = 0;
+  $munge_skip = 0;
   $stderr_skip = 0;
   $stdout_skip = 0;
   $rmfiltertest = 0;
@@ -4300,6 +4426,7 @@ foreach $test (@test_list)
     {
     if (/^no_message_check/) { $message_skip = 1; next; }
     if (/^no_msglog_check/)  { $msglog_skip = 1; next; }
+    if (/^no_munge/)         { $munge_skip = 1; next; }
     if (/^no_stderr_check/)  { $stderr_skip = 1; next; }
     if (/^no_stdout_check/)  { $stdout_skip = 1; next; }
     if (/^rmfiltertest/)     { $rmfiltertest = 1; next; }
@@ -4334,6 +4461,7 @@ foreach $test (@test_list)
       # set above, but doesn't hurt to leave them here.
       if (/^no_message_check/) { $message_skip = 1; next; }
       if (/^no_msglog_check/)  { $msglog_skip = 1; next; }
+      if (/^no_munge/)         { $munge_skip = 1; next; }
       if (/^no_stderr_check/)  { $stderr_skip = 1; next; }
       if (/^no_stdout_check/)  { $stdout_skip = 1; next; }
       if (/^rmfiltertest/)     { $rmfiltertest = 1; next; }