Debug: build a summary string tracking transport SMTP commands & responses
[exim.git] / src / src / transports / smtp.c
index 721056f278978bf5aa30b3471e53ff33d032e855..e38ea1502dbc8fc21e83a3bface4f7ea1178d8e8 100644 (file)
@@ -678,7 +678,8 @@ deliver_localpart = addr->local_part;
        : string_copy(addr->message)
       : addr->basic_errno > 0
        ? string_copy(US strerror(addr->basic_errno))
-       : NULL);
+       : NULL,
+      NULL);
 
 deliver_localpart = save_local;
 deliver_domain =    save_domain;
@@ -751,7 +752,7 @@ sx->helo_response = string_copy(sx->buffer);
 #endif
 #ifndef DISABLE_EVENT
 (void) event_raise(sx->conn_args.tblock->event_action,
-  US"smtp:ehlo", sx->buffer);
+  US"smtp:ehlo", sx->buffer, NULL);
 #endif
 return TRUE;
 }
@@ -1432,10 +1433,17 @@ smtp_transport_options_block * ob = sx->conn_args.ob;   /* transport options */
 host_item * host = sx->conn_args.host;                 /* host to deliver to */
 int rc;
 
+/* Set up globals for error messages */
+
+authenticator_name = au->name;
+driver_srcfile = au->srcfile;
+driver_srcline = au->srcline;
+
 sx->outblock.authenticating = TRUE;
 rc = (au->info->clientcode)(au, sx, ob->command_timeout,
                            sx->buffer, sizeof(sx->buffer));
 sx->outblock.authenticating = FALSE;
+driver_srcfile = authenticator_name = NULL; driver_srcline = 0;
 DEBUG(D_transport) debug_printf("%s authenticator yielded %d\n", au->name, rc);
 
 /* A temporary authentication failure must hold up delivery to
@@ -2014,44 +2022,31 @@ int yield = OK;
 uschar * tls_errstr;
 #endif
 
+/* Many lines of clearing individual elements of *sx that used to
+be here have been replaced by a full memset to zero (de41aff051).
+There are two callers, this file and verify.c .  Now we only set
+up nonzero elements. */
+
 sx->conn_args.ob = ob;
 
 sx->lmtp = strcmpic(ob->protocol, US"lmtp") == 0;
 sx->smtps = strcmpic(ob->protocol, US"smtps") == 0;
-/* sx->ok = FALSE; */
 sx->send_rset = TRUE;
 sx->send_quit = TRUE;
 sx->setting_up = TRUE;
 sx->esmtp = TRUE;
-/* sx->esmtp_sent = FALSE; */
-#ifdef SUPPORT_I18N
-/* sx->utf8_needed = FALSE; */
-#endif
 sx->dsn_all_lasthop = TRUE;
 #ifdef SUPPORT_DANE
-/* sx->conn_args.dane = FALSE; */
 sx->dane_required =
   verify_check_given_host(CUSS &ob->hosts_require_dane, sx->conn_args.host) == OK;
 #endif
-#ifndef DISABLE_PIPE_CONNECT
-/* sx->early_pipe_active = sx->early_pipe_ok = FALSE; */
-/* sx->ehlo_resp.cleartext_features = sx->ehlo_resp.crypted_features = 0; */
-/* sx->pending_BANNER = sx->pending_EHLO = sx->pending_MAIL = FALSE; */
-#endif
 
 if ((sx->max_mail = sx->conn_args.tblock->connection_max_messages) == 0) sx->max_mail = 999999;
 if ((sx->max_rcpt = sx->conn_args.tblock->max_addresses) == 0)           sx->max_rcpt = 999999;
-/* sx->peer_offered = 0; */
-/* sx->avoid_option = 0; */
 sx->igquotstr = US"";
 if (!sx->helo_data) sx->helo_data = ob->helo_data;
-#ifdef EXPERIMENTAL_DSN_INFO
-/* sx->smtp_greeting = NULL; */
-/* sx->helo_response = NULL; */
-#endif
 
 smtp_command = US"initial connection";
-/* sx->buffer[0] = '\0'; */
 
 /* Set up the buffer for reading SMTP response packets. */
 
@@ -2065,9 +2060,6 @@ sx->inblock.ptrend = sx->inbuffer;
 sx->outblock.buffer = sx->outbuffer;
 sx->outblock.buffersize = sizeof(sx->outbuffer);
 sx->outblock.ptr = sx->outbuffer;
-/* sx->outblock.cmd_count = 0; */
-/* sx->outblock.authenticating = FALSE; */
-/* sx->outblock.conn_args = NULL; */
 
 /* Reset the parameters of a TLS session. */
 
@@ -2131,7 +2123,8 @@ if (continue_hostname && continue_proxy_cipher)
 #  ifndef DISABLE_EVENT
                            (void) event_raise(sx->conn_args.tblock->event_action,
                              US"dane:fail", sx->dane_required
-                               ?  US"dane-required" : US"dnssec-invalid");
+                               ?  US"dane-required" : US"dnssec-invalid",
+                             NULL);
 #  endif
                            return rc;
       }
@@ -2162,7 +2155,7 @@ if (continue_hostname && continue_proxy_cipher)
     DEBUG(D_transport)
       debug_printf("Closing proxied-TLS connection due to SNI mismatch\n");
 
-    HDEBUG(D_transport|D_acl|D_v) debug_printf_indent("  SMTP>> QUIT\n");
+    smtp_debug_cmd(US"QUIT", 0);
     write(0, "QUIT\r\n", 6);
     close(0);
     continue_hostname = continue_proxy_cipher = NULL;
@@ -2218,7 +2211,8 @@ if (!continue_hostname)
 # ifndef DISABLE_EVENT
                                (void) event_raise(sx->conn_args.tblock->event_action,
                                  US"dane:fail", sx->dane_required
-                                   ?  US"dane-required" : US"dnssec-invalid");
+                                   ?  US"dane-required" : US"dnssec-invalid",
+                                 NULL);
 # endif
                                return rc;
          }
@@ -2230,7 +2224,7 @@ if (!continue_hostname)
        FAIL, FALSE, &sx->delivery_start);
 # ifndef DISABLE_EVENT
       (void) event_raise(sx->conn_args.tblock->event_action,
-       US"dane:fail", US"dane-required");
+       US"dane:fail", US"dane-required", NULL);
 # endif
       return FAIL;
       }
@@ -2245,6 +2239,9 @@ if (!continue_hostname)
   sx->peer_limit_mail = sx->peer_limit_rcpt = sx->peer_limit_rcptdom =
 #endif
   sx->avoid_option = sx->peer_offered = smtp_peer_options = 0;
+#ifndef DISABLE_CLIENT_CMD_LOG
+  client_cmd_log = NULL;
+#endif
 
 #ifndef DISABLE_PIPE_CONNECT
   if (  verify_check_given_host(CUSS &ob->hosts_pipe_connect,
@@ -2349,7 +2346,7 @@ will be?  Somehow I doubt it. */
       uschar * s;
       lookup_dnssec_authenticated = sx->conn_args.host->dnssec==DS_YES ? US"yes"
        : sx->conn_args.host->dnssec==DS_NO ? US"no" : NULL;
-      s = event_raise(sx->conn_args.tblock->event_action, US"smtp:connect", sx->buffer);
+      s = event_raise(sx->conn_args.tblock->event_action, US"smtp:connect", sx->buffer, NULL);
       if (s)
        {
        set_errno_nohost(sx->addrlist, ERRNO_EXPANDFAIL,
@@ -2686,7 +2683,7 @@ if (  smtp_peer_options & OPTION_TLS
          sx->conn_args.host->name, sx->conn_args.host->address, tls_errstr);
 #  ifndef DISABLE_EVENT
        (void) event_raise(sx->conn_args.tblock->event_action,
-         US"dane:fail", US"validation-failure");       /* could do with better detail */
+         US"dane:fail", US"validation-failure", NULL); /* could do with better detail */
 #  endif
        }
 # endif
@@ -2854,7 +2851,8 @@ else if (  sx->smtps
     (void) event_raise(sx->conn_args.tblock->event_action, US"dane:fail",
       smtp_peer_options & OPTION_TLS
       ? US"validation-failure"         /* could do with better detail */
-      : US"starttls-not-supported");
+      : US"starttls-not-supported",
+      NULL);
 # endif
   goto TLS_FAILED;
   }
@@ -3172,9 +3170,10 @@ if (sx->send_quit)
 sx->cctx.sock = -1;
 
 #ifndef DISABLE_EVENT
-(void) event_raise(sx->conn_args.tblock->event_action, US"tcp:close", NULL);
+(void) event_raise(sx->conn_args.tblock->event_action, US"tcp:close", NULL, NULL);
 #endif
 
+smtp_debug_cmd_report();
 continue_transport = NULL;
 continue_hostname = NULL;
 return yield;
@@ -3697,7 +3696,7 @@ int rc;
 
 uschar *message = NULL;
 uschar new_message_id[MESSAGE_ID_LENGTH + 1];
-smtp_context * sx = store_get(sizeof(*sx), TRUE);      /* tainted, for the data buffers */
+smtp_context * sx = store_get(sizeof(*sx), GET_TAINTED);       /* tainted, for the data buffers */
 BOOL pass_message = FALSE;
 #ifdef EXPERIMENTAL_ESMTP_LIMITS
 BOOL mail_limit = FALSE;
@@ -3712,12 +3711,11 @@ BOOL tcw_done = FALSE, tcw = FALSE;
 memset(sx, 0, sizeof(*sx));
 sx->addrlist = addrlist;
 sx->conn_args.host = host;
-sx->conn_args.host_af = host_af,
+sx->conn_args.host_af = host_af;
 sx->port = defport;
 sx->conn_args.interface = interface;
 sx->helo_data = NULL;
 sx->conn_args.tblock = tblock;
-/* sx->verify = FALSE; */
 gettimeofday(&sx->delivery_start, NULL);
 sx->sync_addr = sx->first_addr = addrlist;
 
@@ -3768,7 +3766,7 @@ if (tblock->filter_command)
 
   if (!transport_set_up_command(&transport_filter_argv,
        tblock->filter_command, TRUE, DEFER, addrlist,
-       string_sprintf("%.50s transport", tblock->name), NULL))
+       string_sprintf("%.50s transport filter", tblock->name), NULL))
     {
     set_errno_nohost(addrlist->next, addrlist->basic_errno, addrlist->message, DEFER,
       FALSE, &sx->delivery_start);
@@ -4091,7 +4089,7 @@ else
       sx->send_quit = FALSE;   /* avoid sending it later */
 
 #ifndef DISABLE_TLS
-      if (sx->cctx.tls_ctx)    /* need to send TLS Close Notify */
+      if (sx->cctx.tls_ctx && sx->send_tlsclose)       /* need to send TLS Close Notify */
        {
 # ifdef EXIM_TCP_CORK          /* Use _CORK to get Close Notify in FIN segment */
        (void) setsockopt(sx->cctx.sock, IPPROTO_TCP, EXIM_TCP_CORK, US &on, sizeof(on));
@@ -4435,7 +4433,8 @@ if (!sx->ok)
 # ifndef DISABLE_TLS
        if (sx->cctx.tls_ctx)
          {
-         tls_close(sx->cctx.tls_ctx, TLS_SHUTDOWN_WAIT);
+         tls_close(sx->cctx.tls_ctx,
+                   sx->send_tlsclose ? TLS_SHUTDOWN_WAIT : TLS_SHUTDOWN_WONLY);
          sx->cctx.tls_ctx = NULL;
          }
 # endif
@@ -4646,7 +4645,8 @@ if (sx->completed_addr && sx->ok && sx->send_quit)
            a new EHLO. If we don't get a good response, we don't attempt to pass
            the socket on. */
 
-         tls_close(sx->cctx.tls_ctx, TLS_SHUTDOWN_WAIT);
+         tls_close(sx->cctx.tls_ctx,
+           sx->send_tlsclose ? TLS_SHUTDOWN_WAIT : TLS_SHUTDOWN_WONLY);
          sx->send_tlsclose = FALSE;
          sx->cctx.tls_ctx = NULL;
          tls_out.active.sock = -1;
@@ -4748,7 +4748,7 @@ if (sx->send_quit)
   {                    /* Use _MORE to get QUIT in FIN segment */
   (void)smtp_write_command(sx, SCMD_MORE, "QUIT\r\n");
 #ifndef DISABLE_TLS
-  if (sx->cctx.tls_ctx)
+  if (sx->cctx.tls_ctx && sx->send_tlsclose)
     {
 # ifdef EXIM_TCP_CORK  /* Use _CORK to get TLS Close Notify in FIN segment */
     (void) setsockopt(sx->cctx.sock, IPPROTO_TCP, EXIM_TCP_CORK, US &on, sizeof(on));
@@ -4803,10 +4803,15 @@ if (sx->send_quit || tcw_done && !tcw)
     while (!sigalrm_seen && n > 0);
     ALARM_CLR(0);
 
+    if (sx->send_tlsclose)
+      {
 # ifdef EXIM_TCP_CORK
-    (void) setsockopt(sx->cctx.sock, IPPROTO_TCP, EXIM_TCP_CORK, US &on, sizeof(on));
+      (void) setsockopt(sx->cctx.sock, IPPROTO_TCP, EXIM_TCP_CORK, US &on, sizeof(on));
 # endif
-    tls_close(sx->cctx.tls_ctx, TLS_SHUTDOWN_WAIT);
+      tls_close(sx->cctx.tls_ctx, TLS_SHUTDOWN_WAIT);
+      }
+    else
+      tls_close(sx->cctx.tls_ctx, TLS_SHUTDOWN_WONLY);
     sx->cctx.tls_ctx = NULL;
     }
 #endif
@@ -4830,9 +4835,10 @@ HDEBUG(D_transport|D_acl|D_v) debug_printf_indent("  SMTP(close)>>\n");
 sx->cctx.sock = -1;
 continue_transport = NULL;
 continue_hostname = NULL;
+smtp_debug_cmd_report();
 
 #ifndef DISABLE_EVENT
-(void) event_raise(tblock->event_action, US"tcp:close", NULL);
+(void) event_raise(tblock->event_action, US"tcp:close", NULL, NULL);
 #endif
 
 #ifdef SUPPORT_DANE
@@ -5103,8 +5109,11 @@ if (!hostlist || (ob->hosts_override && ob->hosts))
     else
       if (ob->hosts_randomize) s = expanded_hosts = string_copy(s);
 
-    if (is_tainted2(s, LOG_MAIN|LOG_PANIC, "Tainted host list '%s' from '%s' in transport %s", s, ob->hosts, tblock->name))
+    if (is_tainted(s))
       {
+      log_write(0, LOG_MAIN|LOG_PANIC,
+       "attempt to use tainted host list '%s' from '%s' in transport %s",
+       s, ob->hosts, tblock->name);
       /* Avoid leaking info to an attacker */
       addrlist->message = US"internal configuration error";
       addrlist->transport_return = PANIC;
@@ -5601,7 +5610,7 @@ retry_non_continued:
 
       if (expanded_hosts)
        {
-       thost = store_get(sizeof(host_item), FALSE);
+       thost = store_get(sizeof(host_item), GET_UNTAINTED);
        *thost = *host;
        thost->name = string_copy(host->name);
        thost->address = string_copy(host->address);