For connects and certificate-verifies denied by event actions, log
[exim.git] / src / src / transports / smtp.c
index 7b2a7d5594fcd4244d2f422cf2f6f650a2282f78..c572306972bc657c71541a604600e2af720ac389 100644 (file)
@@ -212,7 +212,7 @@ smtp_transport_options_block smtp_transport_option_defaults = {
   NULL,                /* hosts_try_prdr */
 #endif
 #ifndef DISABLE_OCSP
-  US"*",               /* hosts_request_ocsp (except under DANE) */
+  US"*",               /* hosts_request_ocsp (except under DANE; tls_client_start()) */
   NULL,                /* hosts_require_ocsp */
 #endif
   NULL,                /* hosts_require_tls */
@@ -433,6 +433,7 @@ Arguments:
   msg            to put in each address's message field
   rc             to put in each address's transport_return field
   pass_message   if TRUE, set the "pass message" flag in the address
+  host           if set, mark addrs as having used this host
 
 If errno_value has the special value ERRNO_CONNECTTIMEOUT, ETIMEDOUT is put in
 the errno field, and RTEF_CTOUT is ORed into the more_errno field, to indicate
@@ -443,7 +444,7 @@ Returns:       nothing
 
 static void
 set_errno(address_item *addrlist, int errno_value, uschar *msg, int rc,
-  BOOL pass_message)
+  BOOL pass_message, host_item * host)
 {
 address_item *addr;
 int orvalue = 0;
@@ -463,6 +464,8 @@ for (addr = addrlist; addr != NULL; addr = addr->next)
     if (pass_message) setflag(addr, af_pass_message);
     }
   addr->transport_return = rc;
+  if (host)
+    addr->host_used = host;
   }
 }
 
@@ -508,8 +511,8 @@ if (smtp_use_pipelining &&
 
 if (*errno_value == ETIMEDOUT)
   {
-  *message = US string_sprintf("SMTP timeout while connected to %s [%s] "
-    "after %s%s", host->name, host->address, pl, smtp_command);
+  *message = US string_sprintf("SMTP timeout after %s%s",
+      pl, smtp_command);
   if (transport_count > 0)
     *message = US string_sprintf("%s (%d bytes written)", *message,
       transport_count);
@@ -522,13 +525,11 @@ if (*errno_value == ERRNO_SMTPFORMAT)
   {
   uschar *malfresp = string_printing(buffer);
   while (isspace(*malfresp)) malfresp++;
-  if (*malfresp == 0)
-    *message = string_sprintf("Malformed SMTP reply (an empty line) from "
-      "%s [%s] in response to %s%s", host->name, host->address, pl,
-      smtp_command);
-  else
-    *message = string_sprintf("Malformed SMTP reply from %s [%s] in response "
-      "to %s%s: %s", host->name, host->address, pl, smtp_command, malfresp);
+  *message = *malfresp == 0
+    ? string_sprintf("Malformed SMTP reply (an empty line) "
+       "in response to %s%s", pl, smtp_command)
+    : string_sprintf("Malformed SMTP reply in response to %s%s: %s",
+       pl, smtp_command, malfresp);
   return FALSE;
   }
 
@@ -568,7 +569,7 @@ if (buffer[0] != 0)
   {
   uschar *s = string_printing(buffer);
   *message = US string_sprintf("SMTP error from remote mail server after %s%s: "
-    "host %s [%s]: %s", pl, smtp_command, host->name, host->address, s);
+    "%s", pl, smtp_command, s);
   *pass_message = TRUE;
   *yield = buffer[0];
   return TRUE;
@@ -583,8 +584,8 @@ assume the connection is now dead. */
 if (*errno_value == 0 || *errno_value == ECONNRESET)
   {
   *errno_value = ERRNO_SMTPCLOSED;
-  *message = US string_sprintf("Remote host %s [%s] closed connection "
-    "in response to %s%s", host->name, host->address, pl, smtp_command);
+  *message = US string_sprintf("Remote host closed connection "
+    "in response to %s%s",  pl, smtp_command);
   }
 else *message = US string_sprintf("%s [%s]", host->name, host->address);
 
@@ -609,9 +610,11 @@ Returns:   nothing
 static void
 write_logs(address_item *addr, host_item *host)
 {
-if (addr->message != NULL)
+uschar * message = string_sprintf("H=%s [%s]", host->name, host->address);
+
+if (addr->message)
   {
-  uschar *message = addr->message;
+  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);
@@ -619,21 +622,25 @@ if (addr->message != NULL)
   }
 else
   {
-  uschar *msg =
-    ((log_extra_selector & LX_outgoing_port) != 0)?
-    string_sprintf("%s [%s]:%d", host->name, host->address,
-      (host->port == PORT_NONE)? 25 : host->port)
-    :
-    string_sprintf("%s [%s]", host->name, host->address);
-  log_write(0, LOG_MAIN, "%s %s", msg, strerror(addr->basic_errno));
-  deliver_msglog("%s %s %s\n", tod_stamp(tod_log), msg,
-    strerror(addr->basic_errno));
+  if (log_extra_selector & LX_outgoing_port)
+    message = string_sprintf("%s:%d", message,
+               host->port == PORT_NONE ? 25 : host->port);
+  log_write(0, LOG_MAIN, "%s %s", message, strerror(addr->basic_errno));
+  deliver_msglog("%s %s %s\n", tod_stamp(tod_log), message,
+               strerror(addr->basic_errno));
   }
 }
 
+static void
+msglog_line(host_item * host, uschar * message)
+{
+  deliver_msglog("%s H=%s [%s] %s\n", tod_stamp(tod_log),
+    host->name, host->address, message);
+}
+
 
 
-#ifdef EXPERIMENTAL_TPDA
+#ifdef EXPERIMENTAL_EVENT
 /*************************************************
 *   Post-defer action                            *
 *************************************************/
@@ -649,9 +656,9 @@ Returns:   nothing
 */
 
 static void
-tpda_deferred(address_item *addr, host_item *host)
+deferred_event_raise(address_item *addr, host_item *host)
 {
-uschar * action = addr->transport->tpda_event_action;
+uschar * action = addr->transport->event_action;
 uschar * save_domain;
 uschar * save_local;
 
@@ -663,15 +670,15 @@ save_local = deliver_localpart;
 
 /*XXX would ip & port already be set up? */
 deliver_host_address = string_copy(host->address);
-deliver_host_port =    (host->port == PORT_NONE)? 25 : host->port;
-tpda_defer_errno =     addr->basic_errno;
+deliver_host_port =    host->port == PORT_NONE ? 25 : host->port;
+event_defer_errno =    addr->basic_errno;
 
 router_name =    addr->router->name;
 transport_name = addr->transport->name;
 deliver_domain = addr->domain;
 deliver_localpart = addr->local_part;
 
-(void) tpda_raise_event(action, US"msg:host:defer",
+(void) event_raise(action, US"msg:host:defer",
     addr->message
       ? addr->basic_errno > 0
        ? string_sprintf("%s: %s", addr->message, strerror(addr->basic_errno))
@@ -777,6 +784,14 @@ if (pending_MAIL)
         }
       errno = save_errno;
       }
+
+    if (pending_DATA) count--;  /* Number of RCPT responses to come */
+    while (count-- > 0)                /* Mark any pending addrs with the host used */
+      {
+      while (addr->transport_return != PENDING_DEFER) addr = addr->next;
+      addr->host_used = host;
+      addr = addr->next;
+      }
     return -3;
     }
   }
@@ -792,6 +807,7 @@ while (count-- > 0)
   while (addr->transport_return != PENDING_DEFER) addr = addr->next;
 
   /* The address was accepted */
+  addr->host_used = host;
 
   if (smtp_read_response(inblock, buffer, buffsize, '2', timeout))
     {
@@ -816,10 +832,9 @@ while (count-- > 0)
   else if (errno == ETIMEDOUT)
     {
     int save_errno = errno;
-    uschar *message = string_sprintf("SMTP timeout while connected to %s [%s] "
-      "after RCPT TO:<%s>", host->name, host->address,
-      transport_rcpt_address(addr, include_affixes));
-    set_errno(addrlist, save_errno, message, DEFER, FALSE);
+    uschar *message = string_sprintf("SMTP timeout after RCPT TO:<%s>",
+                         transport_rcpt_address(addr, include_affixes));
+    set_errno(addrlist, save_errno, message, DEFER, FALSE, NULL);
     retry_add_item(addr, addr->address_retry_key, 0);
     update_waiting = FALSE;
     return -1;
@@ -843,10 +858,10 @@ while (count-- > 0)
     {
     addr->message =
       string_sprintf("SMTP error from remote mail server after RCPT TO:<%s>: "
-        "host %s [%s]: %s", transport_rcpt_address(addr, include_affixes),
-        host->name, host->address, string_printing(buffer));
+       "%s", transport_rcpt_address(addr, include_affixes),
+       string_printing(buffer));
     setflag(addr, af_pass_message);
-    deliver_msglog("%s %s\n", tod_stamp(tod_log), addr->message);
+    msglog_line(host, addr->message);
 
     /* The response was 5xx */
 
@@ -864,9 +879,11 @@ while (count-- > 0)
       addr->basic_errno = ERRNO_RCPT4XX;
       addr->more_errno |= ((buffer[1] - '0')*10 + buffer[2] - '0') << 8;
 
-      /* Log temporary errors if there are more hosts to be tried. */
+      /* Log temporary errors if there are more hosts to be tried.
+      If not, log this last one in the == line. */
 
-      if (host->next != NULL) log_write(0, LOG_MAIN, "%s", addr->message);
+      if (host->next)
+       log_write(0, LOG_MAIN, "H=%s [%s]: %s", host->name, host->address, addr->message);
 
       /* Do not put this message on the list of those waiting for specific
       hosts, as otherwise it is likely to be tried too often. */
@@ -1068,7 +1085,7 @@ if (is_esmtp && regex_match_and_setup(regex_AUTH, buffer, 0, -1))
          /* Internal problem, message in buffer. */
 
          case ERROR:
-         set_errno(addrlist, 0, string_copy(buffer), DEFER, FALSE);
+         set_errno(addrlist, 0, string_copy(buffer), DEFER, FALSE, NULL);
          return ERROR;
          }
 
@@ -1084,7 +1101,7 @@ if (require_auth == OK && !smtp_authenticated)
   {
   set_errno(addrlist, ERRNO_AUTHFAIL,
     string_sprintf("authentication required but %s", fail_reason), DEFER,
-    FALSE);
+    FALSE, NULL);
   return DEFER;
   }
 
@@ -1123,7 +1140,7 @@ if (ob->authenticated_sender != NULL)
       {
       uschar *message = string_sprintf("failed to expand "
         "authenticated_sender: %s", expand_string_message);
-      set_errno(addrlist, 0, message, DEFER, FALSE);
+      set_errno(addrlist, 0, message, DEFER, FALSE, NULL);
       return TRUE;
       }
     }
@@ -1148,6 +1165,46 @@ return FALSE;
 
 
 
+#ifdef EXPERIMENTAL_DANE
+int
+tlsa_lookup(host_item * host, dns_answer * dnsa,
+  BOOL dane_required, BOOL * dane)
+{
+/* move this out to host.c given the similarity to dns_lookup() ? */
+uschar buffer[300];
+uschar * fullname = buffer;
+
+/* TLSA lookup string */
+(void)sprintf(CS buffer, "_%d._tcp.%.256s", host->port, host->name);
+
+switch (dns_lookup(dnsa, buffer, T_TLSA, &fullname))
+  {
+  case DNS_AGAIN:
+    return DEFER; /* just defer this TLS'd conn */
+
+  default:
+  case DNS_FAIL:
+    if (dane_required)
+      {
+      log_write(0, LOG_MAIN, "DANE error: TLSA lookup failed");
+      return FAIL;
+      }
+    break;
+
+  case DNS_SUCCEED:
+    if (!dns_is_secure(dnsa))
+      {
+      log_write(0, LOG_MAIN, "DANE error: TLSA lookup not DNSSEC");
+      return DEFER;
+      }
+    *dane = TRUE;
+    break;
+  }
+return OK;
+}
+#endif
+
+
 /*************************************************
 *       Deliver address list to given host       *
 *************************************************/
@@ -1226,6 +1283,10 @@ BOOL prdr_active;
 #ifdef EXPERIMENTAL_DSN
 BOOL dsn_all_lasthop = TRUE;
 #endif
+#if defined(SUPPORT_TLS) && defined(EXPERIMENTAL_DANE)
+BOOL dane = FALSE;
+dns_answer tlsa_dnsa;
+#endif
 smtp_inblock inblock;
 smtp_outblock outblock;
 int max_rcpt = tblock->max_addresses;
@@ -1280,7 +1341,7 @@ tls_modify_variables(&tls_out);
 #ifndef SUPPORT_TLS
 if (smtps)
   {
-  set_errno(addrlist, 0, US"TLS support not available", DEFER, FALSE);
+  set_errno(addrlist, 0, US"TLS support not available", DEFER, FALSE, NULL);
   return ERROR;
   }
 #endif
@@ -1295,18 +1356,48 @@ if (continue_hostname == NULL)
   inblock.sock = outblock.sock =
     smtp_connect(host, host_af, port, interface, ob->connect_timeout,
                  ob->keepalive, ob->dscp
-#ifdef EXPERIMENTAL_TPDA
-                 , tblock->tpda_event_action
+#ifdef EXPERIMENTAL_EVENT
+                 , tblock->event_action
 #endif
                );
 
   if (inblock.sock < 0)
     {
     set_errno(addrlist, (errno == ETIMEDOUT)? ERRNO_CONNECTTIMEOUT : errno,
-      NULL, DEFER, FALSE);
+      NULL, DEFER, FALSE, NULL);
     return DEFER;
     }
 
+#if defined(SUPPORT_TLS) && defined(EXPERIMENTAL_DANE)
+    {
+    BOOL dane_required;
+
+    tls_out.dane_verified = FALSE;
+    tls_out.tlsa_usage = 0;
+
+    dane_required = verify_check_this_host(&ob->hosts_require_dane, NULL,
+                             host->name, host->address, NULL) == OK;
+
+    if (host->dnssec == DS_YES)
+      {
+      if(  dane_required
+       || verify_check_this_host(&ob->hosts_try_dane, NULL,
+                             host->name, host->address, NULL) == OK
+       )
+       if ((rc = tlsa_lookup(host, &tlsa_dnsa, dane_required, &dane)) != OK)
+         return rc;
+      }
+    else if (dane_required)
+      {
+      log_write(0, LOG_MAIN, "DANE error: %s lookup not DNSSEC", host->name);
+      return FAIL;
+      }
+
+    if (dane)
+      ob->tls_tempfail_tryclear = FALSE;
+    }
+#endif /*DANE*/
+
   /* Expand the greeting message while waiting for the initial response. (Makes
   sense if helo_data contains ${lookup dnsdb ...} stuff). The expansion is
   delayed till here so that $sending_interface and $sending_port are set. */
@@ -1322,15 +1413,18 @@ if (continue_hostname == NULL)
     if (!smtp_read_response(&inblock, buffer, sizeof(buffer), '2',
       ob->command_timeout)) goto RESPONSE_FAILED;
 
-#ifdef EXPERIMENTAL_TPDA
-    if (tpda_raise_event(tblock->tpda_event_action, US"smtp:connect", buffer)
-       == DEFER)
+#ifdef EXPERIMENTAL_EVENT
+      {
+      uschar * s = event_raise(tblock->event_action, US"smtp:connect", buffer);
+      if (s)
        {
-       uschar *message = US"deferred by smtp:connect event expansion";
-       set_errno(addrlist, 0, message, DEFER, FALSE);
+       set_errno(addrlist, 0,
+         string_sprintf("deferred by smtp:connect event expansion: %s", s),
+         DEFER, FALSE, NULL);
        yield = DEFER;
        goto SEND_QUIT;
        }
+      }
 #endif
 
     /* Now check if the helo_data expansion went well, and sign off cleanly if
@@ -1340,7 +1434,7 @@ if (continue_hostname == NULL)
       {
       uschar *message = string_sprintf("failed to expand helo_data: %s",
         expand_string_message);
-      set_errno(addrlist, 0, message, DEFER, FALSE);
+      set_errno(addrlist, 0, message, DEFER, FALSE, NULL);
       yield = DEFER;
       goto SEND_QUIT;
       }
@@ -1505,7 +1599,11 @@ if (tls_offered && !suppress_tls &&
   else
   TLS_NEGOTIATE:
     {
-    int rc = tls_client_start(inblock.sock, host, addrlist, tblock);
+    int rc = tls_client_start(inblock.sock, host, addrlist, tblock
+# ifdef EXPERIMENTAL_DANE
+                            , dane ? &tlsa_dnsa : NULL
+# endif
+                            );
 
     /* TLS negotiation failed; give an error. From outside, this function may
     be called again to try in clear on a new connection, if the options permit
@@ -1522,7 +1620,6 @@ if (tls_offered && !suppress_tls &&
     /* TLS session is set up */
 
     for (addr = addrlist; addr != NULL; addr = addr->next)
-      {
       if (addr->transport_return == PENDING_DEFER)
         {
         addr->cipher = tls_out.cipher;
@@ -1531,7 +1628,6 @@ if (tls_offered && !suppress_tls &&
         addr->peerdn = tls_out.peerdn;
        addr->ocsp = tls_out.ocsp;
         }
-      }
     }
   }
 
@@ -1555,7 +1651,7 @@ if (tls_out.active >= 0)
       {
       uschar *message = string_sprintf("failed to expand helo_data: %s",
         expand_string_message);
-      set_errno(addrlist, 0, message, DEFER, FALSE);
+      set_errno(addrlist, 0, message, DEFER, FALSE, NULL);
       yield = DEFER;
       goto SEND_QUIT;
       }
@@ -1588,22 +1684,21 @@ if (tls_out.active >= 0)
 /* If the host is required to use a secure channel, ensure that we
 have one. */
 
-else if (  verify_check_this_host(&(ob->hosts_require_tls), NULL, host->name,
-            host->address, NULL) == OK
-#ifdef EXPERIMENTAL_DANE
-       || verify_check_this_host(&(ob->hosts_require_dane), NULL, host->name,
+else if (
+# ifdef EXPERIMENTAL_DANE
+       dane ||
+# endif
+        verify_check_this_host(&(ob->hosts_require_tls), NULL, host->name,
             host->address, NULL) == OK
-#endif
        )
   {
   save_errno = ERRNO_TLSREQUIRED;
-  message = string_sprintf("a TLS session is required for %s [%s], but %s",
-    host->name, host->address,
+  message = string_sprintf("a TLS session is required, but %s",
     tls_offered? "an attempt to start TLS failed" :
                  "the server did not offer TLS support");
   goto TLS_FAILED;
   }
-#endif
+#endif /*SUPPORT_TLS*/
 
 /* If TLS is active, we have just started it up and re-done the EHLO command,
 so its response needs to be analyzed. If TLS is not active and this is a
@@ -1699,7 +1794,7 @@ if (tblock->filter_command != NULL)
   if (!rc)
     {
     set_errno(addrlist->next, addrlist->basic_errno, addrlist->message, DEFER,
-      FALSE);
+      FALSE, NULL);
     yield = ERROR;
     goto SEND_QUIT;
     }
@@ -1948,7 +2043,7 @@ if (mua_wrapper)
   if (badaddr != NULL)
     {
     set_errno(addrlist, 0, badaddr->message, FAIL,
-      testflag(badaddr, af_pass_message));
+      testflag(badaddr, af_pass_message), NULL);
     ok = FALSE;
     }
   }
@@ -2126,7 +2221,7 @@ if (!ok) ok = TRUE; else
     /* Set up confirmation if needed - applies only to SMTP */
 
     if (
-#ifndef EXPERIMENTAL_TPDA
+#ifndef EXPERIMENTAL_EVENT
           (log_extra_selector & LX_smtp_confirmation) != 0 &&
 #endif
           !lmtp
@@ -2322,12 +2417,10 @@ if (!ok)
   if (setting_up)
     {
     if (code == '5')
-      {
-      set_errno(addrlist, save_errno, message, FAIL, pass_message);
-      }
+      set_errno(addrlist, save_errno, message, FAIL, pass_message, host);
     else
       {
-      set_errno(addrlist, save_errno, message, DEFER, pass_message);
+      set_errno(addrlist, save_errno, message, DEFER, pass_message, host);
       yield = DEFER;
       }
     }
@@ -2383,7 +2476,7 @@ if (!ok)
       {
       if (mua_wrapper) code = '5';  /* Force hard failure in wrapper mode */
       set_errno(addrlist, save_errno, message, (code == '5')? FAIL : DEFER,
-        pass_message);
+        pass_message, host);
 
       /* If there's an errno, the message contains just the identity of
       the host. */
@@ -2393,7 +2486,7 @@ if (!ok)
         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);
-        deliver_msglog("%s %s\n", tod_stamp(tod_log), message);
+       msglog_line(host, message);
         *message_defer = TRUE;
         }
       }
@@ -2408,7 +2501,7 @@ if (!ok)
       {
       yield = (save_errno == ERRNO_CHHEADER_FAIL ||
                save_errno == ERRNO_FILTER_FAIL)? ERROR : DEFER;
-      set_errno(addrlist, save_errno, message, DEFER, pass_message);
+      set_errno(addrlist, save_errno, message, DEFER, pass_message, host);
       }
     }
   }
@@ -2479,7 +2572,8 @@ if (completed_address && ok && send_quit)
           &pass_message);
         if (!send_quit)
           {
-          DEBUG(D_transport) debug_printf("%s\n", msg);
+          DEBUG(D_transport) debug_printf("H=%s [%s] %s\n",
+           host->name, host->address, msg);
           }
         }
       }
@@ -2525,7 +2619,7 @@ if (completed_address && ok && send_quit)
 
     /* If RSET failed and there are addresses left, they get deferred. */
 
-    else set_errno(first_addr, errno, msg, DEFER, FALSE);
+    else set_errno(first_addr, errno, msg, DEFER, FALSE, host);
     }
   }
 
@@ -2568,8 +2662,8 @@ case continue_more won't get set. */
 
 (void)close(inblock.sock);
 
-#ifdef EXPERIMENTAL_TPDA
-(void) tpda_raise_event(tblock->tpda_event_action, US"tcp:close", NULL);
+#ifdef EXPERIMENTAL_EVENT
+(void) event_raise(tblock->event_action, US"tcp:close", NULL);
 #endif
 
 continue_transport = NULL;
@@ -3205,7 +3299,7 @@ for (cutoff_retry = 0; expired &&
     if (dont_deliver)
       {
       host_item *host2;
-      set_errno(addrlist, 0, NULL, OK, FALSE);
+      set_errno(addrlist, 0, NULL, OK, FALSE, NULL);
       for (addr = addrlist; addr != NULL; addr = addr->next)
         {
         addr->host_used = host;
@@ -3279,9 +3373,9 @@ for (cutoff_retry = 0; expired &&
                          first_addr->basic_errno != ERRNO_TLSFAILURE)
         write_logs(first_addr, host);
 
-#ifdef EXPERIMENTAL_TPDA
+#ifdef EXPERIMENTAL_EVENT
       if (rc == DEFER)
-        tpda_deferred(first_addr, host);
+        deferred_event_raise(first_addr, host);
 #endif
 
       /* If STARTTLS was accepted, but there was a failure in setting up the
@@ -3299,10 +3393,6 @@ for (cutoff_retry = 0; expired &&
         && ob->tls_tempfail_tryclear
         && verify_check_this_host(&(ob->hosts_require_tls), NULL, host->name,
              host->address, NULL) != OK
-# ifdef EXPERIMENTAL_DANE
-        && verify_check_this_host(&(ob->hosts_require_dane), NULL, host->name,
-             host->address, NULL) != OK
-# endif
         )
         {
         log_write(0, LOG_MAIN, "TLS session failure: delivering unencrypted "
@@ -3312,9 +3402,9 @@ for (cutoff_retry = 0; expired &&
           expanded_hosts != NULL, &message_defer, TRUE);
         if (rc == DEFER && first_addr->basic_errno != ERRNO_AUTHFAIL)
           write_logs(first_addr, host);
-# ifdef EXPERIMENTAL_TPDA
+# ifdef EXPERIMENTAL_EVENT
         if (rc == DEFER)
-          tpda_deferred(first_addr, host);
+          deferred_event_raise(first_addr, host);
 # endif
         }
 #endif /*SUPPORT_TLS*/