Testsuite: delays for debug output ordering
[exim.git] / src / src / transports / smtp.c
index a3819fe49954bd5e1f799db01f219c3a439e54ae..ef9309c471a0f296126cfb9aad2bbd9f0c8cf4d7 100644 (file)
@@ -43,6 +43,10 @@ optionlist smtp_transport_options[] = {
       (void *)offsetof(smtp_transport_options_block, dkim.dkim_canon) },
   { "dkim_domain", opt_stringptr,
       (void *)offsetof(smtp_transport_options_block, dkim.dkim_domain) },
+  { "dkim_hash", opt_stringptr,
+      (void *)offsetof(smtp_transport_options_block, dkim.dkim_hash) },
+  { "dkim_identity", opt_stringptr,
+      (void *)offsetof(smtp_transport_options_block, dkim.dkim_identity) },
   { "dkim_private_key", opt_stringptr,
       (void *)offsetof(smtp_transport_options_block, dkim.dkim_private_key) },
   { "dkim_selector", opt_stringptr,
@@ -201,87 +205,89 @@ void smtp_transport_closedown(transport_instance *tblock) {}
 /* Default private options block for the smtp transport. */
 
 smtp_transport_options_block smtp_transport_option_defaults = {
-  NULL,                /* hosts */
-  NULL,                /* fallback_hosts */
-  NULL,                /* hostlist */
-  NULL,                /* fallback_hostlist */
-  NULL,                /* authenticated_sender */
-  US"$primary_hostname", /* helo_data */
-  NULL,                /* interface */
-  NULL,                /* port */
-  US"smtp",            /* protocol */
-  NULL,                /* DSCP */
-  NULL,                /* serialize_hosts */
-  NULL,                /* hosts_try_auth */
-  NULL,                /* hosts_require_auth */
-  US"*",               /* hosts_try_chunking */
+  .hosts =                     NULL,
+  .hosts =                     NULL,
+  .hostlist =                  NULL,
+  .fallback_hostlist =         NULL,
+  .authenticated_sender =      NULL,
+  .helo_data =                 US"$primary_hostname",
+  .interface =                 NULL,
+  .port =                      NULL,
+  .protocol =                  US"smtp",
+  .dscp =                      NULL,
+  .serialize_hosts =           NULL,
+  .hosts_try_auth =            NULL,
+  .hosts_require_auth =                NULL,
+  .hosts_try_chunking =                US"*",
 #ifdef EXPERIMENTAL_DANE
-  NULL,                /* hosts_try_dane */
-  NULL,                /* hosts_require_dane */
+  .hosts_try_dane =            NULL,
+  .hosts_require_dane =                NULL,
 #endif
-  NULL,                /* hosts_try_fastopen */
+  .hosts_try_fastopen =                NULL,
 #ifndef DISABLE_PRDR
-  US"*",               /* hosts_try_prdr */
+  .hosts_try_prdr =            US"*",
 #endif
 #ifndef DISABLE_OCSP
-  US"*",               /* hosts_request_ocsp (except under DANE; tls_client_start()) */
-  NULL,                /* hosts_require_ocsp */
+  .hosts_request_ocsp =                US"*",               /* hosts_request_ocsp (except under DANE; tls_client_start()) */
+  .hosts_require_ocsp =                NULL,
 #endif
-  NULL,                /* hosts_require_tls */
-  NULL,                /* hosts_avoid_tls */
-  NULL,                /* hosts_verify_avoid_tls */
-  NULL,                /* hosts_avoid_pipelining */
-  NULL,                /* hosts_avoid_esmtp */
+  .hosts_require_tls =         NULL,
+  .hosts_avoid_tls =           NULL,
+  .hosts_verify_avoid_tls =    NULL,
+  .hosts_avoid_pipelining =    NULL,
+  .hosts_avoid_esmtp =         NULL,
 #ifdef SUPPORT_TLS
-  NULL,                /* hosts_nopass_tls */
-  US"*",              /* hosts_noproxy_tls */
+  .hosts_nopass_tls =          NULL,
+  .hosts_noproxy_tls =         US"*",
 #endif
-  5*60,                /* command_timeout */
-  5*60,                /* connect_timeout; shorter system default overrides */
-  5*60,                /* data timeout */
-  10*60,               /* final timeout */
-  1024,                /* size_addition */
-  5,                   /* hosts_max_try */
-  50,                  /* hosts_max_try_hardlimit */
-  TRUE,                /* address_retry_include_sender */
-  FALSE,               /* allow_localhost */
-  FALSE,               /* authenticated_sender_force */
-  FALSE,               /* gethostbyname */
-  TRUE,                /* dns_qualify_single */
-  FALSE,               /* dns_search_parents */
-  { NULL, NULL },      /* dnssec_domains {request,require} */
-  TRUE,                /* delay_after_cutoff */
-  FALSE,               /* hosts_override */
-  FALSE,               /* hosts_randomize */
-  TRUE,                /* keepalive */
-  FALSE,               /* lmtp_ignore_quota */
-  NULL,                       /* expand_retry_include_ip_address */
-  TRUE                 /* retry_include_ip_address */
+  .command_timeout =           5*60,
+  .connect_timeout =           5*60,
+  .data_timeout =              5*60,
+  .final_timeout =             10*60,
+  .size_addition =             1024,
+  .hosts_max_try =             5,
+  .hosts_max_try_hardlimit =   50,
+  .address_retry_include_sender = TRUE,
+  .allow_localhost =           FALSE,
+  .authenticated_sender_force =        FALSE,
+  .gethostbyname =             FALSE,
+  .dns_qualify_single =                TRUE,
+  .dns_search_parents =                FALSE,
+  .dnssec = { .request=NULL, .require=NULL },
+  .delay_after_cutoff =                TRUE,
+  .hosts_override =            FALSE,
+  .hosts_randomize =           FALSE,
+  .keepalive =                 TRUE,
+  .lmtp_ignore_quota =         FALSE,
+  .expand_retry_include_ip_address =   NULL,
+  .retry_include_ip_address =  TRUE,
 #ifdef SUPPORT_SOCKS
- ,NULL                 /* socks_proxy */
+  .socks_proxy =               NULL,
 #endif
 #ifdef SUPPORT_TLS
- ,NULL,                /* tls_certificate */
-  NULL,                /* tls_crl */
-  NULL,                /* tls_privatekey */
-  NULL,                /* tls_require_ciphers */
-  NULL,                /* tls_sni */
-  US"system",          /* tls_verify_certificates */
-  EXIM_CLIENT_DH_DEFAULT_MIN_BITS,
-                       /* tls_dh_min_bits */
-  TRUE,                /* tls_tempfail_tryclear */
-  NULL,                /* tls_verify_hosts */
-  US"*",               /* tls_try_verify_hosts */
-  US"*"                /* tls_verify_cert_hostnames */
+  .tls_certificate =           NULL,
+  .tls_crl =                   NULL,
+  .tls_privatekey =            NULL,
+  .tls_require_ciphers =       NULL,
+  .tls_sni =                   NULL,
+  .tls_verify_certificates =   US"system",
+  .tls_dh_min_bits =           EXIM_CLIENT_DH_DEFAULT_MIN_BITS,
+  .tls_tempfail_tryclear =     TRUE,
+  .tls_verify_hosts =          NULL,
+  .tls_try_verify_hosts =      US"*",
+  .tls_verify_cert_hostnames = US"*",
 #endif
 #ifndef DISABLE_DKIM
- , {NULL,              /* dkim_canon */
-    NULL,              /* dkim_domain */
-    NULL,              /* dkim_private_key */
-    NULL,              /* dkim_selector */
-    NULL,              /* dkim_sign_headers */
-    NULL,              /* dkim_strict */
-    FALSE}            /* dot_stuffed */
+ .dkim =
+   {.dkim_domain =             NULL,
+    .dkim_identity =           NULL,
+    .dkim_private_key =                NULL,
+    .dkim_selector =           NULL,
+    .dkim_canon =              NULL,
+    .dkim_sign_headers =       NULL,
+    .dkim_strict =             NULL,
+    .dkim_hash =               US"sha256",
+    .dot_stuffed =             FALSE},
 #endif
 };
 
@@ -617,34 +623,34 @@ return FALSE;
 /* This writes to the main log and to the message log.
 
 Arguments:
-  addr     the address item containing error information
   host     the current host
+  detail  the current message (addr_item->message)
+  basic_errno the errno (addr_item->basic_errno)
 
 Returns:   nothing
 */
 
 static void
-write_logs(address_item *addr, host_item *host)
+write_logs(const host_item *host, const uschar *suffix, int basic_errno)
 {
-uschar * message = LOGGING(outgoing_port)
+
+
+uschar *message = LOGGING(outgoing_port)
   ? string_sprintf("H=%s [%s]:%d", host->name, host->address,
                    host->port == PORT_NONE ? 25 : host->port)
   : string_sprintf("H=%s [%s]", host->name, host->address);
 
-if (addr->message)
+if (suffix)
   {
-  message = string_sprintf("%s: %s", message, addr->message);
-  if (addr->basic_errno > 0)
-    message = string_sprintf("%s: %s", message, strerror(addr->basic_errno));
-  log_write(0, LOG_MAIN, "%s", message);
-  deliver_msglog("%s %s\n", tod_stamp(tod_log), message);
+  message = string_sprintf("%s: %s", message, suffix);
+  if (basic_errno > 0)
+    message = string_sprintf("%s: %s", message, strerror(basic_errno));
   }
 else
-  {
-  const uschar * s = exim_errstr(addr->basic_errno);
-  log_write(0, LOG_MAIN, "%s %s", message, s);
-  deliver_msglog("%s %s %s\n", tod_stamp(tod_log), message, s);
-  }
+  message = string_sprintf("%s %s", message, exim_errstr(basic_errno));
+
+log_write(0, LOG_MAIN, "%s", message);
+deliver_msglog("%s %s\n", tod_stamp(tod_log), message);
 }
 
 static void
@@ -1814,7 +1820,7 @@ goto SEND_QUIT;
        errno = ERRNO_SMTPCLOSED;
        goto EHLOHELO_FAILED;
        }
-      Ustrncpy(sx->buffer, rsp, sizeof(sx->buffer)/2);
+      memmove(sx->buffer, rsp, Ustrlen(rsp));
       goto RESPONSE_FAILED;
       }
     }
@@ -2170,11 +2176,6 @@ return OK;
     sx->send_quit = FALSE;
     goto FAILED;
 
-  /* This label is jumped to directly when a TLS negotiation has failed,
-  or was not done for a host for which it is required. Values will be set
-  in message and errno, and setting_up will always be true. Treat as
-  a temporary error. */
-
   EHLOHELO_FAILED:
     code = '4';
     message = string_sprintf("Remote host closed connection in response to %s"
@@ -2182,6 +2183,11 @@ return OK;
     sx->send_quit = FALSE;
     goto FAILED;
 
+  /* This label is jumped to directly when a TLS negotiation has failed,
+  or was not done for a host for which it is required. Values will be set
+  in message and errno, and setting_up will always be true. Treat as
+  a temporary error. */
+
 #ifdef SUPPORT_TLS
   TLS_FAILED:
     code = '4';
@@ -2505,7 +2511,10 @@ for (addr = sx->first_addr, address_count = 0;
   uschar * rcpt_addr;
 
   if (tcp_out_fastopen && !tcp_out_fastopen_logged)
-    setflag(addr, af_tcp_fastopen);
+    {
+    setflag(addr, af_tcp_fastopen_conn);
+    if (tcp_out_fastopen > 1) setflag(addr, af_tcp_fastopen);
+    }
 
   addr->dsn_aware = sx->peer_offered & OPTION_DSN
     ? dsn_support_yes : dsn_support_no;
@@ -2571,29 +2580,38 @@ return 0;
 * Proxy TLS connection for another transport process *
 ******************************************************/
 /*
-Use the given buffer as a staging area, and select on both the given fd
-and the TLS'd client-fd for data to read (per the coding in ip_recv() and
-fd_ready() this is legitimate).  Do blocking full-size writes, and reads
-under a timeout.
+Close the unused end of the pipe, fork once more, then use the given buffer
+as a staging area, and select on both the given fd and the TLS'd client-fd for
+data to read (per the coding in ip_recv() and fd_ready() this is legitimate).
+Do blocking full-size writes, and reads under a timeout.  Once both input
+channels are closed, exit the process.
 
 Arguments:
   buf          space to use for buffering
   bufsiz       size of buffer
-  proxy_fd     comms to proxied process
+  pfd          pipe filedescriptor array; [0] is comms to proxied process
   timeout      per-read timeout, seconds
 */
 
 void
-smtp_proxy_tls(uschar * buf, size_t bsize, int proxy_fd, int timeout)
+smtp_proxy_tls(uschar * buf, size_t bsize, int * pfd, int timeout)
 {
 fd_set rfds, efds;
-int max_fd = MAX(proxy_fd, tls_out.active) + 1;
+int max_fd = MAX(pfd[0], tls_out.active) + 1;
 int rc, i, fd_bits, nbytes;
 
+close(pfd[1]);
+if ((rc = fork()))
+  {
+  DEBUG(D_transport) debug_printf("proxy-proc final-pid %d\n", rc);
+  _exit(rc < 0 ? EXIT_FAILURE : EXIT_SUCCESS);
+  }
+
+if (running_in_test_harness) millisleep(100); /* let parent debug out */
 set_process_info("proxying TLS connection for continued transport");
 FD_ZERO(&rfds);
 FD_SET(tls_out.active, &rfds);
-FD_SET(proxy_fd, &rfds);
+FD_SET(pfd[0], &rfds);
 
 for (fd_bits = 3; fd_bits; )
   {
@@ -2615,17 +2633,17 @@ for (fd_bits = 3; fd_bits; )
     if (rc <= 0)
       {
       DEBUG(D_transport) if (rc == 0) debug_printf("%s: timed out\n", __FUNCTION__);
-      return;
+      goto done;
       }
 
-    if (FD_ISSET(tls_out.active, &efds) || FD_ISSET(proxy_fd, &efds))
+    if (FD_ISSET(tls_out.active, &efds) || FD_ISSET(pfd[0], &efds))
       {
       DEBUG(D_transport) debug_printf("select: exceptional cond on %s fd\n",
-       FD_ISSET(proxy_fd, &efds) ? "proxy" : "tls");
-      return;
+       FD_ISSET(pfd[0], &efds) ? "proxy" : "tls");
+      goto done;
       }
     }
-  while (rc < 0 || !(FD_ISSET(tls_out.active, &rfds) || FD_ISSET(proxy_fd, &rfds)));
+  while (rc < 0 || !(FD_ISSET(tls_out.active, &rfds) || FD_ISSET(pfd[0], &rfds)));
 
   /* handle inbound data */
   if (FD_ISSET(tls_out.active, &rfds))
@@ -2633,20 +2651,20 @@ for (fd_bits = 3; fd_bits; )
       {
       fd_bits &= ~1;
       FD_CLR(tls_out.active, &rfds);
-      shutdown(proxy_fd, SHUT_WR);
+      shutdown(pfd[0], SHUT_WR);
       timeout = 5;
       }
     else
       {
       for (nbytes = 0; rc - nbytes > 0; nbytes += i)
-       if ((i = write(proxy_fd, buf + nbytes, rc - nbytes)) < 0) return;
+       if ((i = write(pfd[0], buf + nbytes, rc - nbytes)) < 0) goto done;
       }
   else if (fd_bits & 1)
     FD_SET(tls_out.active, &rfds);
 
   /* handle outbound data */
-  if (FD_ISSET(proxy_fd, &rfds))
-    if ((rc = read(proxy_fd, buf, bsize)) <= 0)
+  if (FD_ISSET(pfd[0], &rfds))
+    if ((rc = read(pfd[0], buf, bsize)) <= 0)
       {
       fd_bits = 0;
       tls_close(FALSE, TRUE);
@@ -2655,11 +2673,15 @@ for (fd_bits = 3; fd_bits; )
       {
       for (nbytes = 0; rc - nbytes > 0; nbytes += i)
        if ((i = tls_write(FALSE, buf + nbytes, rc - nbytes, FALSE)) < 0)
-         return;
+         goto done;
       }
   else if (fd_bits & 2)
-    FD_SET(proxy_fd, &rfds);
+    FD_SET(pfd[0], &rfds);
   }
+
+done:
+  if (running_in_test_harness) millisleep(100);        /* let logging complete */
+  exim_exit(0, US"TLS proxy");
 }
 #endif
 
@@ -3298,8 +3320,9 @@ if (!sx.ok)
        set_rc = DEFER;
         if (save_errno > 0)
           message = US string_sprintf("%s: %s", message, strerror(save_errno));
-        if (host->next != NULL) log_write(0, LOG_MAIN, "%s", message);
-       msglog_line(host, message);
+
+        write_logs(host, message, sx.first_addr ? sx.first_addr->basic_errno : 0);
+
         *message_defer = TRUE;
         }
       }
@@ -3476,7 +3499,8 @@ propagate it from the initial
        {
         sx.send_quit = FALSE;
 
-       /* If TLS is still active, we need to proxy it for the transport we
+       /* We have passed the client socket to a fresh transport process.
+       If TLS is still active, we need to proxy it for the transport we
        just passed the baton to.  Fork a child to to do it, and return to
        get logging done asap.  Which way to place the work makes assumptions
        about post-fork prioritisation which may not hold on all platforms. */
@@ -3484,10 +3508,19 @@ propagate it from the initial
        if (tls_out.active >= 0)
          {
          int pid = fork();
+         if (pid == 0)         /* child; fork again to disconnect totally */
+           {
+           if (running_in_test_harness) millisleep(100); /* let parent debug out */
+           /* does not return */
+           smtp_proxy_tls(sx.buffer, sizeof(sx.buffer), pfd,
+                           sx.ob->command_timeout);
+           }
+
          if (pid > 0)          /* parent */
            {
            DEBUG(D_transport) debug_printf("proxy-proc inter-pid %d\n", pid);
            close(pfd[0]);
+           /* tidy the inter-proc to disconn the proxy proc */
            waitpid(pid, NULL, 0);
            tls_close(FALSE, FALSE);
            (void)close(sx.inblock.sock);
@@ -3495,17 +3528,7 @@ propagate it from the initial
            continue_hostname = NULL;
            return yield;
            }
-         else if (pid == 0)    /* child; fork again to disconnect totally */
-           {
-           close(pfd[1]);
-           if ((pid = fork()))
-             {
-             DEBUG(D_transport) debug_printf("proxy-prox final-pid %d\n", pid);
-             _exit(pid ? EXIT_FAILURE : EXIT_SUCCESS);
-             }
-           smtp_proxy_tls(sx.buffer, sizeof(sx.buffer), pfd[0], sx.ob->command_timeout);
-           exim_exit(0);
-           }
+         log_write(0, LOG_PANIC_DIE, "fork failed");
          }
 #endif
        }
@@ -4307,7 +4330,7 @@ for (cutoff_retry = 0;
 
       if (rc == DEFER && first_addr->basic_errno != ERRNO_AUTHFAIL
                      && first_addr->basic_errno != ERRNO_TLSFAILURE)
-        write_logs(first_addr, host);
+        write_logs(host, first_addr->message, first_addr->basic_errno);
 
 #ifndef DISABLE_EVENT
       if (rc == DEFER)
@@ -4337,7 +4360,7 @@ for (cutoff_retry = 0;
         rc = smtp_deliver(addrlist, thost, host_af, defport, interface, tblock,
           &message_defer, TRUE);
         if (rc == DEFER && first_addr->basic_errno != ERRNO_AUTHFAIL)
-          write_logs(first_addr, host);
+          write_logs(host, first_addr->message, first_addr->basic_errno);
 # ifndef DISABLE_EVENT
         if (rc == DEFER)
           deferred_event_raise(first_addr, host);