&`SNI `& server name indication from TLS client hello
&`ST `& shadow transport name
&`T `& on &`<=`& lines: message subject (topic)
+&`TFO `& connection took advantage of TCP Fast Open
&` `& on &`=>`& &`**`& and &`==`& lines: transport name
&`U `& local user or RFC 1413 identity
&`X `& TLS cipher suite
11. Millisecond timetamps in logs, on log_selector "millisec". Also affects
log elements QT, DT and D, and timstamps in debug output.
+12. TCP Fast Open logging. As a server, logs when the SMTP banner was sent
+ while still in SYN_RECV state; as a client logs when the connection
+ is opened with a TFO cookie.
+
Version 4.89
------------
#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 */
}
#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;
}
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));
{
readycount--;
if (par_read_pipe(poffset, FALSE)) /* Finished with this pipe */
- {
for (;;) /* Loop for signals */
{
pid_t endedpid = waitpid(pid, &status, 0);
"%d (errno = %d) from waitpid() for process %d",
(int)endedpid, errno, (int)pid);
}
- }
}
}
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));
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
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
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
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)
{
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;
}
}
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);
}
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;
}
+
+
+#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 *
*************************************************/
/* 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;
}
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;
+#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)
return -1;
}
if (ob->keepalive) ip_keepalive(sock, host->address, TRUE);
+#ifdef TCP_FASTOPEN
+ tfo_out_check(sock);
+#endif
return sock;
}
}
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
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;
}
} /* Loop for next address */
+tcp_out_fastopen_logged = TRUE;
sx->next_addr = addr;
return 0;
}
--- /dev/null
+# Exim test configuration 1990
+# TCP Fast Open
+
+SERVER=
+
+.include DIR/aux-var/std_conf_prefix
+
+primary_hostname = myhost.test.ex
+
+# ----- Main settings -----
+
+acl_smtp_rcpt = accept
+log_selector = +received_recipients +millisec
+
+# ----- Routers -----
+
+begin routers
+
+server:
+ driver = redirect
+ condition = ${if eq {SERVER}{server} {yes}{no}}
+ data = :blackhole:
+
+client:
+ driver = accept
+ condition = ${if eq {SERVER}{server}{no}{yes}}
+ transport = send_to_server
+
+
+# ----- Transports -----
+
+begin transports
+
+send_to_server:
+ driver = smtp
+ allow_localhost
+ hosts = 127.0.0.1
+ port = PORT_D
+ hosts_try_fastopen = *
+
+# ----- Retry -----
+
+begin retry
+
+* * F,5d,10s
+
+
+# End
+++ /dev/null
-# Exim test configuration 2052
-# as per 2000 but with TCP Fast Open
-
-SERVER=
-
-.include DIR/aux-var/tls_conf_prefix
-
-primary_hostname = myhost.test.ex
-
-# ----- Main settings -----
-
-acl_smtp_rcpt = accept
-
-log_selector = +tls_peerdn
-
-queue_only
-queue_run_in_order
-
-tls_advertise_hosts = *
-# needed to force generation
-tls_dhparam = historic
-
-# Set certificate only if server
-
-tls_certificate = ${if eq {SERVER}{server}{DIR/aux-fixed/cert1}fail}
-tls_privatekey = ${if eq {SERVER}{server}{DIR/aux-fixed/cert1}fail}
-
-tls_verify_hosts = *
-tls_verify_certificates = ${if eq {SERVER}{server}{DIR/aux-fixed/cert2}fail}
-
-
-# ----- Routers -----
-
-begin routers
-
-client:
- driver = accept
- condition = ${if eq {SERVER}{server}{no}{yes}}
- retry_use_local_part
- transport = send_to_server
-
-
-# ----- Transports -----
-
-begin transports
-
-send_to_server:
- driver = smtp
- allow_localhost
- hosts = 127.0.0.1
- port = PORT_D
- hosts_try_fastopen = *
- tls_certificate = DIR/aux-fixed/cert2
- tls_privatekey = DIR/aux-fixed/cert2
- tls_verify_certificates = DIR/aux-fixed/cert2
- tls_try_verify_hosts =
-
-
-# ----- Retry -----
-
-
-begin retry
-
-* * F,5d,10s
-
-
-# End
+++ /dev/null
-# Exim test configuration 2152
-# as per 2100 but with TCP Fast Open
-
-SERVER=
-
-.include DIR/aux-var/tls_conf_prefix
-
-primary_hostname = myhost.test.ex
-
-.ifdef _HAVE_TLS
-# that was purely to trigger the lazy-create of builtin macros
-.endif
-# ----- Main settings -----
-
-acl_smtp_rcpt = accept
-
-log_selector = +tls_peerdn
-
-queue_only
-queue_run_in_order
-
-tls_advertise_hosts = *
-
-# Set certificate only if server
-
-tls_certificate = ${if eq {SERVER}{server}{DIR/aux-fixed/cert1}fail}
-tls_privatekey = ${if eq {SERVER}{server}{DIR/aux-fixed/cert1}fail}
-
-tls_verify_hosts = *
-tls_verify_certificates = ${if eq {SERVER}{server}{DIR/aux-fixed/cert2}fail}
-
-
-# ----- Routers -----
-
-begin routers
-
-client:
- driver = accept
- condition = ${if eq {SERVER}{server}{no}{yes}}
- retry_use_local_part
- transport = send_to_server
-
-
-# ----- Transports -----
-
-begin transports
-
-send_to_server:
- driver = smtp
- allow_localhost
- hosts = 127.0.0.1
- port = PORT_D
- hosts_try_fastopen = *
- tls_certificate = DIR/aux-fixed/cert2
- tls_privatekey = DIR/aux-fixed/cert2
- tls_verify_certificates = DIR/aux-fixed/cert2
- tls_try_verify_hosts = :
-
-
-# ----- Retry -----
-
-
-begin retry
-
-* * F,5d,10s
-
-
-# End
--- /dev/null
+2017-07-30 18:51:05.712 10HmaX-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for a@test.ex
+2017-07-30 18:51:05.712 10HmaX-0005vi-00 => a@test.ex R=client T=send_to_server H=127.0.0.1 [127.0.0.1] C="250 OK id=10HmaY-0005vi-00"
+2017-07-30 18:51:05.712 10HmaX-0005vi-00 Completed
+2017-07-30 18:51:05.712 10HmaZ-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for b@test.ex
+2017-07-30 18:51:05.712 10HmaZ-0005vi-00 => b@test.ex R=client T=send_to_server H=127.0.0.1 [127.0.0.1] TFO C="250 OK id=10HmbA-0005vi-00"
+2017-07-30 18:51:05.712 10HmaZ-0005vi-00 Completed
+
+******** SERVER ********
+2017-07-30 18:51:05.712 exim x.yz daemon started: pid=pppp, no queue runs, listening for SMTP on port 1225
+2017-07-30 18:51:05.712 10HmaY-0005vi-00 <= CALLER@myhost.test.ex H=localhost (myhost.test.ex) [127.0.0.1] P=esmtp S=sss id=E10HmaX-0005vi-00@myhost.test.ex for a@test.ex
+2017-07-30 18:51:05.712 10HmaY-0005vi-00 => :blackhole: <a@test.ex> R=server
+2017-07-30 18:51:05.712 10HmaY-0005vi-00 Completed
+2017-07-30 18:51:05.712 10HmbA-0005vi-00 <= CALLER@myhost.test.ex H=localhost (myhost.test.ex) [127.0.0.1] TFO P=esmtp S=sss id=E10HmaZ-0005vi-00@myhost.test.ex for b@test.ex
+2017-07-30 18:51:05.712 10HmbA-0005vi-00 => :blackhole: <b@test.ex> R=server
+2017-07-30 18:51:05.712 10HmbA-0005vi-00 Completed
+++ /dev/null
-1999-03-02 09:44:33 10HmaX-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss
-1999-03-02 09:44:33 Start queue run: pid=pppp -qf
-1999-03-02 09:44:33 10HmaX-0005vi-00 TLS session: (certificate verification failed): certificate invalid: delivering unencrypted to H=127.0.0.1 [127.0.0.1] (not in hosts_require_tls)
-1999-03-02 09:44:33 10HmaX-0005vi-00 => CALLER@test.ex R=client T=send_to_server H=127.0.0.1 [127.0.0.1] C="250 OK id=10HmaY-0005vi-00"
-1999-03-02 09:44:33 10HmaX-0005vi-00 Completed
-1999-03-02 09:44:33 End queue run: pid=pppp -qf
-
-******** SERVER ********
-1999-03-02 09:44:33 exim x.yz daemon started: pid=pppp, no queue runs, listening for SMTP on port 1225
-1999-03-02 09:44:33 TLS error on connection from localhost [127.0.0.1] (recv): A TLS fatal alert has been received.: Certificate is bad
-1999-03-02 09:44:33 TLS error on connection from localhost [127.0.0.1] (send): The specified session has been invalidated for some reason.
-1999-03-02 09:44:33 10HmaY-0005vi-00 <= CALLER@myhost.test.ex H=localhost (myhost.test.ex) [127.0.0.1] P=esmtp S=sss id=E10HmaX-0005vi-00@myhost.test.ex
+++ /dev/null
-1999-03-02 09:44:33 10HmaX-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss
-1999-03-02 09:44:33 Start queue run: pid=pppp -qf
-1999-03-02 09:44:33 10HmaX-0005vi-00 => CALLER@test.ex R=client T=send_to_server H=127.0.0.1 [127.0.0.1] X=TLSv1:AES256-SHA:256 CV=no DN="/C=UK/O=The Exim Maintainers/OU=Test Suite/CN=Phil Pennock" C="250 OK id=10HmaY-0005vi-00"
-1999-03-02 09:44:33 10HmaX-0005vi-00 Completed
-1999-03-02 09:44:33 End queue run: pid=pppp -qf
-
-******** SERVER ********
-1999-03-02 09:44:33 exim x.yz daemon started: pid=pppp, no queue runs, listening for SMTP on port 1225
-1999-03-02 09:44:33 10HmaY-0005vi-00 <= CALLER@myhost.test.ex H=localhost (myhost.test.ex) [127.0.0.1] P=esmtps X=TLSv1:AES256-SHA:256 CV=yes DN="/C=UK/O=The Exim Maintainers/OU=Test Suite/CN=Phil Pennock" S=sss id=E10HmaX-0005vi-00@myhost.test.ex
--- /dev/null
+# TCP Fast Open
+#
+# Linux:
+# Both server and client-side TFO support must be enabled in the
+# kernel, 'sudo sh -c "echo 3 > /proc/sys/net/ipv4/tcp_fastopen"'.
+#
+# A packet capture on the loopback interface will show the TFO
+# option on the SYN, but the fast-output SMTP banner will not
+# be seen unless you also deliberately emulate a long path:
+# 'sudo tc qdisc add dev lo root netem delay 100ms'
+#
+# First time runs will see a TFO request option only; subsequent
+# ones should see the TFO cookie and fast-output SMTP banner
+# (currently on a separate packet after the server SYN,ACK but before
+# the client ACK).
+#
+# The log <= line should have a "TFO" element.
+#
+# If the client-side is disabled in the kernel, Exim logs
+# will become noisy.
+#
+#
+# FreeBSD: it looks like you have to compile a custom kernel, with
+# 'options TCP_RFC7413' in the config. Also set
+# 'net.inet.tcp.fastopen.enabled=1' in /etc/sysctl.conf
+# Untested.
+#
+exim -DSERVER=server -bd -oX PORT_D
+****
+exim a@test.ex
+Testing
+****
+sleep 3
+exim b@test.ex
+Testing
+****
+sleep 3
+killdaemon
+no_msglog_check
--- /dev/null
+support TCP_Fast_Open
+++ /dev/null
-# TLS client: TLS setup fails - retry in clear (with fastopen)
-#
-# If all works you'll not see any difference. To enable in the
-# kernel, 'sudo sh -c "echo 3 > /proc/sys/net/ipv4/tcp_fastopen"'.
-# A packet capture on the loopback interface will show the TFU
-# option on the SYN, but the fast-output SMTP banner will not
-# be seen unless you also deliberately emulate a long path:
-# 'sudo tc qdisc add dev lo root netem delay 100ms'
-#
-# If the client-side is disabled in the kernel, Exim logs
-# will become noisy.
-#
-gnutls
-exim -DSERVER=server -bd -oX PORT_D
-****
-exim CALLER@test.ex
-Testing
-****
-exim -qf
-****
-killdaemon
-no_msglog_check
+++ /dev/null
-# TLS client: TLS setup fails - retry in clear (with fastopen)
-#
-# If all works you'll not see any difference. To enable in the
-# kernel, 'sudo sh -c "echo 3 > /proc/sys/net/ipv4/tcp_fastopen"'.
-# A packet capture on the loopback interface will show the TFO
-# option on the SYN, but the fast-output SMTP banner will not
-# be seen unless you also deliberately emulate a long path:
-# 'sudo tc qdisc add dev lo root netem delay 100ms'
-#
-# If the client-side is disabled in the kernel, Exim logs
-# will become noisy.
-#
-exim -DSERVER=server -bd -oX PORT_D
-****
-exim CALLER@test.ex
-Testing
-****
-exim -qf
-****
-killdaemon
-no_msglog_check