X-Git-Url: https://git.exim.org/exim.git/blobdiff_plain/4243a209fd9499f30bebd58ceaa2d0d9845407ae..aae673d7db4b26e8c4a8cc3d59fe94de4c47ba16:/src/src/smtp_in.c

diff --git a/src/src/smtp_in.c b/src/src/smtp_in.c
index b161f362d..04b20d27c 100644
--- a/src/src/smtp_in.c
+++ b/src/src/smtp_in.c
@@ -333,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))
@@ -355,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",
@@ -373,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",
@@ -384,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 */
 }
@@ -394,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 */
@@ -1187,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          *
 *************************************************/
@@ -1263,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;
@@ -1287,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))
@@ -1299,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
     {
@@ -1306,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;
@@ -1343,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);
@@ -1588,7 +1611,7 @@ bad:
 ALARM(0);
 return;
 }
-#endif
+#endif	/*SUPPORT_PROXY*/
 
 /*************************************************
 *           Read one command line                *
@@ -2680,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
@@ -2735,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");
 
@@ -2758,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;
@@ -3040,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;
@@ -3057,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 */
 
@@ -3546,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;
 }
 
@@ -3960,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) */
@@ -5724,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;
@@ -5747,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;