Logging: server pipelining offer but no uptake

diff --git a/doc/doc-docbook/spec.xfpt b/doc/doc-docbook/spec.xfpt
index a9b5d968e5c6ca057af17dce49f8426ffb876641..9ab06eddca274276745c442a9b0fa74961ba7351 100644 (file)
--- 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
 &`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
 &`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
 &` 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
 &` 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
 &%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".
 .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"
 .next
 .cindex "log" "queue run"
 .cindex "queue runner" "logging"

diff --git a/src/src/globals.c b/src/src/globals.c
index f1c6a7457cc75a4e9c119da8f09037e85abb7385..ee1db4b3514e4783314cefb3c39dd7c1c399f04c 100644 (file)
--- 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_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;
 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 684c05d5703e6014bd6a3f9359c92a5ba1271d6d..5b234e2250a0be753b819cdce47d9e0750f11e9a 100644 (file)
--- 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_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 */
 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 39f5b67583b51164c4213fd390207aac820ac500..7e5aac15edc126410891dbe4d091c0fc52d4babf 100644 (file)
--- 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)
 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;
 }
 
 return g;
 }
 

diff --git a/src/src/smtp_in.c b/src/src/smtp_in.c
index e59dece25f9dcc5db62e05f7d9c44e12e51209ca..84059454423c85ce5bcd177e21f99566c548cfc3 100644 (file)
--- 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;
 
    || 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;
 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 */
 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 b7f9070ff1cae7c1266eae353f3c8cc9873ce9a6..69af54347e70f4eb03122e42138b07b3ef1d5126 100644 (file)
--- a/test/confs/0216
+++ b/test/confs/0216
@@ -1,6 +1,7 @@
 # Exim test configuration 0216
 
 SERVER=
 # Exim test configuration 0216
 
 SERVER=

+HAP=

 
 .include DIR/aux-var/std_conf_prefix
 
 
 .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
   hosts = 127.0.0.1
   port = PORT_D
   max_rcpt = 0

+  HAP

 
 
 # ----- Retry -----
 
 
 # ----- Retry -----

diff --git a/test/log/0216 b/test/log/0216
index 61f44eea0761822d43b6043c6e73009cda7aa3da..e2dc1563ff9699a82471f9099f197b3b179345b4 100644 (file)
--- 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 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
 
 ******** 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 50ae0230aa063037cb2c0f0232d497e94aba4b7c..0e6eb1d1a072ee290e2f1c153e0a93542a22e658 100644 (file)
--- a/test/scripts/0000-Basic/0216
+++ b/test/scripts/0000-Basic/0216
@@ -109,5 +109,15 @@ Testing
 ****
 exim -M $msg1
 ****
 ****
 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
 killdaemon
 no_msglog_check