Observability: listen queue backlog

12 files changed, 134 insertions, 8 deletions

diff --git a/doc/doc-docbook/spec.xfpt b/doc/doc-docbook/spec.xfpt
index dfbd7a41a..b462f6758 100644
--- a/doc/doc-docbook/spec.xfpt
+++ b/doc/doc-docbook/spec.xfpt
@@ -14714,6 +14714,7 @@ listed in more than one group.
 .row &%notifier_socket%&             "override compiled-in value"
 .row &%pid_file_path%&               "override compiled-in value"
 .row &%queue_run_max%&               "maximum simultaneous queue runners"
+.row &%smtp_backlog_monitor%&        "level to log listen baclog"
 .endtable
 
 
@@ -17732,6 +17733,14 @@ messages, it is also used as the default for HELO commands in callout
 verification if there is no remote transport from which to obtain a
 &%helo_data%& value.
 
+.option smtp_backlog_monitor main integer 0
+.cindex "connection backlog" monitoring
+If this option is set to greater than zero, and the backlog of available
+TCP connections on a socket listening for SMTP is larger than it, a line
+is logged giving the value and the socket address and port.
+The value is retrived jsut before an accept call.
+This facility is only available on Linux.
+
 .option smtp_banner main string&!! "see below"
 .cindex "SMTP" "welcome banner"
 .cindex "banner for SMTP"
@@ -17762,7 +17771,7 @@ is zero). If there isn't enough space, a temporary error code is returned.
 
 
 .option smtp_connect_backlog main integer 20
-.cindex "connection backlog"
+.cindex "connection backlog" "set maximum"
 .cindex "SMTP" "connection backlog"
 .cindex "backlog of connections"
 This option specifies a maximum number of waiting SMTP connections. Exim passes
diff --git a/doc/doc-txt/NewStuff b/doc/doc-txt/NewStuff
index 0ac271eaf..c5a70da53 100644
--- a/doc/doc-txt/NewStuff
+++ b/doc/doc-txt/NewStuff
@@ -51,6 +51,9 @@ Version 4.95
 14. Log selector "queue_size_exclusive", enabled by default, to exclude the
     time taken for reception from QT log elements.
 
+15. Main option "smtp_backlog_monitor", to set a level abve which listen
+    socket backlogs are logged.
+
 Version 4.94
 ------------
 
diff --git a/doc/doc-txt/OptionLists.txt b/doc/doc-txt/OptionLists.txt
index 59be0a06b..2f3435f12 100644
--- a/doc/doc-txt/OptionLists.txt
+++ b/doc/doc-txt/OptionLists.txt
@@ -538,6 +538,7 @@ smtp_accept_queue                    integer         0             main
 smtp_accept_queue_per_connection     integer         10            main              2.03
 smtp_accept_reserve                  integer         0             main
 smtp_active_hostname                 string*         unset         main              4.33
+smtp_backlog_monitor                 integer         0             main              4.95
 smtp_banner                          string*         +             main
 smtp_check_spool_space               boolean         true          main              2.10
 smtp_connect_backlog                 integer         5             main
diff --git a/src/src/daemon.c b/src/src/daemon.c
index 626b43538..2d8b223c4 100644
--- a/src/src/daemon.c
+++ b/src/src/daemon.c
@@ -396,12 +396,18 @@ if (pid == 0)
   int save_debug_selector = debug_selector;
   BOOL local_queue_only;
   BOOL session_local_queue_only;
-  #ifdef SA_NOCLDWAIT
+#ifdef SA_NOCLDWAIT
   struct sigaction act;
-  #endif
+#endif
 
   smtp_accept_count++;    /* So that it includes this process */
 
+  /* If the listen backlog was over the monitoring level, log it. */
+
+  if (smtp_listen_backlog > smtp_backlog_monitor)
+    log_write(0, LOG_MAIN, "listen backlog %d I=[%s]:%d",
+		smtp_listen_backlog, interface_address, interface_port);
+
   /* May have been modified for the subprocess */
 
   *log_selector = save_log_selector;
@@ -685,6 +691,7 @@ if (pid == 0)
         (void)fclose(smtp_in);
 	(void)close(fileno(smtp_out));
         (void)fclose(smtp_out);
+	smtp_in = smtp_out = NULL;
 
         /* Don't ever molest the parent's SSL connection, but do clean up
         the data structures if necessary. */
@@ -2493,12 +2500,31 @@ for (;;)
 	  }
 	while (check_lsk < listen_socket_count)
 	  {
-	  int sk = check_lsk++;
-          if (FD_ISSET(listen_sockets[sk], &fds))
+	  int lfd = listen_sockets[check_lsk++];
+          if (FD_ISSET(lfd, &fds))
             {
-	    EXIM_SOCKLEN_T len = sizeof(accepted);
-            accept_socket = accept(listen_sockets[sk],
-              (struct sockaddr *)&accepted, &len);
+	    EXIM_SOCKLEN_T alen = sizeof(accepted);
+	    struct tcp_info ti;
+	    socklen_t tlen = sizeof(ti);
+
+	    /* If monitoring the backlog is wanted, grab for later logging */
+
+	    smtp_listen_backlog = 0;
+#if defined(TCP_INFO)
+	    if (  smtp_backlog_monitor > 0
+	       && getsockopt(lfd, IPPROTO_TCP, TCP_INFO, &ti, &tlen) == 0)
+	      {
+	      DEBUG(D_interface) debug_printf("listen fd %d queue max %u curr %u\n",
+# ifdef EXIM_HAVE_TCPI_UNACKED
+		      lfd, ti.tcpi_sacked, ti.tcpi_unacked);
+	      smtp_listen_backlog = ti.tcpi_unacked;
+# elif defined(__FreeBSD__)	/* This does not work. Investigate kernel sourcecode. */
+		      lfd, ti.__tcpi_sacked, ti.__tcpi_unacked);
+	      smtp_listen_backlog = ti.__tcpi_unacked;
+# endif
+	      }
+#endif
+            accept_socket = accept(lfd, (struct sockaddr *)&accepted, &alen);
             break;
             }
 	  }
diff --git a/src/src/globals.c b/src/src/globals.c
index e1837b67d..ef7063ddd 100644
--- a/src/src/globals.c
+++ b/src/src/globals.c
@@ -1471,6 +1471,7 @@ int     smtp_accept_queue      = 0;
 int     smtp_accept_queue_per_connection = 10;
 int     smtp_accept_reserve    = 0;
 uschar *smtp_active_hostname   = NULL;
+int	smtp_backlog_monitor   = 0;
 uschar *smtp_banner            = US"$smtp_active_hostname ESMTP "
                              "Exim $version_number $tod_full"
                              "\0<---------------Space to patch smtp_banner->";
@@ -1483,6 +1484,7 @@ int     smtp_connect_backlog   = 20;
 double  smtp_delay_mail        = 0.0;
 double  smtp_delay_rcpt        = 0.0;
 FILE   *smtp_in                = NULL;
+int     smtp_listen_backlog    = 0;
 int     smtp_load_reserve      = -1;
 int     smtp_mailcmd_count     = 0;
 FILE   *smtp_out               = NULL;
diff --git a/src/src/globals.h b/src/src/globals.h
index 4beb9d07e..c7a2635af 100644
--- a/src/src/globals.h
+++ b/src/src/globals.h
@@ -945,6 +945,7 @@ extern int     smtp_accept_queue;      /* Queue after so many connections */
 extern int     smtp_accept_queue_per_connection; /* Queue after so many msgs */
 extern int     smtp_accept_reserve;    /* Reserve these SMTP connections */
 extern uschar *smtp_active_hostname;   /* Hostname for this message */
+extern int     smtp_backlog_monitor;   /* listen backlog level to log */
 extern uschar *smtp_banner;            /* Banner string (to be expanded) */
 extern BOOL    smtp_check_spool_space; /* TRUE to check SMTP SIZE value */
 extern int     smtp_ch_index;          /* Index in smtp_connection_had */
@@ -959,6 +960,7 @@ extern BOOL    smtp_enforce_sync;      /* Enforce sync rules */
 extern uschar *smtp_etrn_command;      /* Command to run */
 extern BOOL    smtp_etrn_serialize;    /* Only one at once */
 extern FILE   *smtp_in;                /* Incoming SMTP input file */
+extern int     smtp_listen_backlog;    /* Current listener socket backlog, if monitored */
 extern int     smtp_load_reserve;      /* Only from reserved if load > this */
 extern int     smtp_mailcmd_count;     /* Count of MAIL commands */
 extern int     smtp_max_synprot_errors;/* Max syntax/protocol errors */
diff --git a/src/src/readconf.c b/src/src/readconf.c
index 816133329..6d7e7a19e 100644
--- a/src/src/readconf.c
+++ b/src/src/readconf.c
@@ -309,6 +309,7 @@ static optionlist optionlist_config[] = {
   { "smtp_accept_queue_per_connection", opt_int, {&smtp_accept_queue_per_connection} },
   { "smtp_accept_reserve",      opt_int,         {&smtp_accept_reserve} },
   { "smtp_active_hostname",     opt_stringptr,   {&raw_active_hostname} },
+  { "smtp_backlog_monitor",     opt_int,         {&smtp_backlog_monitor} },
   { "smtp_banner",              opt_stringptr,   {&smtp_banner} },
   { "smtp_check_spool_space",   opt_bool,        {&smtp_check_spool_space} },
   { "smtp_connect_backlog",     opt_int,         {&smtp_connect_backlog} },
diff --git a/test/confs/0624 b/test/confs/0624
index 2ffd0a18e..70f0c2024 100644
--- a/test/confs/0624
+++ b/test/confs/0624
@@ -34,6 +34,7 @@ smtp:
 	hosts =		127.0.0.1
 	port =		${if eq {c}{$local_part} {PORT_D2}{PORT_D}}
 	allow_localhost
+	hosts_try_fastopen =
 	max_rcpt =	1
 
 # ----- Retry -----
diff --git a/test/confs/0625 b/test/confs/0625
new file mode 100644
index 000000000..ff200a1f2
--- /dev/null
+++ b/test/confs/0625
@@ -0,0 +1,45 @@
+# Exim test configuration 0625
+
+.include DIR/aux-var/std_conf_prefix
+
+# ----- Main settings -----
+
+domainlist local_domains = test.ex
+qualify_domain = test.ex
+log_selector =	+received_recipients +outgoing_port +millisec
+smtp_backlog_monitor = 1
+
+smtp_accept_max_per_host = ${acl {delay}}10
+remote_max_parallel = 3
+
+acl_smtp_rcpt = discard
+
+# ----- ACL -----
+begin acl
+
+delay:
+  accept
+	 delay = 2s
+
+# ----- Routers -----
+begin routers
+r:
+	driver =	accept
+	transport =	smtp
+
+# ----- Trnasport -----
+begin transports
+smtp:
+	driver =	smtp
+	hosts =		127.0.0.1
+	port =		PORT_D
+	allow_localhost
+	hosts_try_fastopen =
+	max_rcpt =	1
+
+# ----- Retry -----
+begin retry
+* * F,5d,1d
+
+# End
+
diff --git a/test/log/0625 b/test/log/0625
new file mode 100644
index 000000000..41dcfb4fd
--- /dev/null
+++ b/test/log/0625
@@ -0,0 +1,21 @@
+2017-07-30 18:51:05.712 10HmaX-0005vi-00 <= CALLER@test.ex U=CALLER P=local S=sss for a@test.ex b@test.ex c@test.ex
+2017-07-30 18:51:05.712 10HmaX-0005vi-00 => a@test.ex R=r T=smtp H=127.0.0.1 [127.0.0.1]:PORT_D C="250 OK id=10HmaY-0005vi-00"
+2017-07-30 18:51:05.712 10HmaX-0005vi-00 => b@test.ex R=r T=smtp H=127.0.0.1 [127.0.0.1]:PORT_D C="250 OK id=10HmaZ-0005vi-00"
+2017-07-30 18:51:05.712 10HmaX-0005vi-00 => c@test.ex R=r T=smtp H=127.0.0.1 [127.0.0.1]:PORT_D C="250 OK id=10HmbA-0005vi-00"
+2017-07-30 18:51:05.712 10HmaX-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 PORT_D
+2017-07-30 18:51:05.712 H=localhost (the.local.host.name) [127.0.0.1] F=<CALLER@test.ex> RCPT <a@test.ex>: discarded by RCPT ACL
+2017-07-30 18:51:05.712 10HmaY-0005vi-00 <= CALLER@test.ex H=localhost (the.local.host.name) [127.0.0.1] P=esmtp S=sss id=E10HmaX-0005vi-00@the.local.host.name
+2017-07-30 18:51:05.712 10HmaY-0005vi-00 => blackhole (RCPT ACL discarded recipients)
+2017-07-30 18:51:05.712 10HmaY-0005vi-00 Completed
+2017-07-30 18:51:05.712 listen backlog 2 I=[127.0.0.1]:ppppp
+2017-07-30 18:51:05.712 H=localhost (the.local.host.name) [127.0.0.1] F=<CALLER@test.ex> RCPT <b@test.ex>: discarded by RCPT ACL
+2017-07-30 18:51:05.712 10HmaZ-0005vi-00 <= CALLER@test.ex H=localhost (the.local.host.name) [127.0.0.1] P=esmtp S=sss id=E10HmaX-0005vi-00@the.local.host.name
+2017-07-30 18:51:05.712 10HmaZ-0005vi-00 => blackhole (RCPT ACL discarded recipients)
+2017-07-30 18:51:05.712 10HmaZ-0005vi-00 Completed
+2017-07-30 18:51:05.712 H=localhost (the.local.host.name) [127.0.0.1] F=<CALLER@test.ex> RCPT <c@test.ex>: discarded by RCPT ACL
+2017-07-30 18:51:05.712 10HmbA-0005vi-00 <= CALLER@test.ex H=localhost (the.local.host.name) [127.0.0.1] P=esmtp S=sss id=E10HmaX-0005vi-00@the.local.host.name
+2017-07-30 18:51:05.712 10HmbA-0005vi-00 => blackhole (RCPT ACL discarded recipients)
+2017-07-30 18:51:05.712 10HmbA-0005vi-00 Completed
diff --git a/test/rejectlog/0625 b/test/rejectlog/0625
new file mode 100644
index 000000000..cfb1500fc
--- /dev/null
+++ b/test/rejectlog/0625
@@ -0,0 +1,5 @@
+
+******** SERVER ********
+2017-07-30 18:51:05.712 H=localhost (the.local.host.name) [127.0.0.1] F=<CALLER@test.ex> RCPT <a@test.ex>: discarded by RCPT ACL
+2017-07-30 18:51:05.712 H=localhost (the.local.host.name) [127.0.0.1] F=<CALLER@test.ex> RCPT <b@test.ex>: discarded by RCPT ACL
+2017-07-30 18:51:05.712 H=localhost (the.local.host.name) [127.0.0.1] F=<CALLER@test.ex> RCPT <c@test.ex>: discarded by RCPT ACL
diff --git a/test/scripts/0000-Basic/0625 b/test/scripts/0000-Basic/0625
new file mode 100644
index 000000000..b39a1cbe3
--- /dev/null
+++ b/test/scripts/0000-Basic/0625
@@ -0,0 +1,10 @@
+# queued connections on listener socket
+#
+exim -bd -DSERVER=server -oX PORT_D
+****
+exim a@test.ex b@test.ex c@test.ex
+Subject: test mail
+****
+#
+sleep 8
+killdaemon