Header-wrap expansion. Bug 2843
[exim.git] / src / src / smtp_in.c
index 3fe3dab82700acdebf162ac634795f56140465c8..a13af867aaa2c010b80c0a04e3eb81dc588c7f2d 100644 (file)
@@ -2,9 +2,10 @@
 *     Exim - an Internet mail transport agent    *
 *************************************************/
 
+/* Copyright (c) The Exim Maintainers 2020 - 2022 */
 /* Copyright (c) University of Cambridge 1995 - 2018 */
-/* Copyright (c) The Exim Maintainers 2020 - 2021 */
 /* See the file NOTICE for conditions of use and distribution. */
+/* SPDX-License-Identifier: GPL-2.0-or-later */
 
 /* Functions for handling an incoming SMTP call. */
 
@@ -332,7 +333,7 @@ Returns:    nothing
 */
 
 static void
-incomplete_transaction_log(uschar *what)
+incomplete_transaction_log(uschar * what)
 {
 if (!sender_address                            /* No transaction in progress */
    || !LOGGING(smtp_incomplete_transaction))
@@ -354,13 +355,21 @@ log_write(L_smtp_incomplete_transaction, LOG_MAIN|LOG_SENDER|LOG_RECIPIENTS,
 
 
 
+static void
+log_close_event(const uschar * reason)
+{
+log_write(L_smtp_connection, LOG_MAIN, "%s D=%s closed %s",
+  smtp_get_connection_info(), string_timesince(&smtp_connection_start), reason);
+}
+
 
 void
 smtp_command_timeout_exit(void)
 {
 log_write(L_lost_incoming_connection,
-         LOG_MAIN, "SMTP command timeout on%s connection from %s",
-         tls_in.active.sock >= 0 ? " TLS" : "", host_and_ident(FALSE));
+         LOG_MAIN, "SMTP command timeout on%s connection from %s D=%s",
+         tls_in.active.sock >= 0 ? " TLS" : "", host_and_ident(FALSE),
+         string_timesince(&smtp_connection_start));
 if (smtp_batched_input)
   moan_smtp_batch(NULL, "421 SMTP command timeout"); /* Does not return */
 smtp_notquit_exit(US"command-timeout", US"421",
@@ -372,7 +381,7 @@ exim_exit(EXIT_FAILURE);
 void
 smtp_command_sigterm_exit(void)
 {
-log_write(0, LOG_MAIN, "%s closed after SIGTERM", smtp_get_connection_info());
+log_close_event(US"after SIGTERM");
 if (smtp_batched_input)
   moan_smtp_batch(NULL, "421 SIGTERM received");  /* Does not return */
 smtp_notquit_exit(US"signal-exit", US"421",
@@ -383,9 +392,10 @@ exim_exit(EXIT_FAILURE);
 void
 smtp_data_timeout_exit(void)
 {
-log_write(L_lost_incoming_connection,
-  LOG_MAIN, "SMTP data timeout (message abandoned) on connection from %s F=<%s>",
-  sender_fullhost ? sender_fullhost : US"local process", sender_address);
+log_write(L_lost_incoming_connection, LOG_MAIN,
+  "SMTP data timeout (message abandoned) on connection from %s F=<%s> D=%s",
+  sender_fullhost ? sender_fullhost : US"local process", sender_address,
+  string_timesince(&smtp_connection_start));
 receive_bomb_out(US"data-timeout", US"SMTP incoming data timeout");
 /* Does not return */
 }
@@ -393,8 +403,7 @@ receive_bomb_out(US"data-timeout", US"SMTP incoming data timeout");
 void
 smtp_data_sigint_exit(void)
 {
-log_write(0, LOG_MAIN, "%s closed after %s",
-  smtp_get_connection_info(), had_data_sigint == SIGTERM ? "SIGTERM":"SIGINT");
+log_close_event(had_data_sigint == SIGTERM ? US"SIGTERM":US"SIGINT");
 receive_bomb_out(US"signal-exit",
   US"Service not available - SIGTERM or SIGINT received");
 /* Does not return */
@@ -840,12 +849,8 @@ while (chunking_data_left)
   }
 
 bdat_pop_receive_functions();
-
-if (chunking_state != CHUNKING_LAST)
-  {
-  chunking_state = CHUNKING_OFFERED;
-  DEBUG(D_receive) debug_printf("chunking state %d\n", (int)chunking_state);
-  }
+chunking_state = CHUNKING_OFFERED;
+DEBUG(D_receive) debug_printf("chunking state %d\n", (int)chunking_state);
 }
 
 
@@ -956,15 +961,12 @@ that we'll never expand it. */
 yield = !! string_vformat(&gs, SVFMT_TAINT_NOCHK, format, ap);
 string_from_gstring(&gs);
 
-DEBUG(D_receive)
-  {
-  uschar *msg_copy, *cr, *end;
-  msg_copy = string_copy(gs.s);
-  end = msg_copy + gs.ptr;
-  while ((cr = Ustrchr(msg_copy, '\r')) != NULL)   /* lose CRs */
-    memmove(cr, cr + 1, (end--) - cr);
-  debug_printf("SMTP>> %s", msg_copy);
-  }
+DEBUG(D_receive) for (const uschar * t, * s = gs.s;
+                     s && (t = Ustrchr(s, '\r'));
+                     s = t + 2)                                /* \r\n */
+    debug_printf("%s %.*s\n",
+                 s == gs.s ? "SMTP>>" : "      ",
+                 (int)(t - s), s);
 
 if (!yield)
   {
@@ -981,7 +983,7 @@ which sometimes uses smtp_printf() and sometimes smtp_respond(). */
 
 if (fl.rcpt_in_progress)
   {
-  if (rcpt_smtp_response == NULL)
+  if (!rcpt_smtp_response)
     rcpt_smtp_response = string_copy(big_buffer);
   else if (fl.rcpt_smtp_response_same &&
            Ustrcmp(rcpt_smtp_response, big_buffer) != 0)
@@ -1193,6 +1195,16 @@ errno = EOVERFLOW;
 return -1;
 }
 
+
+static void
+proxy_debug(uschar * buf, unsigned start, unsigned end)
+{
+debug_printf("PROXY<<");
+while (start < end) debug_printf(" %02x", buf[start++]);
+debug_printf("\n");
+}
+
+
 /*************************************************
 *         Setup host for proxy protocol          *
 *************************************************/
@@ -1269,11 +1281,11 @@ So to safely handle v1 and v2, with client-sent-first supported correctly,
 we have to do a minimum of 3 read calls, not 1.  Eww.
 */
 
-#define PROXY_INITIAL_READ 14
-#define PROXY_V2_HEADER_SIZE 16
-#if PROXY_INITIAL_READ > PROXY_V2_HEADER_SIZE
-# error Code bug in sizes of data to read for proxy usage
-#endif
+# define PROXY_INITIAL_READ 14
+# define PROXY_V2_HEADER_SIZE 16
+# if PROXY_INITIAL_READ > PROXY_V2_HEADER_SIZE
+#  error Code bug in sizes of data to read for proxy usage
+# endif
 
 int get_ok = 0;
 int size, ret;
@@ -1293,11 +1305,11 @@ do
   "safe". Can't take it all because TLS-on-connect clients follow
   immediately with TLS handshake. */
   ret = read(fd, &hdr, PROXY_INITIAL_READ);
-  }
-  while (ret == -1 && errno == EINTR && !had_command_timeout);
+  } while (ret == -1 && errno == EINTR && !had_command_timeout);
 
 if (ret == -1)
   goto proxyfail;
+DEBUG(D_receive) proxy_debug(US &hdr, 0, ret);
 
 /* For v2, handle reading the length, and then the rest. */
 if ((ret == PROXY_INITIAL_READ) && (memcmp(&hdr.v2, v2sig, sizeof(v2sig)) == 0))
@@ -1305,6 +1317,8 @@ if ((ret == PROXY_INITIAL_READ) && (memcmp(&hdr.v2, v2sig, sizeof(v2sig)) == 0))
   int retmore;
   uint8_t ver;
 
+  DEBUG(D_receive) debug_printf("v2\n");
+
   /* First get the length fields. */
   do
     {
@@ -1312,6 +1326,8 @@ if ((ret == PROXY_INITIAL_READ) && (memcmp(&hdr.v2, v2sig, sizeof(v2sig)) == 0))
     } while (retmore == -1 && errno == EINTR && !had_command_timeout);
   if (retmore == -1)
     goto proxyfail;
+  DEBUG(D_receive) proxy_debug(US &hdr, ret, ret + retmore);
+
   ret += retmore;
 
   ver = (hdr.v2.ver_cmd & 0xf0) >> 4;
@@ -1349,6 +1365,7 @@ if ((ret == PROXY_INITIAL_READ) && (memcmp(&hdr.v2, v2sig, sizeof(v2sig)) == 0))
       } while (retmore == -1 && errno == EINTR && !had_command_timeout);
     if (retmore == -1)
       goto proxyfail;
+    DEBUG(D_receive) proxy_debug(US &hdr, ret, ret + retmore);
     ret += retmore;
     DEBUG(D_receive) debug_printf("PROXYv2: have %d/%d required octets\n", ret, size);
     } while (ret < size);
@@ -1594,7 +1611,7 @@ bad:
 ALARM(0);
 return;
 }
-#endif
+#endif /*SUPPORT_PROXY*/
 
 /*************************************************
 *           Read one command line                *
@@ -1764,7 +1781,7 @@ Returns:    nothing
 */
 
 void
-smtp_closedown(uschar *message)
+smtp_closedown(uschar * message)
 {
 if (!smtp_in || smtp_batched_input) return;
 receive_swallow_smtp();
@@ -2164,8 +2181,12 @@ prdr_requested = FALSE;
 #ifdef SUPPORT_I18N
 message_smtputf8 = FALSE;
 #endif
+#ifdef WITH_CONTENT_SCAN
+regex_vars_clear();
+#endif
 body_linecount = body_zerocount = 0;
 
+lookup_value = NULL;                           /* Can be set by ACL */
 sender_rate = sender_rate_limit = sender_rate_period = NULL;
 ratelimiters_mail = NULL;           /* Updated by ratelimit ACL condition */
                    /* Note that ratelimiters_conn persists across resets. */
@@ -2507,6 +2528,22 @@ else DEBUG(D_receive)
 #endif
 
 
+static void
+log_connect_tls_drop(const uschar * what, const uschar * log_msg)
+{
+gstring * g = s_tlslog(NULL);
+uschar * tls = string_from_gstring(g);
+
+log_write(L_connection_reject,
+  log_reject_target, "%s%s%s dropped by %s%s%s",
+  LOGGING(dnssec) && sender_host_dnssec ? US" DS" : US"",
+  host_and_ident(TRUE),
+  tls ? tls : US"",
+  what,
+  log_msg ? US": " : US"", log_msg);
+}
+
+
 /*************************************************
 *          Start an SMTP session                 *
 *************************************************/
@@ -2666,32 +2703,32 @@ if (!f.sender_host_unknown)
 
 #if !HAVE_IPV6 && !defined(NO_IP_OPTIONS)
 
-  #ifdef GLIBC_IP_OPTIONS
-    #if (!defined __GLIBC__) || (__GLIBC__ < 2)
-    #define OPTSTYLE 1
-    #else
-    #define OPTSTYLE 2
-    #endif
-  #elif defined DARWIN_IP_OPTIONS
-    #define OPTSTYLE 2
-  #else
-    #define OPTSTYLE 3
-  #endif
+ifdef GLIBC_IP_OPTIONS
+#  if (!defined __GLIBC__) || (__GLIBC__ < 2)
+#   define OPTSTYLE 1
+#  else
+#   define OPTSTYLE 2
+#  endif
+elif defined DARWIN_IP_OPTIONS
+define OPTSTYLE 2
+else
+define OPTSTYLE 3
+endif
 
   if (!host_checking && !f.sender_host_notsocket)
     {
-    #if OPTSTYLE == 1
+if OPTSTYLE == 1
     EXIM_SOCKLEN_T optlen = sizeof(struct ip_options) + MAX_IPOPTLEN;
     struct ip_options *ipopt = store_get(optlen, GET_UNTAINTED);
-    #elif OPTSTYLE == 2
+elif OPTSTYLE == 2
     struct ip_opts ipoptblock;
     struct ip_opts *ipopt = &ipoptblock;
     EXIM_SOCKLEN_T optlen = sizeof(ipoptblock);
-    #else
+else
     struct ipoption ipoptblock;
     struct ipoption *ipopt = &ipoptblock;
     EXIM_SOCKLEN_T optlen = sizeof(ipoptblock);
-    #endif
+endif
 
     /* Occasional genuine failures of getsockopt() have been seen - for
     example, "reset by peer". Therefore, just log and give up on this
@@ -2721,19 +2758,19 @@ if (!f.sender_host_unknown)
 
     else if (optlen > 0)
       {
-      uschar *p = big_buffer;
-      uschar *pend = big_buffer + big_buffer_size;
-      uschar *adptr;
+      uschar * p = big_buffer;
+      uschar * pend = big_buffer + big_buffer_size;
+      uschar * adptr;
       int optcount;
       struct in_addr addr;
 
-      #if OPTSTYLE == 1
-      uschar *optstart = US (ipopt->__data);
-      #elif OPTSTYLE == 2
-      uschar *optstart = US (ipopt->ip_opts);
-      #else
-      uschar *optstart = US (ipopt->ipopt_list);
-      #endif
+if OPTSTYLE == 1
+      uschar * optstart = US (ipopt->__data);
+elif OPTSTYLE == 2
+      uschar * optstart = US (ipopt->ip_opts);
+else
+      uschar * optstart = US (ipopt->ipopt_list);
+endif
 
       DEBUG(D_receive) debug_printf("IP options exist\n");
 
@@ -2744,59 +2781,65 @@ if (!f.sender_host_unknown)
         switch (*opt)
           {
           case IPOPT_EOL:
-          opt = NULL;
-          break;
+           opt = NULL;
+           break;
 
           case IPOPT_NOP:
-          opt++;
-          break;
+           opt++;
+           break;
 
           case IPOPT_SSRR:
           case IPOPT_LSRR:
-          if (!string_format(p, pend-p, " %s [@%s",
-               (*opt == IPOPT_SSRR)? "SSRR" : "LSRR",
-               #if OPTSTYLE == 1
-               inet_ntoa(*((struct in_addr *)(&(ipopt->faddr))))))
-               #elif OPTSTYLE == 2
-               inet_ntoa(ipopt->ip_dst)))
-               #else
-               inet_ntoa(ipopt->ipopt_dst)))
-               #endif
-            {
-            opt = NULL;
-            break;
-            }
+           if (!
+# if OPTSTYLE == 1
+                string_format(p, pend-p, " %s [@%s",
+                (*opt == IPOPT_SSRR)? "SSRR" : "LSRR",
+                inet_ntoa(*((struct in_addr *)(&(ipopt->faddr)))))
+# elif OPTSTYLE == 2
+                string_format(p, pend-p, " %s [@%s",
+                (*opt == IPOPT_SSRR)? "SSRR" : "LSRR",
+                inet_ntoa(ipopt->ip_dst))
+# else
+                string_format(p, pend-p, " %s [@%s",
+                (*opt == IPOPT_SSRR)? "SSRR" : "LSRR",
+                inet_ntoa(ipopt->ipopt_dst))
+# endif
+             )
+             {
+             opt = NULL;
+             break;
+             }
 
-          p += Ustrlen(p);
-          optcount = (opt[1] - 3) / sizeof(struct in_addr);
-          adptr = opt + 3;
-          while (optcount-- > 0)
-            {
-            memcpy(&addr, adptr, sizeof(addr));
-            if (!string_format(p, pend - p - 1, "%s%s",
-                  (optcount == 0)? ":" : "@", inet_ntoa(addr)))
-              {
-              opt = NULL;
-              break;
-              }
-            p += Ustrlen(p);
-            adptr += sizeof(struct in_addr);
-            }
-          *p++ = ']';
-          opt += opt[1];
-          break;
+           p += Ustrlen(p);
+           optcount = (opt[1] - 3) / sizeof(struct in_addr);
+           adptr = opt + 3;
+           while (optcount-- > 0)
+             {
+             memcpy(&addr, adptr, sizeof(addr));
+             if (!string_format(p, pend - p - 1, "%s%s",
+                   (optcount == 0)? ":" : "@", inet_ntoa(addr)))
+               {
+               opt = NULL;
+               break;
+               }
+             p += Ustrlen(p);
+             adptr += sizeof(struct in_addr);
+             }
+           *p++ = ']';
+           opt += opt[1];
+           break;
 
           default:
-            {
-            if (pend - p < 4 + 3*opt[1]) { opt = NULL; break; }
-            Ustrcat(p, "[ ");
-            p += 2;
-            for (int i = 0; i < opt[1]; i++)
-              p += sprintf(CS p, "%2.2x ", opt[i]);
-            *p++ = ']';
-            }
-          opt += opt[1];
-          break;
+             {
+             if (pend - p < 4 + 3*opt[1]) { opt = NULL; break; }
+             Ustrcat(p, "[ ");
+             p += 2;
+             for (int i = 0; i < opt[1]; i++)
+               p += sprintf(CS p, "%2.2x ", opt[i]);
+             *p++ = ']';
+             }
+           opt += opt[1];
+           break;
           }
 
       *p = 0;
@@ -2859,7 +2902,10 @@ if (!f.sender_host_unknown)
     {
     log_write(L_connection_reject, LOG_MAIN|LOG_REJECT, "refused connection "
       "from %s (host_reject_connection)", host_and_ident(FALSE));
-    smtp_printf("554 SMTP service not available\r\n", FALSE);
+#ifndef DISABLE_TLS
+    if (!tls_in.on_connect)
+#endif
+      smtp_printf("554 SMTP service not available\r\n", FALSE);
     return FALSE;
     }
 
@@ -2985,18 +3031,6 @@ if (check_proxy_protocol_host())
   setup_proxy_protocol_host();
 #endif
 
-/* Start up TLS if tls_on_connect is set. This is for supporting the legacy
-smtps port for use with older style SSL MTAs. */
-
-#ifndef DISABLE_TLS
-if (tls_in.on_connect)
-  {
-  if (tls_server_start(&user_msg) != OK)
-    return smtp_log_tls_fail(user_msg);
-  cmd_list[CMD_LIST_TLS_AUTH].is_mail_cmd = TRUE;
-  }
-#endif
-
 /* Run the connect ACL if it exists */
 
 user_msg = NULL;
@@ -3006,11 +3040,28 @@ if (acl_smtp_connect)
   if ((rc = acl_check(ACL_WHERE_CONNECT, NULL, acl_smtp_connect, &user_msg,
                      &log_msg)) != OK)
     {
-    (void) smtp_handle_acl_fail(ACL_WHERE_CONNECT, rc, user_msg, log_msg);
+#ifndef DISABLE_TLS
+    if (tls_in.on_connect)
+      log_connect_tls_drop(US"'connect' ACL", log_msg);
+    else
+#endif
+      (void) smtp_handle_acl_fail(ACL_WHERE_CONNECT, rc, user_msg, log_msg);
     return FALSE;
     }
   }
 
+/* Start up TLS if tls_on_connect is set. This is for supporting the legacy
+smtps port for use with older style SSL MTAs. */
+
+#ifndef DISABLE_TLS
+if (tls_in.on_connect)
+  {
+  if (tls_server_start(&user_msg) != OK)
+    return smtp_log_tls_fail(user_msg);
+  cmd_list[CMD_LIST_TLS_AUTH].is_mail_cmd = TRUE;
+  }
+#endif
+
 /* Output the initial message for a two-way SMTP connection. It may contain
 newlines, which then cause a multi-line response to be given. */
 
@@ -3018,13 +3069,7 @@ code = US"220";   /* Default status code */
 esc = US"";       /* Default extended status code */
 esclen = 0;       /* Length of esc */
 
-if (!user_msg)
-  {
-  if (!(s = expand_string(smtp_banner)))
-    log_write(0, LOG_MAIN|LOG_PANIC_DIE, "Expansion of \"%s\" (smtp_banner) "
-      "failed: %s", smtp_banner, expand_string_message);
-  }
-else
+if (user_msg)
   {
   int codelen = 3;
   s = user_msg;
@@ -3035,6 +3080,17 @@ else
     esclen = codelen - 4;
     }
   }
+else if (!(s = expand_string(smtp_banner)))
+  {
+  log_write(0, f.expand_string_forcedfail ? LOG_MAIN : LOG_MAIN|LOG_PANIC_DIE,
+    "Expansion of \"%s\" (smtp_banner) failed: %s",
+    smtp_banner, expand_string_message);
+  /* for force-fail */
+#ifndef DISABLE_TLS
+  if (tls_in.on_connect) tls_close(NULL, TLS_SHUTDOWN_WAIT);
+#endif
+  return FALSE;
+  }
 
 /* Remove any terminating newlines; might as well remove trailing space too */
 
@@ -3524,14 +3580,26 @@ if (log_reject_target != 0)
 
 if (!drop) return 0;
 
-log_write(L_smtp_connection, LOG_MAIN, "%s closed by DROP in ACL",
-  smtp_get_connection_info());
+log_close_event(US"by DROP in ACL");
 
 /* Run the not-quit ACL, but without any custom messages. This should not be a
 problem, because we get here only if some other ACL has issued "drop", and
 in that case, *its* custom messages will have been used above. */
 
 smtp_notquit_exit(US"acl-drop", NULL, NULL);
+
+/* An overenthusiastic fail2ban/iptables implimentation has been seen to result
+in the TCP conn staying open, and retrying, despite this process exiting. A
+malicious client could possibly do the same, tying up server netowrking
+resources. Close the socket explicitly to try to avoid that (there's a note in
+the Linux socket(7) manpage, SO_LINGER para, to the effect that exim() without
+close() results in the socket always lingering). */
+
+(void) poll_one_fd(fileno(smtp_in), POLLIN, 200);
+DEBUG(D_any) debug_printf_indent("SMTP(close)>>\n");
+(void) fclose(smtp_in);
+(void) fclose(smtp_out);
+
 return 2;
 }
 
@@ -3772,7 +3840,7 @@ smtp_respond(code, len, TRUE, user_msg);
 
 
 static int
-smtp_in_auth(auth_instance *au, uschar ** s, uschar ** ss)
+smtp_in_auth(auth_instance *au, uschar ** smtp_resp, uschar ** errmsg)
 {
 const uschar *set_id = NULL;
 int rc;
@@ -3836,7 +3904,7 @@ switch(rc)
       received_protocol =
        (sender_host_address ? protocols : protocols_local)
          [pextend + pauthed + (tls_in.active.sock >= 0 ? pcrpted:0)];
-      *s = *ss = US"235 Authentication succeeded";
+      *smtp_resp = *errmsg = US"235 Authentication succeeded";
       authenticated_by = au;
       break;
       }
@@ -3849,34 +3917,34 @@ switch(rc)
 
   case DEFER:
     if (set_id) authenticated_fail_id = string_copy_perm(set_id, TRUE);
-    *s = string_sprintf("435 Unable to authenticate at present%s",
+    *smtp_resp = string_sprintf("435 Unable to authenticate at present%s",
       auth_defer_user_msg);
-    *ss = string_sprintf("435 Unable to authenticate at present%s: %s",
+    *errmsg = string_sprintf("435 Unable to authenticate at present%s: %s",
       set_id, auth_defer_msg);
     break;
 
   case BAD64:
-    *s = *ss = US"501 Invalid base64 data";
+    *smtp_resp = *errmsg = US"501 Invalid base64 data";
     break;
 
   case CANCELLED:
-    *s = *ss = US"501 Authentication cancelled";
+    *smtp_resp = *errmsg = US"501 Authentication cancelled";
     break;
 
   case UNEXPECTED:
-    *s = *ss = US"553 Initial data not expected";
+    *smtp_resp = *errmsg = US"553 Initial data not expected";
     break;
 
   case FAIL:
     if (set_id) authenticated_fail_id = string_copy_perm(set_id, TRUE);
-    *s = US"535 Incorrect authentication data";
-    *ss = string_sprintf("535 Incorrect authentication data%s", set_id);
+    *smtp_resp = US"535 Incorrect authentication data";
+    *errmsg = string_sprintf("535 Incorrect authentication data%s", set_id);
     break;
 
   default:
     if (set_id) authenticated_fail_id = string_copy_perm(set_id, TRUE);
-    *s = US"435 Internal error";
-    *ss = string_sprintf("435 Internal error%s: return %d from authentication "
+    *smtp_resp = US"435 Internal error";
+    *errmsg = string_sprintf("435 Internal error%s: return %d from authentication "
       "check", set_id, rc);
     break;
   }
@@ -3938,16 +4006,14 @@ else
 tls_close(NULL, TLS_SHUTDOWN_NOWAIT);
 # endif
 
-log_write(L_smtp_connection, LOG_MAIN, "%s closed by QUIT",
-  smtp_get_connection_info());
+log_close_event(US"by QUIT");
 #else
 
 # ifndef DISABLE_TLS
 tls_close(NULL, TLS_SHUTDOWN_WAIT);
 # endif
 
-log_write(L_smtp_connection, LOG_MAIN, "%s closed by QUIT",
-  smtp_get_connection_info());
+log_close_event(US"by QUIT");
 
 /* Pause, hoping client will FIN first so that they get the TIME_WAIT.
 The socket should become readble (though with no data) */
@@ -3964,6 +4030,8 @@ HAD(SCH_RSET);
 incomplete_transaction_log(US"RSET");
 smtp_printf("250 Reset OK\r\n", FALSE);
 cmd_list[CMD_LIST_RSET].is_mail_cmd = FALSE;
+if (chunking_state > CHUNKING_OFFERED)
+  chunking_state = CHUNKING_OFFERED;
 }
 
 
@@ -4103,7 +4171,18 @@ while (done <= 0)
          if (smtp_in_auth(au, &s, &ss) == OK)
            { DEBUG(D_auth) debug_printf("tls auth succeeded\n"); }
          else
-           { DEBUG(D_auth) debug_printf("tls auth not succeeded\n"); }
+           {
+           DEBUG(D_auth) debug_printf("tls auth not succeeded\n");
+#ifndef DISABLE_EVENT
+            {
+             uschar * save_name = sender_host_authenticated, * logmsg;
+             sender_host_authenticated = au->name;
+             if ((logmsg = event_raise(event_action, US"auth:fail", s, NULL)))
+               log_write(0, LOG_MAIN, "%s", logmsg);
+             sender_host_authenticated = save_name;
+            }
+#endif
+           }
          }
        break;
        }
@@ -4193,6 +4272,8 @@ while (done <= 0)
 
        {
        auth_instance * au;
+       uschar * smtp_resp, * errmsg;
+
        for (au = auths; au; au = au->next)
          if (strcmpic(s, au->public_name) == 0 && au->server &&
              (au->advertised || f.allow_auth_unadvertised))
@@ -4200,12 +4281,25 @@ while (done <= 0)
 
        if (au)
          {
-         c = smtp_in_auth(au, &s, &ss);
+         int rc = smtp_in_auth(au, &smtp_resp, &errmsg);
 
-         smtp_printf("%s\r\n", FALSE, s);
-         if (c != OK)
-           log_write(0, LOG_MAIN|LOG_REJECT, "%s authenticator failed for %s: %s",
-             au->name, host_and_ident(FALSE), ss);
+         smtp_printf("%s\r\n", FALSE, smtp_resp);
+         if (rc != OK)
+           {
+           uschar * logmsg = NULL;
+#ifndef DISABLE_EVENT
+            {uschar * save_name = sender_host_authenticated;
+             sender_host_authenticated = au->name;
+             logmsg = event_raise(event_action, US"auth:fail", smtp_resp, NULL);
+             sender_host_authenticated = save_name;
+            }
+#endif
+           if (logmsg)
+             log_write(0, LOG_MAIN|LOG_REJECT, "%s", logmsg);
+           else
+             log_write(0, LOG_MAIN|LOG_REJECT, "%s authenticator failed for %s: %s",
+               au->name, host_and_ident(FALSE), errmsg);
+           }
          }
        else
          done = synprot_error(L_smtp_protocol_error, 504, NULL,
@@ -4394,7 +4488,7 @@ while (done <= 0)
 
       else
        {
-       char *ss;
+       char * ss;
        int codelen = 4;
        smtp_message_code(&smtp_code, &codelen, &user_msg, NULL, TRUE);
        s = string_sprintf("%.*s%s", codelen, smtp_code, user_msg);
@@ -4414,7 +4508,7 @@ while (done <= 0)
 
       if (fl.esmtp)
        {
-       g->s[3] = '-';
+       g->s[3] = '-';  /* overwrite the space after the SMTP response code */
 
        /* I'm not entirely happy with this, as an MTA is supposed to check
        that it has enough room to accept a message of maximum size before
@@ -4545,9 +4639,9 @@ while (done <= 0)
                  first = FALSE;
                  fl.auth_advertised = TRUE;
                  }
-               saveptr = g->ptr;
+               saveptr = gstring_length(g);
                g = string_catn(g, US" ", 1);
-               g = string_cat (g, au->public_name);
+               g = string_cat(g, au->public_name);
                while (++saveptr < g->ptr) g->s[saveptr] = toupper(g->s[saveptr]);
                au->advertised = TRUE;
                }
@@ -4610,28 +4704,29 @@ while (done <= 0)
       /* Terminate the string (for debug), write it, and note that HELO/EHLO
       has been seen. */
 
+       {
+       uschar * ehlo_resp;
+       int len = len_string_from_gstring(g, &ehlo_resp);
 #ifndef DISABLE_TLS
-      if (tls_in.active.sock >= 0)
-       (void)tls_write(NULL, g->s, g->ptr,
+       if (tls_in.active.sock >= 0)
+         (void) tls_write(NULL, ehlo_resp, len,
 # ifndef DISABLE_PIPE_CONNECT
-                       fl.pipe_connect_acceptable && pipeline_connect_sends());
+                         fl.pipe_connect_acceptable && pipeline_connect_sends());
 # else
-                       FALSE);
+                         FALSE);
 # endif
-      else
+       else
 #endif
-       (void) fwrite(g->s, 1, g->ptr, smtp_out);
-
-      DEBUG(D_receive)
-       {
-       uschar *cr;
+         (void) fwrite(ehlo_resp, 1, len, smtp_out);
 
-       (void) string_from_gstring(g);
-       while ((cr = Ustrchr(g->s, '\r')) != NULL)   /* lose CRs */
-         memmove(cr, cr + 1, (g->ptr--) - (cr - g->s));
-       debug_printf("SMTP>> %s", g->s);
-       }
-      fl.helo_seen = TRUE;
+       DEBUG(D_receive) for (const uschar * t, * s = ehlo_resp;
+                             s && (t = Ustrchr(s, '\r'));
+                             s = t + 2)                                /* \r\n */
+           debug_printf("%s %.*s\n",
+                         s == g->s ? "SMTP>>" : "      ",
+                         (int)(t - s), s);
+       fl.helo_seen = TRUE;
+       }
 
       /* Reset the protocol and the state, abandoning any previous message. */
       received_protocol =
@@ -5087,7 +5182,7 @@ while (done <= 0)
       count this as a protocol error. Reset was_rej_mail so that further RCPTs
       get the same treatment. */
 
-      if (sender_address == NULL)
+      if (!sender_address)
        {
        if (f.smtp_in_pipelining_advertised && last_was_rej_mail)
          {
@@ -5106,7 +5201,7 @@ while (done <= 0)
 
       /* Check for an operand */
 
-      if (smtp_cmd_data[0] == 0)
+      if (!smtp_cmd_data[0])
        {
        done = synprot_error(L_smtp_syntax_error, 501, NULL,
          US"RCPT must have an address operand");
@@ -5397,7 +5492,7 @@ while (done <= 0)
 #endif
       if (!discarded && recipients_count <= 0)
        {
-       if (fl.rcpt_smtp_response_same && rcpt_smtp_response != NULL)
+       if (fl.rcpt_smtp_response_same && rcpt_smtp_response)
          {
          uschar *code = US"503";
          int len = Ustrlen(rcpt_smtp_response);
@@ -5677,8 +5772,7 @@ while (done <= 0)
       while (done <= 0) switch(smtp_read_command(FALSE, GETC_BUFFER_UNLIMITED))
        {
        case EOF_CMD:
-         log_write(L_smtp_connection, LOG_MAIN, "%s closed by EOF",
-           smtp_get_connection_info());
+         log_close_event(US"by EOF");
          smtp_notquit_exit(US"tls-failed", NULL, NULL);
          done = 2;
          break;
@@ -5700,8 +5794,7 @@ while (done <= 0)
            smtp_respond(US"221", 3, TRUE, user_msg);
          else
            smtp_printf("221 %s closing connection\r\n", FALSE, smtp_active_hostname);
-         log_write(L_smtp_connection, LOG_MAIN, "%s closed by QUIT",
-           smtp_get_connection_info());
+         log_close_event(US"by QUIT");
          done = 2;
          break;
 
@@ -5834,7 +5927,7 @@ while (done <= 0)
        etrn_command = smtp_etrn_command;
        deliver_domain = smtp_cmd_data;
        rc = transport_set_up_command(&argv, smtp_etrn_command, TRUE, 0, NULL,
-         US"ETRN processing", &error);
+         FALSE, US"ETRN processing", &error);
        deliver_domain = NULL;
        if (!rc)
          {
@@ -6040,7 +6133,6 @@ while (done <= 0)
   COMMAND_LOOP:
   last_was_rej_mail = was_rej_mail;     /* Remember some last commands for */
   last_was_rcpt = was_rcpt;             /* protocol error handling */
-  continue;
   }
 
 return done - 2;  /* Convert yield values */