Logging: Add "D=" to more connection closure log lines. Bug 2434
[exim.git] / src / src / smtp_in.c
index 28e529bae25c7e23b367099562ae5ba35c1f5a69..04b20d27ce262c81c0776d37dfc670bb46fceec3 100644 (file)
@@ -5,6 +5,7 @@
 /* Copyright (c) The Exim Maintainers 2020 - 2022 */
 /* Copyright (c) University of Cambridge 1995 - 2018 */
 /* 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 */
@@ -1186,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          *
 *************************************************/
@@ -1262,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;
@@ -1286,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))
@@ -1298,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
     {
@@ -1305,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;
@@ -1342,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);
@@ -1587,7 +1611,7 @@ bad:
 ALARM(0);
 return;
 }
-#endif
+#endif /*SUPPORT_PROXY*/
 
 /*************************************************
 *           Read one command line                *
@@ -2504,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                 *
 *************************************************/
@@ -2663,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
@@ -2718,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");
 
@@ -2741,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;
@@ -2856,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;
     }
 
@@ -2982,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;
@@ -3003,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. */
 
@@ -3015,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;
@@ -3032,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 */
 
@@ -3521,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;
 }
 
@@ -3935,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) */
@@ -5699,8 +5768,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;
@@ -5722,8 +5790,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;