Observability: listen queue backlog
authorJeremy Harris <jgh146exb@wizmail.org>
Sun, 6 Jun 2021 18:58:48 +0000 (19:58 +0100)
committerJeremy Harris <jgh146exb@wizmail.org>
Sun, 6 Jun 2021 20:13:15 +0000 (21:13 +0100)
12 files changed:
doc/doc-docbook/spec.xfpt
doc/doc-txt/NewStuff
doc/doc-txt/OptionLists.txt
src/src/daemon.c
src/src/globals.c
src/src/globals.h
src/src/readconf.c
test/confs/0624
test/confs/0625 [new file with mode: 0644]
test/log/0625 [new file with mode: 0644]
test/rejectlog/0625 [new file with mode: 0644]
test/scripts/0000-Basic/0625 [new file with mode: 0644]

index dfbd7a41a2cc01e5f001f031edf549296337609f..b462f675869364e900e5ad4963bf1a9b715c5422 100644 (file)
@@ -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
index 0ac271eaf07aad626cd1ab88e4b1e4a674efa286..c5a70da539d3c7f7b8fb1b4fbdc1d132bc3b44ec 100644 (file)
@@ -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
 ------------
 
index 59be0a06bc69ec72ec95a90141e5f2b81c4274b5..2f3435f1214d7a041a250cb5a986594bae5f4584 100644 (file)
@@ -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
index 626b43538d1d47198c4f72df5e506e9287878e0f..2d8b223c4cf3f64f1255f24f8d1d87657f1eb71a 100644 (file)
@@ -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;
             }
          }
index e1837b67d5fcd8a92400e1d47356167083ec4561..ef7063ddd7674a86a9ffbca13111a351b157ead8 100644 (file)
@@ -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;
index 4beb9d07e8387c02403e6f817409263aaa0ec3c9..c7a2635afef0067ff70094345fa67d7f166aa654 100644 (file)
@@ -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 */
index 816133329b09cbf313c5d6b1f3ddad30c8bf57c0..6d7e7a19e884ed35051f542d4ee8b2f08b6eb72c 100644 (file)
@@ -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} },
index 2ffd0a18e533e5f95c46648d5a3658a6bb9c6944..70f0c2024852d515ddff8f89167cf6a3ea20f9d7 100644 (file)
@@ -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 (file)
index 0000000..ff200a1
--- /dev/null
@@ -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 (file)
index 0000000..41dcfb4
--- /dev/null
@@ -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 (file)
index 0000000..cfb1500
--- /dev/null
@@ -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 (file)
index 0000000..b39a1cb
--- /dev/null
@@ -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