Logging: Add "D=" to more connection closure log lines. Bug 2434
[exim.git] / src / src / smtp_in.c
index 1cfcc0404fd8ce00a0cb2493b6b287175272c4ba..04b20d27ce262c81c0776d37dfc670bb46fceec3 100644 (file)
@@ -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                *
@@ -3557,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;
 }
 
@@ -3971,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) */
@@ -5735,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;
@@ -5758,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;