TLS: rework error logging to pass more string back to caller for logging
[exim.git] / src / src / verify.c
index 6fef314fc848ac20632c847b8d8d56ce1becfc55..a152a8f2414a3aa5b9e2e6677158625283ec618e 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. */
 
 /* Functions concerned with verifying things. The original code for callout
@@ -682,18 +682,21 @@ tls_retry_connection:
     SMTP command to send.  If we tried TLS but it failed, try again without
     if permitted */
 
-    if (  (yield = smtp_setup_conn(&sx, FALSE)) == DEFER
+    yield = smtp_setup_conn(&sx, FALSE);
+#ifdef SUPPORT_TLS
+    if (  yield == DEFER
        && addr->basic_errno == ERRNO_TLSFAILURE
        && ob->tls_tempfail_tryclear
        && verify_check_given_host(&ob->hosts_require_tls, host) != OK
        )
       {
-      log_write(0, LOG_MAIN, "TLS session failure:"
-       " callout unencrypted to %s [%s] (not in hosts_require_tls)",
-       host->name, host->address);
+      log_write(0, LOG_MAIN,
+       "%s: callout unencrypted to %s [%s] (not in hosts_require_tls)",
+       addr->message, host->name, host->address);
       addr->transport_return = PENDING_DEFER;
       yield = smtp_setup_conn(&sx, TRUE);
       }
+#endif
     if (yield != OK)
       {
       errno = addr->basic_errno;
@@ -727,8 +730,7 @@ tls_retry_connection:
     sx.send_rset = TRUE;
     sx.completed_addr = FALSE;
 
-    new_domain_record.result =
-      old_domain_cache_result == ccache_reject_mfnull
+    new_domain_record.result = old_domain_cache_result == ccache_reject_mfnull
       ? ccache_reject_mfnull : ccache_accept;
 
     /* Do the random local part check first. Temporarily replace the recipient
@@ -778,6 +780,9 @@ tls_retry_connection:
       need another return code filtering out to here.
       */
 
+      /* Remember when we last did a random test */
+      new_domain_record.random_stamp = time(NULL);
+
       if (smtp_write_mail_and_rcpt_cmds(&sx, &yield) == 0)
        switch(addr->transport_return)
          {
@@ -798,25 +803,27 @@ tls_retry_connection:
              break;
 
            HDEBUG(D_acl|D_v)
-             debug_printf("problem after random/rset/mfrom; reopen conn\n");
+             debug_printf_indent("problem after random/rset/mfrom; reopen conn\n");
            random_local_part = NULL;
 #ifdef SUPPORT_TLS
            tls_close(FALSE, TRUE);
 #endif
-           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");
            (void)close(sx.inblock.sock);
            sx.inblock.sock = sx.outblock.sock = -1;
 #ifndef DISABLE_EVENT
            (void) event_raise(addr->transport->event_action,
                              US"tcp:close", NULL);
 #endif
+           addr->address = main_address;
+           addr->transport_return = PENDING_DEFER;
+           sx.first_addr = sx.sync_addr = addr;
+           sx.ok = FALSE;
+           sx.send_rset = TRUE;
+           sx.completed_addr = FALSE;
            goto tls_retry_connection;
          }
 
-      /* Remember when we last did a random test */
-
-      new_domain_record.random_stamp = time(NULL);
-
       /* Re-setup for main verify, or for the error message when failing */
       addr->address = main_address;
       addr->transport_return = PENDING_DEFER;
@@ -881,7 +888,7 @@ tls_retry_connection:
       for cutthrough.  But no way to handle a subsequent rcpt, so just
       refuse any */
       cancel_cutthrough_connection("postmaster verify");
-      HDEBUG(D_acl|D_v) debug_printf("Cutthrough cancelled by presence of postmaster verify\n");
+      HDEBUG(D_acl|D_v) debug_printf_indent("Cutthrough cancelled by presence of postmaster verify\n");
 
       done = smtp_write_command(&sx.outblock, FALSE, "RSET\r\n") >= 0
           && smtp_read_response(&sx.inblock, sx.buffer,
@@ -1009,7 +1016,7 @@ no_conn:
        && !sx.lmtp
        )
       {
-      HDEBUG(D_acl|D_v) debug_printf("holding verify callout open for cutthrough delivery\n");
+      HDEBUG(D_acl|D_v) debug_printf_indent("holding verify callout open for cutthrough delivery\n");
 
       cutthrough.fd = sx.outblock.sock;        /* We assume no buffer in use in the outblock */
       cutthrough.nrcpt = 1;
@@ -1046,7 +1053,7 @@ no_conn:
 #ifdef SUPPORT_TLS
        tls_close(FALSE, TRUE);
 #endif
-       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");
        (void)close(sx.inblock.sock);
        sx.inblock.sock = sx.outblock.sock = -1;
 #ifndef DISABLE_EVENT
@@ -1123,7 +1130,7 @@ int rc;
 get rewritten. */
 
 addr2 = *addr;
-HDEBUG(D_acl) debug_printf("----------- %s cutthrough setup ------------\n",
+HDEBUG(D_acl) debug_printf_indent("----------- %s cutthrough setup ------------\n",
   rcpt_count > 1 ? "more" : "start");
 rc = verify_address(&addr2, NULL,
        vopt_is_recipient | vopt_callout_recipsender | vopt_callout_no_cache,
@@ -1131,7 +1138,7 @@ rc = verify_address(&addr2, NULL,
        NULL, NULL, NULL);
 addr->message = addr2.message;
 addr->user_message = addr2.user_message;
-HDEBUG(D_acl) debug_printf("----------- end cutthrough setup ------------\n");
+HDEBUG(D_acl) debug_printf_indent("----------- end cutthrough setup ------------\n");
 return rc;
 }
 
@@ -1156,7 +1163,7 @@ if(
   return TRUE;
 }
 
-HDEBUG(D_transport|D_acl) debug_printf("cutthrough_send failed: %s\n", strerror(errno));
+HDEBUG(D_transport|D_acl) debug_printf_indent("cutthrough_send failed: %s\n", strerror(errno));
 return FALSE;
 }
 
@@ -1254,7 +1261,7 @@ cutthrough_predata(void)
 if(cutthrough.fd < 0)
   return FALSE;
 
-HDEBUG(D_transport|D_acl|D_v) debug_printf("  SMTP>> DATA\n");
+HDEBUG(D_transport|D_acl|D_v) debug_printf_indent("  SMTP>> DATA\n");
 cutthrough_puts(US"DATA\r\n", 6);
 cutthrough_flush_send();
 
@@ -1292,7 +1299,7 @@ if(cutthrough.fd < 0)
 /* We share a routine with the mainline transport to handle header add/remove/rewrites,
    but having a separate buffered-output function (for now)
 */
-HDEBUG(D_acl) debug_printf("----------- start cutthrough headers send -----------\n");
+HDEBUG(D_acl) debug_printf_indent("----------- start cutthrough headers send -----------\n");
 
 tctx.tblock = cutthrough.addr.transport;
 tctx.addr = &cutthrough.addr;
@@ -1303,7 +1310,7 @@ tctx.options = topt_use_crlf;
 if (!transport_headers_send(cutthrough.fd, &tctx, &cutthrough_write_chunk))
   return FALSE;
 
-HDEBUG(D_acl) debug_printf("----------- done cutthrough headers send ------------\n");
+HDEBUG(D_acl) debug_printf_indent("----------- done cutthrough headers send ------------\n");
 return TRUE;
 }
 
@@ -1318,7 +1325,7 @@ if(cutthrough.fd >= 0)
      conn before the final dot.
   */
   ctblock.ptr = ctbuffer;
-  HDEBUG(D_transport|D_acl|D_v) debug_printf("  SMTP>> QUIT\n");
+  HDEBUG(D_transport|D_acl|D_v) debug_printf_indent("  SMTP>> QUIT\n");
   _cutthrough_puts(US"QUIT\r\n", 6);   /* avoid recursion */
   _cutthrough_flush_send();
 
@@ -1328,10 +1335,10 @@ if(cutthrough.fd >= 0)
   #ifdef SUPPORT_TLS
   tls_close(FALSE, TRUE);
   #endif
-  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");
   (void)close(cutthrough.fd);
   cutthrough.fd = -1;
-  HDEBUG(D_acl) debug_printf("----------- cutthrough shutdown (%s) ------------\n", why);
+  HDEBUG(D_acl) debug_printf_indent("----------- cutthrough shutdown (%s) ------------\n", why);
   }
 ctblock.ptr = ctbuffer;
 }
@@ -1356,7 +1363,7 @@ cutthrough_finaldot(void)
 {
 uschar res;
 address_item * addr;
-HDEBUG(D_transport|D_acl|D_v) debug_printf("  SMTP>> .\n");
+HDEBUG(D_transport|D_acl|D_v) debug_printf_indent("  SMTP>> .\n");
 
 /* Assume data finshed with new-line */
 if(  !cutthrough_puts(US".", 1)