From 9d783bb9f39bca59e720d0c543499b372c412441 Mon Sep 17 00:00:00 2001 From: Jeremy Harris Date: Sun, 6 Jun 2021 19:58:48 +0100 Subject: [PATCH] Observability: listen queue backlog --- doc/doc-docbook/spec.xfpt | 11 ++++++++- doc/doc-txt/NewStuff | 3 +++ doc/doc-txt/OptionLists.txt | 1 + src/src/daemon.c | 40 ++++++++++++++++++++++++++------ src/src/globals.c | 2 ++ src/src/globals.h | 2 ++ src/src/readconf.c | 1 + test/confs/0624 | 1 + test/confs/0625 | 45 ++++++++++++++++++++++++++++++++++++ test/log/0625 | 21 +++++++++++++++++ test/rejectlog/0625 | 5 ++++ test/scripts/0000-Basic/0625 | 10 ++++++++ 12 files changed, 134 insertions(+), 8 deletions(-) create mode 100644 test/confs/0625 create mode 100644 test/log/0625 create mode 100644 test/rejectlog/0625 create mode 100644 test/scripts/0000-Basic/0625 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= RCPT : 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= RCPT : 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= RCPT : 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= RCPT : discarded by RCPT ACL +2017-07-30 18:51:05.712 H=localhost (the.local.host.name) [127.0.0.1] F= RCPT : discarded by RCPT ACL +2017-07-30 18:51:05.712 H=localhost (the.local.host.name) [127.0.0.1] F= RCPT : 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 -- 2.30.2