Logging: TCP Fast Open

10 files changed, 137 insertions, 28 deletions

diff --git a/src/OS/os.h-FreeBSD b/src/OS/os.h-FreeBSD
index 9b47de3d1..3a06e766e 100644
--- a/src/OS/os.h-FreeBSD
+++ b/src/OS/os.h-FreeBSD
@@ -43,4 +43,22 @@ performance on outgoing mail a bit. */
 #define OS_SENDFILE
 extern ssize_t os_sendfile(int, int, off_t *, size_t);
 
+
+/*******************/
+
+/* TCP_FASTOPEN support.  There does not seems to be a
+MSG_FASTOPEN defined yet... */
+
+#include <netinet/tcp.h>        /* for TCP_FASTOPEN */
+#include <sys/socket.h>         /* for MSG_FASTOPEN */
+#if defined(TCP_FASTOPEN) && !defined(MSG_FASTOPEN)
+# define MSG_FASTOPEN 0x20000000
+#endif
+ 
+/* for TCP state-variable values, for TFO logging */
+#include <netinet/tcp_fsm.h>
+#define TCP_SYN_RECV TCPS_SYN_RECEIVED
+
+/*******************/
+
 /* End */
diff --git a/src/src/deliver.c b/src/src/deliver.c
index 2d2850cf5..b8a55b20a 100644
--- a/src/src/deliver.c
+++ b/src/src/deliver.c
@@ -752,7 +752,12 @@ if (LOGGING(proxy) && proxy_local_address)
   }
 #endif
 
-return d_log_interface(s, sp, pp);
+s = d_log_interface(s, sp, pp);
+
+if (testflag(addr, af_tcp_fastopen))
+  s = string_catn(s, sp, pp, US" TFO", 4);
+
+return s;
 }
 
 
@@ -3560,6 +3565,10 @@ while (!done)
       setflag(addr, af_chunking_used);
       break;
 
+    case 'T':
+      setflag(addr, af_tcp_fastopen);
+      break;
+
     case 'D':
       if (!addr) goto ADDR_MISMATCH;
       memcpy(&(addr->dsn_aware), ptr, sizeof(addr->dsn_aware));
@@ -3979,7 +3988,6 @@ for (;;)   /* Normally we do not repeat this loop */
         {
         readycount--;
         if (par_read_pipe(poffset, FALSE))    /* Finished with this pipe */
-          {
           for (;;)                            /* Loop for signals */
             {
             pid_t endedpid = waitpid(pid, &status, 0);
@@ -3989,7 +3997,6 @@ for (;;)   /* Normally we do not repeat this loop */
                 "%d (errno = %d) from waitpid() for process %d",
                 (int)endedpid, errno, (int)pid);
             }
-          }
         }
       }
 
@@ -4856,6 +4863,9 @@ for (delivery_count = 0; addr_remote; delivery_count++)
       if (testflag(addr, af_chunking_used))
 	rmt_dlv_checked_write(fd, 'K', '0', NULL, 0);
 
+      if (testflag(addr, af_tcp_fastopen))
+	rmt_dlv_checked_write(fd, 'T', '0', NULL, 0);
+
       memcpy(big_buffer, &addr->dsn_aware, sizeof(addr->dsn_aware));
       rmt_dlv_checked_write(fd, 'D', '0', big_buffer, sizeof(addr->dsn_aware));
 
diff --git a/src/src/globals.c b/src/src/globals.c
index f3fdb5975..97debee58 100644
--- a/src/src/globals.c
+++ b/src/src/globals.c
@@ -1417,7 +1417,11 @@ BOOL    system_filter_uid_set  = FALSE;
 BOOL    system_filtering       = FALSE;
 
 BOOL    tcp_fastopen_ok        = FALSE;
+BOOL    tcp_in_fastopen        = FALSE;
+BOOL    tcp_in_fastopen_logged = FALSE;
 BOOL    tcp_nodelay            = TRUE;
+BOOL    tcp_out_fastopen       = FALSE;
+BOOL    tcp_out_fastopen_logged= FALSE;
 #ifdef USE_TCP_WRAPPERS
 uschar *tcp_wrappers_daemon_name = US TCP_WRAPPERS_DAEMON_NAME;
 #endif
diff --git a/src/src/globals.h b/src/src/globals.h
index bd8d14288..7578a1d82 100644
--- a/src/src/globals.h
+++ b/src/src/globals.h
@@ -922,7 +922,11 @@ extern BOOL    system_filter_uid_set;  /* TRUE if uid set */
 extern BOOL    system_filtering;       /* TRUE when running system filter */
 
 extern BOOL    tcp_fastopen_ok;	       /* appears to be supported by kernel */
+extern BOOL    tcp_in_fastopen;	       /* conn used fastopen */
+extern BOOL    tcp_in_fastopen_logged; /* one-time logging */
 extern BOOL    tcp_nodelay;            /* Controls TCP_NODELAY on daemon */
+extern BOOL    tcp_out_fastopen;       /* conn used fastopen */
+extern BOOL    tcp_out_fastopen_logged; /* one-time logging */
 #ifdef USE_TCP_WRAPPERS
 extern uschar *tcp_wrappers_daemon_name; /* tcpwrappers daemon lookup name */
 #endif
diff --git a/src/src/ip.c b/src/src/ip.c
index 09b4c439e..08d32f21b 100644
--- a/src/src/ip.c
+++ b/src/src/ip.c
@@ -235,14 +235,15 @@ connect in FASTOPEN mode but with zero data.
 
 if (fastopen)
   {
-  if (  (rc = sendto(sock, NULL, 0, MSG_FASTOPEN, s_ptr, s_len)) < 0
-     && errno == EOPNOTSUPP
-     )
-    {
-    DEBUG(D_transport)
-      debug_printf("Tried TCP Fast Open but apparently not enabled by sysctl\n");
-    rc = connect(sock, s_ptr, s_len);
-    }
+  if ((rc = sendto(sock, NULL, 0, MSG_FASTOPEN | MSG_DONTWAIT, s_ptr, s_len)) < 0)
+    if (errno == EINPROGRESS)		/* the expected case */
+      rc = 0;
+    else if(errno == EOPNOTSUPP)
+      {
+      DEBUG(D_transport)
+	debug_printf("Tried TCP Fast Open but apparently not enabled by sysctl\n");
+      rc = connect(sock, s_ptr, s_len);
+      }
   }
 else
 #endif
diff --git a/src/src/receive.c b/src/src/receive.c
index 71026ff4a..65e9fb415 100644
--- a/src/src/receive.c
+++ b/src/src/receive.c
@@ -1303,7 +1303,7 @@ add_host_info_for_log(uschar * s, int * sizeptr, int * ptrptr)
 if (sender_fullhost)
   {
   if (LOGGING(dnssec) && sender_host_dnssec)	/*XXX sender_helo_dnssec? */
-    s = string_cat(s, sizeptr, ptrptr, US" DS");
+    s = string_catn(s, sizeptr, ptrptr, US" DS", 3);
   s = string_append(s, sizeptr, ptrptr, 2, US" H=", sender_fullhost);
   if (LOGGING(incoming_interface) && interface_address != NULL)
     {
@@ -1311,9 +1311,14 @@ if (sender_fullhost)
       string_sprintf(" I=[%s]:%d", interface_address, interface_port));
     }
   }
-if (sender_ident != NULL)
+if (tcp_in_fastopen && !tcp_in_fastopen_logged)
+  {
+  s = string_catn(s, sizeptr, ptrptr, US" TFO", 4);
+  tcp_in_fastopen_logged = TRUE;
+  }
+if (sender_ident)
   s = string_append(s, sizeptr, ptrptr, 2, US" U=", sender_ident);
-if (received_protocol != NULL)
+if (received_protocol)
   s = string_append(s, sizeptr, ptrptr, 2, US" P=", received_protocol);
 return s;
 }
diff --git a/src/src/smtp_in.c b/src/src/smtp_in.c
index d6250d12d..36f685677 100644
--- a/src/src/smtp_in.c
+++ b/src/src/smtp_in.c
@@ -1798,7 +1798,8 @@ for (i = 0; i < smtp_ch_index; i++)
   }
 
 if (s) s[ptr] = 0; else s = US"";
-log_write(0, LOG_MAIN, "no MAIL in SMTP connection from %s D=%s%s",
+log_write(0, LOG_MAIN, "no MAIL in %sSMTP connection from %s D=%s%s",
+  tcp_in_fastopen ? US"TFO " : US"",
   host_and_ident(FALSE), string_timesince(&smtp_connection_start), s);
 }
 
@@ -1941,17 +1942,17 @@ while (v > smtp_cmd_data && *v != '=' && !isspace(*v))
 
 n = v;
 if (*v == '=')
-{
+  {
   while(isalpha(n[-1])) n--;
   /* RFC says SP, but TAB seen in wild and other major MTAs accept it */
   if (!isspace(n[-1])) return FALSE;
   n[-1] = 0;
-}
+  }
 else
-{
+  {
   n++;
   if (v == smtp_cmd_data) return FALSE;
-}
+  }
 *v++ = 0;
 *name = n;
 *value = v;
@@ -2331,6 +2332,28 @@ return FALSE;
 }
 
 
+
+
+#ifdef TCP_FASTOPEN
+static void
+tfo_in_check(void)
+{
+# ifdef TCP_INFO
+struct tcp_info tinfo;
+socklen_t len = sizeof(tinfo);
+
+if (  getsockopt(fileno(smtp_out), IPPROTO_TCP, TCP_INFO, &tinfo, &len) == 0
+   && tinfo.tcpi_state == TCP_SYN_RECV
+   )
+  {
+  DEBUG(D_receive) debug_printf("TCP_FASTOPEN mode connection\n");
+  tcp_in_fastopen = TRUE;
+  }
+# endif
+}
+#endif
+
+
 /*************************************************
 *          Start an SMTP session                 *
 *************************************************/
@@ -2923,6 +2946,14 @@ if (!check_sync())
 /* Now output the banner */
 
 smtp_printf("%s", FALSE, ss);
+
+/* Attempt to see if we sent the banner before the last ACK of the 3-way
+handshake arrived.  If so we must have managed a TFO. */
+
+#ifdef TCP_FASTOPEN
+tfo_in_check();
+#endif
+
 return TRUE;
 }
 
@@ -5459,18 +5490,22 @@ while (done <= 0)
     just drop the call rather than sending QUIT, and it clutters up the logs.
     */
 
-    if (sender_address != NULL || recipients_count > 0)
+    if (sender_address || recipients_count > 0)
       log_write(L_lost_incoming_connection, LOG_MAIN,
-          "unexpected %s while reading SMTP command from %s%s D=%s",
-          sender_host_unknown ? "EOF" : "disconnection",
-          host_and_ident(FALSE), smtp_read_error,
-	  string_timesince(&smtp_connection_start)
-	  );
+	"unexpected %s while reading SMTP command from %s%s%s D=%s",
+	sender_host_unknown ? "EOF" : "disconnection",
+	tcp_in_fastopen && !tcp_in_fastopen_logged ? US"TFO " : US"",
+	host_and_ident(FALSE), smtp_read_error,
+	string_timesince(&smtp_connection_start)
+	);
 
     else
-      log_write(L_smtp_connection, LOG_MAIN, "%s lost%s D=%s",
-        smtp_get_connection_info(), smtp_read_error,
-	string_timesince(&smtp_connection_start));
+      log_write(L_smtp_connection, LOG_MAIN, "%s %slost%s D=%s",
+        smtp_get_connection_info(),
+	tcp_in_fastopen && !tcp_in_fastopen_logged ? US"TFO " : US"",
+	smtp_read_error,
+	string_timesince(&smtp_connection_start)
+	);
 
     done = 1;
     break;
diff --git a/src/src/smtp_out.c b/src/src/smtp_out.c
index 253d7670d..d5bf262be 100644
--- a/src/src/smtp_out.c
+++ b/src/src/smtp_out.c
@@ -140,6 +140,30 @@ return TRUE;
 
 
 
+#ifdef TCP_FASTOPEN
+static void
+tfo_out_check(int sock)
+{
+# ifdef TCP_INFO
+struct tcp_info tinfo;
+socklen_t len = sizeof(tinfo);
+
+if (getsockopt(sock, IPPROTO_TCP, TCP_INFO, &tinfo, &len) == 0)
+  {
+  /* This is a somewhat dubious detection method; totally undocumented so likely
+  to fail in future kernels.  There seems to be no documented way. */
+
+  if (tinfo.tcpi_unacked > 1)
+    {
+    DEBUG(D_transport|D_v) debug_printf("TCP_FASTOPEN mode connection\n");
+    tcp_out_fastopen = TRUE;
+    }
+  }
+# endif
+}
+#endif
+
+
 int
 smtp_sock_connect(host_item * host, int host_af, int port, uschar * interface,
   transport_instance * tb, int timeout)
@@ -239,6 +263,9 @@ else
     return -1;
     }
   if (ob->keepalive) ip_keepalive(sock, host->address, TRUE);
+#ifdef TCP_FASTOPEN
+  tfo_out_check(sock);
+#endif
   return sock;
   }
 }
diff --git a/src/src/structs.h b/src/src/structs.h
index a17b50332..beea57f34 100644
--- a/src/src/structs.h
+++ b/src/src/structs.h
@@ -610,6 +610,7 @@ typedef struct address_item {
     BOOL af_cert_verified:1;		/* delivered with verified TLS cert */
     BOOL af_pass_message:1;		/* pass message in bounces */
     BOOL af_bad_reply:1;		/* filter could not generate autoreply */
+    BOOL af_tcp_fastopen:1;		/* delivery used TCP Fast Open */
 #ifndef DISABLE_PRDR
     BOOL af_prdr_used:1;		/* delivery used SMTP PRDR */
 #endif
diff --git a/src/src/transports/smtp.c b/src/src/transports/smtp.c
index 3ed31d924..a3819fe49 100644
--- a/src/src/transports/smtp.c
+++ b/src/src/transports/smtp.c
@@ -2504,6 +2504,9 @@ for (addr = sx->first_addr, address_count = 0;
   BOOL no_flush;
   uschar * rcpt_addr;
 
+  if (tcp_out_fastopen && !tcp_out_fastopen_logged)
+    setflag(addr, af_tcp_fastopen);
+
   addr->dsn_aware = sx->peer_offered & OPTION_DSN
     ? dsn_support_yes : dsn_support_no;
 
@@ -2557,6 +2560,7 @@ for (addr = sx->first_addr, address_count = 0;
     }
   }      /* Loop for next address */
 
+tcp_out_fastopen_logged = TRUE;
 sx->next_addr = addr;
 return 0;
 }