From: Jeremy Harris Date: Wed, 22 Aug 2018 12:20:54 +0000 (+0100) Subject: Logging: server pipelining offer but no uptake X-Git-Tag: exim-4.92-RC1~128 X-Git-Url: https://git.exim.org/exim.git/commitdiff_plain/3fc73bdc7aa8ac2b2b290033f602bdb947ae8049 Logging: server pipelining offer but no uptake --- diff --git a/doc/doc-docbook/spec.xfpt b/doc/doc-docbook/spec.xfpt index a9b5d968e..9ab06eddc 100644 --- a/doc/doc-docbook/spec.xfpt +++ b/doc/doc-docbook/spec.xfpt @@ -36566,7 +36566,7 @@ the following table: &`I `& local interface used &`id `& message id for incoming message &`K `& CHUNKING extension used -&`L `& on &`<=`& and &`=>`& lines: PIPELINING extension offered or used +&`L `& on &`<=`& and &`=>`& lines: PIPELINING extension used &`M8S `& 8BITMIME status for incoming message &`P `& on &`<=`& lines: protocol used &` `& on &`=>`& and &`**`& lines: return path @@ -36677,7 +36677,7 @@ selection marked by asterisks: &` queue_time `& time on queue for one recipient &` queue_time_overall `& time on queue for whole message &` pid `& Exim process id -&` pipelining `& PIPELINING, advertisement on <= lines, use on => lines +&` pipelining `& PIPELINING use, on <= and => lines &` proxy `& proxy address on <= and => lines &` receive_time `& time taken to receive message &` received_recipients `& recipients on <= lines @@ -36880,11 +36880,14 @@ local port is a random ephemeral port. &%pid%&: The current process id is added to every log line, in square brackets, immediately after the time and date. .next +.new .cindex log pipelining .cindex pipelining "logging outgoing" &%pipelining%&: A field is added to delivery and accept log lines when the ESMTP PIPELINING extension was used. The field is a single "L". +On accept lines, where PIPELINING was offered but not used by the client, +the field has a minus appended. .next .cindex "log" "queue run" .cindex "queue runner" "logging" diff --git a/src/src/globals.c b/src/src/globals.c index f1c6a7457..ee1db4b35 100644 --- a/src/src/globals.c +++ b/src/src/globals.c @@ -1355,6 +1355,7 @@ double smtp_delay_rcpt = 0.0; BOOL smtp_enforce_sync = TRUE; FILE *smtp_in = NULL; BOOL smtp_in_pipelining_advertised = FALSE; +BOOL smtp_in_pipelining_used = FALSE; BOOL smtp_input = FALSE; int smtp_load_reserve = -1; int smtp_mailcmd_count = 0; diff --git a/src/src/globals.h b/src/src/globals.h index 684c05d57..5b234e225 100644 --- a/src/src/globals.h +++ b/src/src/globals.h @@ -855,6 +855,7 @@ 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 BOOL smtp_in_pipelining_advertised; /* server advertised PIPELINING */ +extern BOOL smtp_in_pipelining_used; /* server noted client using PIPELINING */ 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/receive.c b/src/src/receive.c index 39f5b6758..7e5aac15e 100644 --- a/src/src/receive.c +++ b/src/src/receive.c @@ -1321,7 +1321,7 @@ if (sender_ident) if (received_protocol) g = string_append(g, 2, US" P=", received_protocol); if (LOGGING(pipelining) && smtp_in_pipelining_advertised) - g = string_catn(g, US" L", 2); + g = string_catn(g, US" L-", smtp_in_pipelining_used ? 2 : 3); return g; } diff --git a/src/src/smtp_in.c b/src/src/smtp_in.c index e59dece25..840594544 100644 --- a/src/src/smtp_in.c +++ b/src/src/smtp_in.c @@ -391,7 +391,9 @@ if ( !smtp_enforce_sync || !sender_host_address || sender_host_notsocket || !smtp_in_pipelining_advertised) return FALSE; -return !wouldblock_reading(); +if (wouldblock_reading()) return FALSE; +smtp_in_pipelining_used = TRUE; +return TRUE; } @@ -2428,7 +2430,7 @@ count_nonmail = TRUE_UNSET; synprot_error_count = unknown_command_count = nonmail_command_count = 0; smtp_delay_mail = smtp_rlm_base; auth_advertised = FALSE; -smtp_in_pipelining_advertised = FALSE; +smtp_in_pipelining_advertised = smtp_in_pipelining_used = FALSE; pipelining_enable = TRUE; sync_cmd_limit = NON_SYNC_CMD_NON_PIPELINING; smtp_exit_function_called = FALSE; /* For avoiding loop in not-quit exit */ diff --git a/test/confs/0216 b/test/confs/0216 index b7f9070ff..69af54347 100644 --- a/test/confs/0216 +++ b/test/confs/0216 @@ -1,6 +1,7 @@ # Exim test configuration 0216 SERVER= +HAP= .include DIR/aux-var/std_conf_prefix @@ -36,6 +37,7 @@ send_to_server: hosts = 127.0.0.1 port = PORT_D max_rcpt = 0 + HAP # ----- Retry ----- diff --git a/test/log/0216 b/test/log/0216 index 61f44eea0..e2dc1563f 100644 --- a/test/log/0216 +++ b/test/log/0216 @@ -500,7 +500,11 @@ 1999-03-02 09:44:33 10HmaX-0005vi-00 -> a498@test.ex R=client T=send_to_server H=127.0.0.1 [127.0.0.1] L C="250 OK id=10HmaY-0005vi-00" 1999-03-02 09:44:33 10HmaX-0005vi-00 -> a499@test.ex R=client T=send_to_server H=127.0.0.1 [127.0.0.1] L C="250 OK id=10HmaY-0005vi-00" 1999-03-02 09:44:33 10HmaX-0005vi-00 Completed +1999-03-02 09:44:33 10HmaZ-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss +1999-03-02 09:44:33 10HmaZ-0005vi-00 => b@test.ex R=client T=send_to_server H=127.0.0.1 [127.0.0.1] C="250 OK id=10HmbA-0005vi-00" +1999-03-02 09:44:33 10HmaZ-0005vi-00 Completed ******** 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=esmtp L S=sss id=E10HmaX-0005vi-00@myhost.test.ex +1999-03-02 09:44:33 10HmbA-0005vi-00 <= CALLER@myhost.test.ex H=localhost (myhost.test.ex) [127.0.0.1] P=esmtp L- S=sss id=E10HmaZ-0005vi-00@myhost.test.ex diff --git a/test/scripts/0000-Basic/0216 b/test/scripts/0000-Basic/0216 index 50ae0230a..0e6eb1d1a 100644 --- a/test/scripts/0000-Basic/0216 +++ b/test/scripts/0000-Basic/0216 @@ -109,5 +109,15 @@ Testing **** exim -M $msg1 **** +# +# +# Try to spot, in logging, offer but no uptake of PIPELINING +exim b@test.ex +testing +**** +exim -DHAP=hosts_avoid_pipelining=* -M $msg2 +**** +# +# killdaemon no_msglog_check