DKIM: rework error logging to pass strings back to caller for logging. Bug 966
[exim.git] / src / src / transports / smtp.c
index 95bee582d104c2db141496ba4b1e5c346585d1c9..90ec87b301c06558dd30a2b62e20f3b1a54f865b 100644 (file)
@@ -2,7 +2,7 @@
 *     Exim - an Internet mail transport agent    *
 *************************************************/
 
-/* Copyright (c) University of Cambridge 1995 - 2016 */
+/* Copyright (c) University of Cambridge 1995 - 2017 */
 /* See the file NOTICE for conditions of use and distribution. */
 
 #include "../exim.h"
@@ -583,7 +583,8 @@ if (*errno_value == 0 || *errno_value == ECONNRESET)
   *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);
+else
+  *message = US string_sprintf("%s [%s]", host->name, host->address);
 
 return FALSE;
 }
@@ -1408,7 +1409,7 @@ if (sx->pending_BDAT)
     if (errno == 0 && sx->buffer[0] == '4')
       {
       errno = ERRNO_DATA4XX;   /*XXX does this actually get used? */
-      sx->first_addr->more_errno |=
+      sx->addrlist->more_errno |=
        ((sx->buffer[1] - '0')*10 + sx->buffer[2] - '0') << 8;
       }
     return ERROR;
@@ -1453,9 +1454,7 @@ smtp_setup_conn(smtp_context * sx, BOOL suppress_tls)
 dns_answer tlsa_dnsa;
 #endif
 BOOL pass_message = FALSE;
-
 uschar * message = NULL;
-int save_errno;
 int yield = OK;
 int rc;
 
@@ -1550,14 +1549,13 @@ if (continue_hostname == NULL)
   if (sx->inblock.sock < 0)
     {
     uschar * msg = NULL;
-    int save_errno = errno;
     if (sx->verify)
       {
-      msg = strerror(errno);
+      msg = US strerror(errno);
       HDEBUG(D_verify) debug_printf("connect: %s\n", msg);
       }
     set_errno_nohost(sx->addrlist,
-      save_errno == ETIMEDOUT ? ERRNO_CONNECTTIMEOUT : save_errno,
+      errno == ETIMEDOUT ? ERRNO_CONNECTTIMEOUT : errno,
       sx->verify ? string_sprintf("could not connect: %s", msg)
             : NULL,
       DEFER, FALSE);
@@ -1774,12 +1772,8 @@ goto SEND_QUIT;
 
       if (rsp != sx->buffer && rsp[0] == 0 && (errno == 0 || errno == ECONNRESET))
        {
-       sx->send_quit = FALSE;
-       save_errno = ERRNO_SMTPCLOSED;
-       message = string_sprintf("Remote host closed connection "
-             "in response to %s (EHLO response was: %s)",
-             smtp_command, sx->buffer);
-       goto FAILED;
+       errno = ERRNO_SMTPCLOSED;
+       goto EHLOHELO_FAILED;
        }
       Ustrncpy(sx->buffer, rsp, sizeof(sx->buffer)/2);
       goto RESPONSE_FAILED;
@@ -1858,6 +1852,7 @@ if (  smtp_peer_options & PEER_OFFERED_TLS
        )
       {
       Ustrncpy(sx->buffer, buffer2, sizeof(sx->buffer));
+      sx->buffer[sizeof(sx->buffer)-1] = '\0';
       goto RESPONSE_FAILED;
       }
     }
@@ -1868,11 +1863,12 @@ if (  smtp_peer_options & PEER_OFFERED_TLS
   TLS_NEGOTIATE:
     {
     address_item * addr;
-    int rc = tls_client_start(sx->inblock.sock, sx->host, sx->addrlist, sx->tblock
+    uschar * errstr;
+    int rc = tls_client_start(sx->inblock.sock, sx->host, sx->addrlist, sx->tblock,
 # ifdef EXPERIMENTAL_DANE
-                            , sx->dane ? &tlsa_dnsa : NULL
+                            sx->dane ? &tlsa_dnsa : NULL,
 # endif
-                            );
+                            &errstr);
 
     /* 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
@@ -1882,12 +1878,12 @@ if (  smtp_peer_options & PEER_OFFERED_TLS
       {
 # ifdef EXPERIMENTAL_DANE
       if (sx->dane) log_write(0, LOG_MAIN,
-         "DANE attempt failed; no TLS connection to %s [%s]",
-         sx->host->name, sx->host->address);
+         "DANE attempt failed; TLS connection to %s [%s]: %s",
+         sx->host->name, sx->host->address, errstr);
 # endif
 
-      save_errno = ERRNO_TLSFAILURE;
-      message = US"failure while setting up TLS session";
+      errno = ERRNO_TLSFAILURE;
+      message = string_sprintf("TLS session: %s", errstr);
       sx->send_quit = FALSE;
       goto TLS_FAILED;
       }
@@ -1973,7 +1969,7 @@ else if (  sx->smtps
        || verify_check_given_host(&sx->ob->hosts_require_tls, sx->host) == OK
        )
   {
-  save_errno = ERRNO_TLSREQUIRED;
+  errno = ERRNO_TLSREQUIRED;
   message = string_sprintf("a TLS session is required, but %s",
     smtp_peer_options & PEER_OFFERED_TLS
     ? "an attempt to start TLS failed" : "the server did not offer TLS support");
@@ -2096,35 +2092,36 @@ return OK;
 
   {
   int code;
-  uschar * set_message;
 
   RESPONSE_FAILED:
-    {
-    save_errno = errno;
     message = NULL;
-    sx->send_quit = check_response(sx->host, &save_errno, sx->addrlist->more_errno,
+    sx->send_quit = check_response(sx->host, &errno, sx->addrlist->more_errno,
       sx->buffer, &code, &message, &pass_message);
     goto FAILED;
-    }
 
   SEND_FAILED:
-    {
-    save_errno = errno;
     code = '4';
     message = US string_sprintf("send() to %s [%s] failed: %s",
-      sx->host->name, sx->host->address, strerror(save_errno));
+      sx->host->name, sx->host->address, strerror(errno));
     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 save_errno, and setting_up will always be true. Treat as
+  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"
+      " (EHLO response was: %s)", smtp_command, sx->buffer);
+    sx->send_quit = FALSE;
+    goto FAILED;
+
 #ifdef SUPPORT_TLS
   TLS_FAILED:
-  code = '4';
+    code = '4';
+    goto FAILED;
 #endif
 
   /* The failure happened while setting up the call; see if the failure was
@@ -2134,9 +2131,8 @@ return OK;
   whatever), defer all addresses, and yield DEFER, so that the host is not
   tried again for a while. */
 
-  FAILED:
+FAILED:
   sx->ok = FALSE;                /* For when reached by GOTO */
-  set_message = message;
 
   yield = code == '5'
 #ifdef SUPPORT_I18N
@@ -2144,7 +2140,7 @@ return OK;
 #endif
     ? FAIL : DEFER;
 
-  set_errno(sx->addrlist, save_errno, set_message, yield, pass_message, sx->host
+  set_errno(sx->addrlist, errno, message, yield, pass_message, sx->host
 #ifdef EXPERIMENTAL_DSN_INFO
            , sx->smtp_greeting, sx->helo_response
 #endif
@@ -2171,7 +2167,7 @@ writing RSET might have failed, or there may be other addresses whose hosts are
 specified in the transports, and therefore not visible at top level, in which
 case continue_more won't get set. */
 
-HDEBUG(D_transport|D_acl|D_v) debug_printf("  SMTP(close)>>\n");
+HDEBUG(D_transport|D_acl|D_v) debug_printf_indent("  SMTP(close)>>\n");
 if (sx->send_quit)
   {
   shutdown(sx->outblock.sock, SHUT_WR);
@@ -2749,7 +2745,8 @@ else
   transport_count = 0;
 
 #ifndef DISABLE_DKIM
-  sx.ok = dkim_transport_write_message(sx.inblock.sock, &tctx, &sx.ob->dkim);
+  sx.ok = dkim_transport_write_message(sx.inblock.sock, &tctx, &sx.ob->dkim,
+           CUSS &message);
 #else
   sx.ok = transport_write_message(sx.inblock.sock, &tctx, 0);
 #endif
@@ -2766,7 +2763,8 @@ else
   Or, when CHUNKING, it can be a protocol-detected failure. */
 
   if (!sx.ok)
-    goto RESPONSE_FAILED;
+    if (message) goto SEND_FAILED;
+    else         goto RESPONSE_FAILED;
 
   /* We used to send the terminating "." explicitly here, but because of
   buffering effects at both ends of TCP/IP connections, you don't gain
@@ -3031,8 +3029,8 @@ if (!sx.ok)
     {
     save_errno = errno;
     code = '4';
-    message = US string_sprintf("send() to %s [%s] failed: %s",
-      host->name, host->address, strerror(save_errno));
+    message = string_sprintf("send() to %s [%s] failed: %s",
+      host->name, host->address, message ? message : strerror(save_errno));
     sx.send_quit = FALSE;
     goto FAILED;
     }
@@ -3189,7 +3187,7 @@ if (sx.completed_addr && sx.ok && sx.send_quit)
       if (! (sx.ok = smtp_write_command(&sx.outblock, FALSE, "RSET\r\n") >= 0))
         {
         msg = US string_sprintf("send() to %s [%s] failed: %s", host->name,
-          host->address, strerror(save_errno));
+          host->address, strerror(errno));
         sx.send_quit = FALSE;
         }
       else if (! (sx.ok = smtp_read_response(&sx.inblock, sx.buffer,
@@ -3292,7 +3290,7 @@ writing RSET might have failed, or there may be other addresses whose hosts are
 specified in the transports, and therefore not visible at top level, in which
 case continue_more won't get set. */
 
-HDEBUG(D_transport|D_acl|D_v) debug_printf("  SMTP(close)>>\n");
+HDEBUG(D_transport|D_acl|D_v) debug_printf_indent("  SMTP(close)>>\n");
 if (sx.send_quit)
   {
   shutdown(sx.outblock.sock, SHUT_WR);
@@ -3722,7 +3720,7 @@ for (cutoff_retry = 0;
       commonly points to a configuration error, but the best action is still
       to carry on for the next host. */
 
-      if (rc == HOST_FIND_AGAIN || rc == HOST_FIND_FAILED)
+      if (rc == HOST_FIND_AGAIN || rc == HOST_FIND_SECURITY || rc == HOST_FIND_FAILED)
         {
         retry_add_item(addrlist, string_sprintf("R:%s", host->name), 0);
         expired = FALSE;
@@ -3735,8 +3733,11 @@ for (cutoff_retry = 0;
           {
           if (addr->transport_return != DEFER) continue;
           addr->basic_errno = ERRNO_UNKNOWNHOST;
-          addr->message =
-            string_sprintf("failed to lookup IP address for %s", host->name);
+          addr->message = string_sprintf(
+           rc == HOST_FIND_SECURITY
+             ? "lookup of IP address for %s was insecure"
+             : "failed to lookup IP address for %s",
+           host->name);
           }
         continue;
         }
@@ -3875,6 +3876,7 @@ for (cutoff_retry = 0;
            {
            case hwhy_retry: hosts_retry++; break;
            case hwhy_failed:  hosts_fail++; break;
+           case hwhy_insecure:
            case hwhy_deferred: hosts_defer++; break;
            }
 
@@ -4058,8 +4060,9 @@ for (cutoff_retry = 0;
         && verify_check_given_host(&ob->hosts_require_tls, host) != OK
         )
         {
-        log_write(0, LOG_MAIN, "TLS session failure: delivering unencrypted "
-          "to %s [%s] (not in hosts_require_tls)", host->name, host->address);
+        log_write(0, LOG_MAIN,
+         "%s: delivering unencrypted to H=%s [%s] (not in hosts_require_tls)",
+         first_addr->message, host->name, host->address);
         first_addr = prepare_addresses(addrlist, host);
         rc = smtp_deliver(addrlist, thost, host_af, port, interface, tblock,
           &message_defer, TRUE);