Logging: add I= element to transport-defer lines. Bug 2675
[exim.git] / src / src / deliver.c
index 72751c2dc5d415404356df594df10f61fbddc1e6..4e6f08f898b91173a93e1a3480579253e173b4b5 100644 (file)
@@ -3,6 +3,7 @@
 *************************************************/
 
 /* Copyright (c) University of Cambridge 1995 - 2018 */
+/* Copyright (c) The Exim Maintainers 2020 */
 /* See the file NOTICE for conditions of use and distribution. */
 
 /* The main code for delivering a message. */
@@ -220,7 +221,9 @@ if (!addr->next)
 
   deliver_localpart = addr->local_part;
   deliver_localpart_prefix = addr->prefix;
+  deliver_localpart_prefix_v = addr->prefix_v;
   deliver_localpart_suffix = addr->suffix;
+  deliver_localpart_suffix_v = addr->suffix_v;
 
   for (addr_orig = addr; addr_orig->parent; addr_orig = addr_orig->parent) ;
   deliver_domain_orig = addr_orig->domain;
@@ -260,7 +263,9 @@ if (!addr->next)
       else if (deliver_localpart[0] == '|') address_pipe = addr->local_part;
       deliver_localpart = addr->parent->local_part;
       deliver_localpart_prefix = addr->parent->prefix;
+      deliver_localpart_prefix_v = addr->parent->prefix_v;
       deliver_localpart_suffix = addr->parent->suffix;
+      deliver_localpart_suffix_v = addr->parent->suffix_v;
       }
     }
 
@@ -429,7 +434,7 @@ for (address_item * addr2 = addr->next; addr2; addr2 = addr2->next)
   addr2->transport_return = addr->transport_return;
   addr2->basic_errno =     addr->basic_errno;
   addr2->more_errno =      addr->more_errno;
-  addr2->delivery_usec =    addr->delivery_usec;
+  addr2->delivery_time =    addr->delivery_time;
   addr2->special_action =   addr->special_action;
   addr2->message =         addr->message;
   addr2->user_message =            addr->user_message;
@@ -455,6 +460,9 @@ TRUE if the lists refer to the same hosts in the same order, except that
 This enables Exim to use a single SMTP transaction for sending to two entirely
 different domains that happen to end up pointing at the same hosts.
 
+We do not try to batch up different A-record host names that refer to the
+same IP.
+
 Arguments:
   one       points to the first host list
   two       points to the second host list
@@ -812,7 +820,7 @@ d_tlslog(gstring * g, address_item * addr)
 if (LOGGING(tls_cipher) && addr->cipher)
   {
   g = string_append(g, 2, US" X=", addr->cipher);
-#ifdef EXPERIMENTAL_TLS_RESUME
+#ifndef DISABLE_TLS_RESUME
   if (LOGGING(tls_resumption) && testflag(addr, af_tls_resume))
     g = string_catn(g, US"*", 1);
 #endif
@@ -1092,42 +1100,6 @@ return g;
 
 
 
-void
-timesince(struct timeval * diff, struct timeval * then)
-{
-gettimeofday(diff, NULL);
-diff->tv_sec -= then->tv_sec;
-if ((diff->tv_usec -= then->tv_usec) < 0)
-  {
-  diff->tv_sec--;
-  diff->tv_usec += 1000*1000;
-  }
-}
-
-
-
-uschar *
-string_timediff(struct timeval * diff)
-{
-static uschar buf[sizeof("0.000s")];
-
-if (diff->tv_sec >= 5 || !LOGGING(millisec))
-  return readconf_printtime((int)diff->tv_sec);
-
-sprintf(CS buf, "%u.%03us", (uint)diff->tv_sec, (uint)diff->tv_usec/1000);
-return buf;
-}
-
-
-uschar *
-string_timesince(struct timeval * then)
-{
-struct timeval diff;
-
-timesince(&diff, then);
-return string_timediff(&diff);
-}
-
 /******************************************************************************/
 
 
@@ -1180,7 +1152,7 @@ if (LOGGING(sender_on_delivery) || msg)
 if (*queue_name)
   g = string_append(g, 2, US" Q=", queue_name);
 
-#ifdef EXPERIMENTAL_SRS
+#ifdef EXPERIMENTAL_SRS_ALT
 if(addr->prop.srs_sender)
   g = string_append(g, 3, US" SRS=<", addr->prop.srs_sender, US">");
 #endif
@@ -1223,7 +1195,7 @@ else
   if (addr->host_used)
     {
     g = d_hostlog(g, addr);
-    if (continue_sequence > 1)
+    if (continue_sequence > 1)         /*XXX this is wrong for a dropped proxyconn.  Would have to pass back from transport */
       g = string_catn(g, US"*", 1);
 
 #ifndef DISABLE_EVENT
@@ -1257,7 +1229,7 @@ else
     {
     if (testflag(addr, af_pipelining))
       g = string_catn(g, US" L", 2);
-#ifdef SUPPORT_PIPE_CONNECT
+#ifndef DISABLE_PIPE_CONNECT
     if (testflag(addr, af_early_pipe))
       g = string_catn(g, US"*", 1);
 #endif
@@ -1300,10 +1272,7 @@ if (LOGGING(queue_time))
     string_timesince(&received_time));
 
 if (LOGGING(deliver_time))
-  {
-  struct timeval diff = {.tv_sec = addr->more_errno, .tv_usec = addr->delivery_usec};
-  g = string_append(g, 2, US" DT=", string_timediff(&diff));
-  }
+  g = string_append(g, 2, US" DT=", string_timediff(&addr->delivery_time));
 
 /* string_cat() always leaves room for the terminator. Release the
 store we used to build the line after writing it. */
@@ -1356,20 +1325,13 @@ else if (driver_kind)
 g = string_fmt_append(g, " defer (%d)", addr->basic_errno);
 
 if (addr->basic_errno > 0)
-  g = string_append(g, 2, US": ",
-    US strerror(addr->basic_errno));
+  g = string_append(g, 2, US": ", US strerror(addr->basic_errno));
 
 if (addr->host_used)
-  {
-  g = string_append(g, 5,
-                   US" H=", addr->host_used->name,
-                   US" [",  addr->host_used->address, US"]");
-  if (LOGGING(outgoing_port))
-    {
-    int port = addr->host_used->port;
-    g = string_fmt_append(g, ":%d", port == PORT_NONE ? 25 : port);
-    }
-  }
+  g = d_hostlog(g, addr);
+
+if (LOGGING(deliver_time))
+  g = string_append(g, 2, US" DT=", string_timediff(&addr->delivery_time));
 
 if (addr->message)
   g = string_append(g, 2, US": ", addr->message);
@@ -1450,6 +1412,9 @@ if (addr->basic_errno > 0)
 if (addr->message)
   g = string_append(g, 2, US": ", addr->message);
 
+if (LOGGING(deliver_time))
+  g = string_append(g, 2, US" DT=", string_timediff(&addr->delivery_time));
+
 (void) string_from_gstring(g);
 
 /* Do the logging. For the message log, "routing failed" for those cases,
@@ -1646,6 +1611,7 @@ if (result == OK)
   tls_out.peercert = addr->peercert;
   addr->peercert = NULL;
 
+  tls_out.ver = addr->tlsver;
   tls_out.cipher = addr->cipher;
   tls_out.peerdn = addr->peerdn;
   tls_out.ocsp = addr->ocsp;
@@ -1659,6 +1625,7 @@ if (result == OK)
 #ifndef DISABLE_TLS
   tls_free_cert(&tls_out.ourcert);
   tls_free_cert(&tls_out.peercert);
+  tls_out.ver = NULL;
   tls_out.cipher = NULL;
   tls_out.peerdn = NULL;
   tls_out.ocsp = OCSP_NOT_REQ;
@@ -2151,7 +2118,7 @@ Arguments:
 Returns:     nothing
 */
 
-static void
+void
 deliver_local(address_item *addr, BOOL shadowing)
 {
 BOOL use_initgroups;
@@ -2169,7 +2136,7 @@ has its own return path setting, expand it and replace the existing value. */
 
 if(addr->prop.errors_address)
   return_path = addr->prop.errors_address;
-#ifdef EXPERIMENTAL_SRS
+#ifdef EXPERIMENTAL_SRS_ALT
 else if (addr->prop.srs_sender)
   return_path = addr->prop.srs_sender;
 #endif
@@ -2178,18 +2145,16 @@ else
 
 if (tp->return_path)
   {
-  uschar *new_return_path = expand_string(tp->return_path);
-  if (!new_return_path)
-    {
-    if (!f.expand_string_forcedfail)
-      {
-      common_error(TRUE, addr, ERRNO_EXPANDFAIL,
-        US"Failed to expand return path \"%s\" in %s transport: %s",
-        tp->return_path, tp->name, expand_string_message);
-      return;
-      }
+  uschar * new_return_path = expand_string(tp->return_path);
+  if (new_return_path)
+    return_path = new_return_path;
+  else if (!f.expand_string_forcedfail)
+    {
+    common_error(TRUE, addr, ERRNO_EXPANDFAIL,
+      US"Failed to expand return path \"%s\" in %s transport: %s",
+      tp->return_path, tp->name, expand_string_message);
+    return;
     }
-  else return_path = new_return_path;
   }
 
 /* For local deliveries, one at a time, the value used for logging can just be
@@ -2295,7 +2260,7 @@ a clean slate and doesn't interfere with the parent process. */
 
 search_tidyup();
 
-if ((pid = fork()) == 0)
+if ((pid = exim_fork(US"delivery-local")) == 0)
   {
   BOOL replicate = TRUE;
 
@@ -2441,7 +2406,7 @@ if ((pid = fork()) == 0)
       || (ret = write(pfd[pipe_write], &addr2->flags, sizeof(addr2->flags))) != sizeof(addr2->flags)
       || (ret = write(pfd[pipe_write], &addr2->basic_errno,    sizeof(int))) != sizeof(int)
       || (ret = write(pfd[pipe_write], &addr2->more_errno,     sizeof(int))) != sizeof(int)
-      || (ret = write(pfd[pipe_write], &addr2->delivery_usec,  sizeof(int))) != sizeof(int)
+      || (ret = write(pfd[pipe_write], &addr2->delivery_time,  sizeof(struct timeval))) != sizeof(struct timeval)
       || (ret = write(pfd[pipe_write], &addr2->special_action, sizeof(int))) != sizeof(int)
       || (ret = write(pfd[pipe_write], &addr2->transport,
         sizeof(transport_instance *))) != sizeof(transport_instance *)
@@ -2509,7 +2474,7 @@ for (addr2 = addr; addr2; addr2 = addr2->next)
     len = read(pfd[pipe_read], &addr2->flags, sizeof(addr2->flags));
     len = read(pfd[pipe_read], &addr2->basic_errno,    sizeof(int));
     len = read(pfd[pipe_read], &addr2->more_errno,     sizeof(int));
-    len = read(pfd[pipe_read], &addr2->delivery_usec,  sizeof(int));
+    len = read(pfd[pipe_read], &addr2->delivery_time,  sizeof(struct timeval));
     len = read(pfd[pipe_read], &addr2->special_action, sizeof(int));
     len = read(pfd[pipe_read], &addr2->transport,
       sizeof(transport_instance *));
@@ -2579,7 +2544,7 @@ if (!shadowing)
       /* In the test harness, wait just a bit to let the subprocess finish off
       any debug output etc first. */
 
-      if (f.running_in_test_harness) millisleep(300);
+      testharness_pause_ms(300);
 
       DEBUG(D_deliver) debug_printf("journalling %s", big_buffer);
       len = Ustrlen(big_buffer);
@@ -2642,7 +2607,7 @@ if (addr->special_action == SPECIAL_WARN && addr->transport->warn_message)
       "message for %s transport): %s", addr->transport->warn_message,
       addr->transport->name, expand_string_message);
 
-  else if ((pid = child_open_exim(&fd)) > 0)
+  else if ((pid = child_open_exim(&fd, US"tpt-warning-message")) > 0)
     {
     FILE *f = fdopen(fd, "wb");
     if (errors_reply_to && !contains_header(US"Reply-To", warn_message))
@@ -3163,11 +3128,7 @@ while (addr_local)
 
     /* Done with this address */
 
-    if (result == OK)
-      {
-      addr2->more_errno = deliver_time.tv_sec;
-      addr2->delivery_usec = deliver_time.tv_usec;
-      }
+    addr2->delivery_time = deliver_time;
     post_process_one(addr2, result, logflags, EXIM_DTYPE_TRANSPORT, logchar);
 
     /* If a pipe delivery generated text to be sent back, the result may be
@@ -3516,11 +3477,13 @@ while (!done)
       switch (*subid)
        {
        case '1':
-         addr->cipher = NULL;
-         addr->peerdn = NULL;
+         addr->tlsver = addr->cipher = addr->peerdn = NULL;
 
          if (*ptr)
+           {
            addr->cipher = string_copy(ptr);
+           addr->tlsver = string_copyn(ptr, Ustrchr(ptr, ':') - ptr);
+           }
          while (*ptr++);
          if (*ptr)
            addr->peerdn = string_copy(ptr);
@@ -3569,7 +3532,7 @@ while (!done)
     case 'L':
       switch (*subid)
        {
-#ifdef SUPPORT_PIPE_CONNECT
+#ifndef DISABLE_PIPE_CONNECT
        case 2: setflag(addr, af_early_pipe);   /*FALLTHROUGH*/
 #endif
        case 1: setflag(addr, af_pipelining); break;
@@ -3639,8 +3602,8 @@ while (!done)
          ptr += sizeof(addr->basic_errno);
          memcpy(&addr->more_errno, ptr, sizeof(addr->more_errno));
          ptr += sizeof(addr->more_errno);
-         memcpy(&addr->delivery_usec, ptr, sizeof(addr->delivery_usec));
-         ptr += sizeof(addr->delivery_usec);
+         memcpy(&addr->delivery_time, ptr, sizeof(addr->delivery_time));
+         ptr += sizeof(addr->delivery_time);
          memcpy(&addr->flags, ptr, sizeof(addr->flags));
          ptr += sizeof(addr->flags);
          addr->message = *ptr ? string_copy(ptr) : NULL;
@@ -4300,6 +4263,10 @@ for (int delivery_count = 0; addr_remote; delivery_count++)
       }
     }
 
+/*XXX need to defeat this when DANE is used - but we don't know that yet.
+So look out for the place it gets used.
+*/
+
   /* Get the flag which specifies whether the transport can handle different
   domains that nevertheless resolve to the same set of hosts. If it needs
   expanding, get variables set: $address_data, $domain_data, $localpart_data,
@@ -4378,6 +4345,11 @@ for (int delivery_count = 0; addr_remote; delivery_count++)
   /************************************************************************/
 
 
+/*XXX don't know yet if DANE will be used.  So tpt will have to
+check at the point if gets next addr from list, and skip/defer any
+nonmatch domains
+*/
+
   /* Pick off all addresses which have the same transport, errors address,
   destination, and extra headers. In some cases they point to the same host
   list, but we also need to check for identical host lists generated from
@@ -4457,7 +4429,7 @@ for (int delivery_count = 0; addr_remote; delivery_count++)
 
   if(addr->prop.errors_address)
     return_path = addr->prop.errors_address;
-#ifdef EXPERIMENTAL_SRS
+#ifdef EXPERIMENTAL_SRS_ALT
   else if(addr->prop.srs_sender)
     return_path = addr->prop.srs_sender;
 #endif
@@ -4524,6 +4496,7 @@ for (int delivery_count = 0; addr_remote; delivery_count++)
   if (continue_transport)
     {
     BOOL ok = Ustrcmp(continue_transport, tp->name) == 0;
+/*XXX do we need to check for a DANEd conn vs. a change of domain? */
 
     /* If the transport is about to override the host list do not check
     it here but take the cost of running the transport process to discover
@@ -4675,7 +4648,7 @@ all pipes, so I do not see a reason to use non-blocking IO here
 
   search_tidyup();
 
-  if ((pid = fork()) == 0)
+  if ((pid = exim_fork(US"transport")) == 0)
     {
     int fd = pfd[pipe_write];
     host_item *h;
@@ -4689,10 +4662,7 @@ all pipes, so I do not see a reason to use non-blocking IO here
     /* Show pids on debug output if parallelism possible */
 
     if (parmax > 1 && (parcount > 0 || addr_remote))
-      {
       DEBUG(D_any|D_v) debug_selector |= D_pid;
-      DEBUG(D_deliver) debug_printf("Remote delivery process started\n");
-      }
 
     /* Reset the random number generator, so different processes don't all
     have the same sequence. In the test harness we want different, but
@@ -4804,7 +4774,7 @@ all pipes, so I do not see a reason to use non-blocking IO here
 #ifdef SUPPORT_DANE
       if (tls_out.dane_verified)        setflag(addr, af_dane_verified);
 #endif
-# ifdef EXPERIMENTAL_TLS_RESUME
+# ifndef DISABLE_TLS_RESUME
       if (tls_out.resumption & RESUME_USED) setflag(addr, af_tls_resume);
 # endif
 
@@ -4876,7 +4846,7 @@ all pipes, so I do not see a reason to use non-blocking IO here
 #endif
 
       if (testflag(addr, af_pipelining))
-#ifdef SUPPORT_PIPE_CONNECT
+#ifndef DISABLE_PIPE_CONNECT
        if (testflag(addr, af_early_pipe))
          rmt_dlv_checked_write(fd, 'L', '2', NULL, 0);
        else
@@ -4956,8 +4926,8 @@ all pipes, so I do not see a reason to use non-blocking IO here
       ptr += sizeof(addr->basic_errno);
       memcpy(ptr, &addr->more_errno, sizeof(addr->more_errno));
       ptr += sizeof(addr->more_errno);
-      memcpy(ptr, &addr->delivery_usec, sizeof(addr->delivery_usec));
-      ptr += sizeof(addr->delivery_usec);
+      memcpy(ptr, &addr->delivery_time, sizeof(addr->delivery_time));
+      ptr += sizeof(addr->delivery_time);
       memcpy(ptr, &addr->flags, sizeof(addr->flags));
       ptr += sizeof(addr->flags);
 
@@ -5060,9 +5030,10 @@ all pipes, so I do not see a reason to use non-blocking IO here
 
   /* Otherwise, if we are running in the test harness, wait a bit, to let the
   newly created process get going before we create another process. This should
-  ensure repeatability in the tests. We only need to wait a tad. */
+  ensure repeatability in the tests. Wait long enough for most cases to complete
+  the transport. */
 
-  else if (f.running_in_test_harness) millisleep(500);
+  else testharness_pause_ms(600);
 
   continue;
 
@@ -5410,7 +5381,8 @@ Returns:       nothing
 static void
 print_dsn_diagnostic_code(const address_item *addr, FILE *f)
 {
-uschar *s = testflag(addr, af_pass_message) ? addr->message : NULL;
+uschar * s = testflag(addr, af_pass_message) ? addr->message : NULL;
+unsigned cnt;
 
 /* af_pass_message and addr->message set ? print remote host answer */
 if (s)
@@ -5422,19 +5394,32 @@ if (s)
   if (!(s = Ustrstr(addr->message, ": ")))
     return;                            /* not found, bail out */
   s += 2;  /* skip ": " */
-  fprintf(f, "Diagnostic-Code: smtp; ");
+  cnt = fprintf(f, "Diagnostic-Code: smtp; ");
   }
 /* no message available. do nothing */
 else return;
 
 while (*s)
+  {
+  if (cnt > 950)       /* RFC line length limit: 998 */
+    {
+    DEBUG(D_deliver) debug_printf("print_dsn_diagnostic_code() truncated line\n");
+    fputs("[truncated]", f);
+    break;
+    }
+
   if (*s == '\\' && s[1] == 'n')
     {
     fputs("\n ", f);    /* as defined in RFC 3461 */
     s += 2;
+    cnt += 2;
     }
   else
+    {
     fputc(*s++, f);
+    cnt++;
+    }
+  }
 
 fputc('\n', f);
 }
@@ -5509,6 +5494,48 @@ fprintf(f, "Action: %s\n"
 }
 
 
+
+/* When running in the test harness, there's an option that allows us to
+fudge this time so as to get repeatability of the tests. Take the first
+time off the list. In queue runs, the list pointer gets updated in the
+calling process. */
+
+int
+test_harness_fudged_queue_time(int actual_time)
+{
+int qt;
+if (  f.running_in_test_harness && *fudged_queue_times
+   && (qt = readconf_readtime(fudged_queue_times, '/', FALSE)) >= 0)
+  {
+  DEBUG(D_deliver) debug_printf("fudged queue_times = %s\n",
+    fudged_queue_times);
+  return qt;
+  }
+return actual_time;
+}
+
+/************************************************/
+
+static FILE *
+expand_open(const uschar * filename,
+  const uschar * varname, const uschar * reason)
+{
+const uschar * s = expand_cstring(filename);
+FILE * fp = NULL;
+
+if (!s || !*s)
+  log_write(0, LOG_MAIN|LOG_PANIC,
+    "Failed to expand %s: '%s'\n", varname, filename);
+else if (*s != '/' || is_tainted(s))
+  log_write(0, LOG_MAIN|LOG_PANIC,
+    "%s is not %s after expansion: '%s'\n",
+    varname, *s == '/' ? "untainted" : "absolute", s);
+else if (!(fp = Ufopen(s, "rb")))
+  log_write(0, LOG_MAIN|LOG_PANIC, "Failed to open %s for %s "
+    "message texts: %s", s, reason, strerror(errno));
+return fp;
+}
+
 /*************************************************
 *              Deliver one message               *
 *************************************************/
@@ -5560,8 +5587,13 @@ int process_recipients = RECIP_ACCEPT;
 open_db dbblock;
 open_db *dbm_file;
 extern int acl_where;
+uschar *info;
 
-uschar *info = queue_run_pid == (pid_t)0
+#ifdef MEASURE_TIMING
+report_time_since(&timestamp_startup, US"delivery start");     /* testcase 0022, 2100 */
+#endif
+
+info = queue_run_pid == (pid_t)0
   ? string_sprintf("delivering %s", id)
   : string_sprintf("delivering %s (queue run pid %d)", id, queue_run_pid);
 
@@ -6194,7 +6226,8 @@ if (process_recipients != RECIP_IGNORE)
         new->onetime_parent = recipients_list[r->pno].address;
 
       /* If DSN support is enabled, set the dsn flags and the original receipt
-         to be passed on to other DSN enabled MTAs */
+      to be passed on to other DSN enabled MTAs */
+
       new->dsn_flags = r->dsn_flags & rf_dsnflags;
       new->dsn_orcpt = r->orcpt;
       DEBUG(D_deliver) debug_printf("DSN: set orcpt: %s  flags: 0x%x\n",
@@ -7177,7 +7210,7 @@ if (addr_remote)
   /* Precompile some regex that are used to recognize parameters in response
   to an EHLO command, if they aren't already compiled. */
 
-  deliver_init();
+  smtp_deliver_init();
 
   /* Now sort the addresses if required, and do the deliveries. The yield of
   do_remote_deliveries is FALSE when mua_wrapper is set and all addresses
@@ -7314,10 +7347,9 @@ for (address_item * a = addr_succeed; a; a = a->next)
       );
 
   /* send report if next hop not DSN aware or a router flagged "last DSN hop"
-     and a report was requested */
-  if (  (  a->dsn_aware != dsn_support_yes
-       || a->dsn_flags & rf_dsnlasthop
-        )
+  and a report was requested */
+
+  if (  (a->dsn_aware != dsn_support_yes || a->dsn_flags & rf_dsnlasthop)
      && a->dsn_flags & rf_notify_success
      )
     {
@@ -7337,14 +7369,14 @@ if (addr_senddsn)
   int fd;
 
   /* create exim process to send message */
-  pid = child_open_exim(&fd);
+  pid = child_open_exim(&fd, US"DSN");
 
   DEBUG(D_deliver) debug_printf("DSN: child_open_exim returns: %d\n", pid);
 
   if (pid < 0)  /* Creation of child failed */
     {
     log_write(0, LOG_MAIN|LOG_PANIC_DIE, "Process %d (parent %d) failed to "
-      "create child process to send failure message: %s", getpid(),
+      "create child process to send success-dsn message: %s", getpid(),
       getppid(), strerror(errno));
 
     DEBUG(D_deliver) debug_printf("DSN: child_open_exim failed\n");
@@ -7357,7 +7389,7 @@ if (addr_senddsn)
     transport_ctx tctx = {{0}};
 
     DEBUG(D_deliver)
-      debug_printf("sending error message to: %s\n", sender_address);
+      debug_printf("sending success-dsn to: %s\n", sender_address);
 
     /* build unique id for MIME boundary */
     bound = string_sprintf(TIME_T_FMT "-eximdsn-%d", time(NULL), rand());
@@ -7369,8 +7401,11 @@ if (addr_senddsn)
     moan_write_from(f);
     fprintf(f, "Auto-Submitted: auto-generated\n"
        "To: %s\n"
-       "Subject: Delivery Status Notification\n"
-       "Content-Type: multipart/report; report-type=delivery-status; boundary=%s\n"
+       "Subject: Delivery Status Notification\n",
+      sender_address);
+    moan_write_references(f, NULL);
+    fprintf(f, "Content-Type: multipart/report;"
+               " report-type=delivery-status; boundary=%s\n"
        "MIME-Version: 1.0\n\n"
 
        "--%s\n"
@@ -7378,7 +7413,7 @@ if (addr_senddsn)
 
        "This message was created automatically by mail delivery software.\n"
        " ----- The following addresses had successful delivery notifications -----\n",
-      sender_address, bound, bound);
+      bound, bound);
 
     for (address_item * a = addr_senddsn; a; a = a->next)
       fprintf(f, "<%s> (relayed %s)\n\n",
@@ -7535,7 +7570,7 @@ while (addr_failed)
 
     /* Make a subprocess to send a message */
 
-    if ((pid = child_open_exim(&fd)) < 0)
+    if ((pid = child_open_exim(&fd, US"bounce-message")) < 0)
       log_write(0, LOG_MAIN|LOG_PANIC_DIE, "Process %d (parent %d) failed to "
         "create child process to send failure message: %s", getpid(),
         getppid(), strerror(errno));
@@ -7607,6 +7642,7 @@ while (addr_failed)
       fprintf(fp, "Auto-Submitted: auto-replied\n");
       moan_write_from(fp);
       fprintf(fp, "To: %s\n", bounce_recipient);
+      moan_write_references(fp, NULL);
 
       /* generate boundary string and output MIME-Headers */
       bound = string_sprintf(TIME_T_FMT "-eximdsn-%d", time(NULL), rand());
@@ -7620,9 +7656,8 @@ while (addr_failed)
       carry on - default texts will be used. */
 
       if (bounce_message_file)
-        if (!(emf = Ufopen(bounce_message_file, "rb")))
-          log_write(0, LOG_MAIN|LOG_PANIC, "Failed to open %s for error "
-            "message texts: %s", bounce_message_file, strerror(errno));
+       emf = expand_open(bounce_message_file,
+               US"bounce_message_file", US"error");
 
       /* Quietly copy to configured additional addresses if required. */
 
@@ -7811,11 +7846,11 @@ wording. */
            fprintf(fp, "Remote-MTA: X-ip; [%s]%s\n", hu->address, p);
            }
          if ((s = addr->smtp_greeting) && *s)
-           fprintf(fp, "X-Remote-MTA-smtp-greeting: X-str; %s\n", s);
+           fprintf(fp, "X-Remote-MTA-smtp-greeting: X-str; %.900s\n", s);
          if ((s = addr->helo_response) && *s)
-           fprintf(fp, "X-Remote-MTA-helo-response: X-str; %s\n", s);
+           fprintf(fp, "X-Remote-MTA-helo-response: X-str; %.900s\n", s);
          if ((s = addr->message) && *s)
-           fprintf(fp, "X-Exim-Diagnostic: X-str; %s\n", s);
+           fprintf(fp, "X-Exim-Diagnostic: X-str; %.900s\n", s);
          }
 #endif
          print_dsn_diagnostic_code(addr, fp);
@@ -7915,10 +7950,6 @@ wording. */
       (void)fclose(fp);
       rc = child_close(pid, 0);     /* Waits for child to close, no timeout */
 
-      /* In the test harness, let the child do it's thing first. */
-
-      if (f.running_in_test_harness) millisleep(500);
-
       /* If the process failed, there was some disaster in setting up the
       error message. Unless the message is very old, ensure that addr_defer
       is non-null, which will have the effect of leaving the message on the
@@ -8157,21 +8188,7 @@ else if (addr_defer != (address_item *)(+1))
     int show_time;
     int queue_time = time(NULL) - received_time.tv_sec;
 
-    /* When running in the test harness, there's an option that allows us to
-    fudge this time so as to get repeatability of the tests. Take the first
-    time off the list. In queue runs, the list pointer gets updated in the
-    calling process. */
-
-    if (f.running_in_test_harness && fudged_queue_times[0] != 0)
-      {
-      int qt = readconf_readtime(fudged_queue_times, '/', FALSE);
-      if (qt >= 0)
-        {
-        DEBUG(D_deliver) debug_printf("fudged queue_times = %s\n",
-          fudged_queue_times);
-        queue_time = qt;
-        }
-      }
+    queue_time = test_harness_fudged_queue_time(queue_time);
 
     /* See how many warnings we should have sent by now */
 
@@ -8192,7 +8209,8 @@ else if (addr_defer != (address_item *)(+1))
 
     DEBUG(D_deliver)
       {
-      debug_printf("time on queue = %s  id %s  addr %s\n", readconf_printtime(queue_time), message_id, addr_defer->address);
+      debug_printf("time on queue = %s  id %s  addr %s\n",
+       readconf_printtime(queue_time), message_id, addr_defer->address);
       debug_printf("warning counts: required %d done %d\n", count,
         warning_count);
       }
@@ -8205,20 +8223,19 @@ else if (addr_defer != (address_item *)(+1))
       {
       header_line *h;
       int fd;
-      pid_t pid = child_open_exim(&fd);
+      pid_t pid = child_open_exim(&fd, US"delay-warning-message");
 
       if (pid > 0)
         {
-        uschar *wmf_text;
-        FILE *wmf = NULL;
-        FILE *f = fdopen(fd, "wb");
+        uschar * wmf_text;
+        FILE * wmf = NULL;
+        FILE * f = fdopen(fd, "wb");
        uschar * bound;
        transport_ctx tctx = {{0}};
 
         if (warn_message_file)
-          if (!(wmf = Ufopen(warn_message_file, "rb")))
-            log_write(0, LOG_MAIN|LOG_PANIC, "Failed to open %s for warning "
-              "message texts: %s", warn_message_file, strerror(errno));
+         wmf = expand_open(warn_message_file,
+                 US"warn_message_file", US"warning");
 
         warnmsg_recipients = recipients;
         warnmsg_delay = queue_time < 120*60
@@ -8230,6 +8247,7 @@ else if (addr_defer != (address_item *)(+1))
         fprintf(f, "Auto-Submitted: auto-replied\n");
         moan_write_from(f);
         fprintf(f, "To: %s\n", recipients);
+       moan_write_references(f, NULL);
 
         /* generated boundary string and output MIME-Headers */
         bound = string_sprintf(TIME_T_FMT "-eximdsn-%d", time(NULL), rand());
@@ -8491,6 +8509,9 @@ to try delivery. */
 (void)close(deliver_datafile);
 deliver_datafile = -1;
 DEBUG(D_deliver) debug_printf("end delivery of %s\n", id);
+#ifdef MEASURE_TIMING
+report_time_since(&timestamp_startup, US"delivery end"); /* testcase 0005 */
+#endif
 
 /* It is unlikely that there will be any cached resources, since they are
 released after routing, and in the delivery subprocesses. However, it's
@@ -8506,52 +8527,13 @@ return final_yield;
 
 
 void
-deliver_init(void)
+tcp_init(void)
 {
 #ifdef EXIM_TFO_PROBE
 tfo_probe();
 #else
 f.tcp_fastopen_ok = TRUE;
 #endif
-
-
-if (!regex_PIPELINING) regex_PIPELINING =
-  regex_must_compile(US"\\n250[\\s\\-]PIPELINING(\\s|\\n|$)", FALSE, TRUE);
-
-if (!regex_SIZE) regex_SIZE =
-  regex_must_compile(US"\\n250[\\s\\-]SIZE(\\s|\\n|$)", FALSE, TRUE);
-
-if (!regex_AUTH) regex_AUTH =
-  regex_must_compile(AUTHS_REGEX, FALSE, TRUE);
-
-#ifndef DISABLE_TLS
-if (!regex_STARTTLS) regex_STARTTLS =
-  regex_must_compile(US"\\n250[\\s\\-]STARTTLS(\\s|\\n|$)", FALSE, TRUE);
-#endif
-
-if (!regex_CHUNKING) regex_CHUNKING =
-  regex_must_compile(US"\\n250[\\s\\-]CHUNKING(\\s|\\n|$)", FALSE, TRUE);
-
-#ifndef DISABLE_PRDR
-if (!regex_PRDR) regex_PRDR =
-  regex_must_compile(US"\\n250[\\s\\-]PRDR(\\s|\\n|$)", FALSE, TRUE);
-#endif
-
-#ifdef SUPPORT_I18N
-if (!regex_UTF8) regex_UTF8 =
-  regex_must_compile(US"\\n250[\\s\\-]SMTPUTF8(\\s|\\n|$)", FALSE, TRUE);
-#endif
-
-if (!regex_DSN) regex_DSN  =
-  regex_must_compile(US"\\n250[\\s\\-]DSN(\\s|\\n|$)", FALSE, TRUE);
-
-if (!regex_IGNOREQUOTA) regex_IGNOREQUOTA =
-  regex_must_compile(US"\\n250[\\s\\-]IGNOREQUOTA(\\s|\\n|$)", FALSE, TRUE);
-
-#ifdef SUPPORT_PIPE_CONNECT
-if (!regex_EARLY_PIPE) regex_EARLY_PIPE =
-  regex_must_compile(US"\\n250[\\s\\-]" EARLY_PIPE_FEATURE_NAME "(\\s|\\n|$)", FALSE, TRUE);
-#endif
 }
 
 
@@ -8628,18 +8610,17 @@ if (cutthrough.cctx.sock >= 0 && cutthrough.callout_hold_only)
       goto fail;
 
     where = US"fork";
-    if ((pid = fork()) < 0)
+    testharness_pause_ms(150);
+    if ((pid = exim_fork(US"tls-proxy-interproc")) < 0)
       goto fail;
 
-    else if (pid == 0)         /* child: fork again to totally disconnect */
+    if (pid == 0)      /* child: will fork again to totally disconnect */
       {
-      if (f.running_in_test_harness) millisleep(100); /* let parent debug out */
-      /* does not return */
       smtp_proxy_tls(cutthrough.cctx.tls_ctx, big_buffer, big_buffer_size,
                      pfd, 5*60);
+      /* does not return */
       }
 
-    DEBUG(D_transport) debug_printf("proxy-proc inter-pid %d\n", pid);
     close(pfd[0]);
     waitpid(pid, NULL, 0);
     (void) close(channel_fd);  /* release the client socket */