Logging: pipelining log_selector

9 files changed, 56 insertions, 29 deletions

diff --git a/src/src/deliver.c b/src/src/deliver.c
index 0b9e55141..3a395724d 100644
--- a/src/src/deliver.c
+++ b/src/src/deliver.c
@@ -1234,6 +1234,9 @@ else
       }
     }
 
+  if (LOGGING(pipelining) && testflag(addr, af_pipelining))
+    g = string_catn(g, US" L", 2);
+
 #ifndef DISABLE_PRDR
   if (testflag(addr, af_prdr_used))
     g = string_catn(g, US" PRDR", 5);
@@ -3551,6 +3554,13 @@ while (!done)
       break;
 #endif
 
+    case 'L':
+      switch (*subid)
+	{
+	case 1: setflag(addr, af_pipelining); break;
+	}
+      break;
+
     case 'K':
       setflag(addr, af_chunking_used);
       break;
@@ -4856,6 +4866,9 @@ all pipes, so I do not see a reason to use non-blocking IO here
 	rmt_dlv_checked_write(fd, 'P', '0', NULL, 0);
 #endif
 
+      if (testflag(addr, af_pipelining))
+	  rmt_dlv_checked_write(fd, 'L', '1', NULL, 0);
+
       if (testflag(addr, af_chunking_used))
 	rmt_dlv_checked_write(fd, 'K', '0', NULL, 0);
 
diff --git a/src/src/globals.c b/src/src/globals.c
index 10045f482..f1c6a7457 100644
--- a/src/src/globals.c
+++ b/src/src/globals.c
@@ -932,6 +932,7 @@ bit_table log_options[]        = { /* must be in alphabetical order */
   BIT_TABLE(L, outgoing_interface),
   BIT_TABLE(L, outgoing_port),
   BIT_TABLE(L, pid),
+  BIT_TABLE(L, pipelining),
 #if defined(SUPPORT_PROXY) || defined(SUPPORT_SOCKS)
   BIT_TABLE(L, proxy),
 #endif
@@ -1353,6 +1354,7 @@ double  smtp_delay_mail        = 0.0;
 double  smtp_delay_rcpt        = 0.0;
 BOOL    smtp_enforce_sync      = TRUE;
 FILE   *smtp_in                = NULL;
+BOOL    smtp_in_pipelining_advertised = 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 b28aa5e6e..684c05d57 100644
--- a/src/src/globals.h
+++ b/src/src/globals.h
@@ -854,6 +854,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 BOOL    smtp_in_pipelining_advertised; /* server advertised 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/macros.h b/src/src/macros.h
index e7550346c..5c2b0a443 100644
--- a/src/src/macros.h
+++ b/src/src/macros.h
@@ -469,6 +469,7 @@ enum {
   Li_outgoing_interface,
   Li_outgoing_port,
   Li_pid,
+  Li_pipelining,
   Li_proxy,
   Li_queue_time,
   Li_queue_time_overall,
diff --git a/src/src/receive.c b/src/src/receive.c
index 974756f06..39f5b6758 100644
--- a/src/src/receive.c
+++ b/src/src/receive.c
@@ -1320,6 +1320,8 @@ if (sender_ident)
   g = string_append(g, 2, US" U=", 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);
 return g;
 }
 
diff --git a/src/src/smtp_in.c b/src/src/smtp_in.c
index d1c19ea0d..aa85add3e 100644
--- a/src/src/smtp_in.c
+++ b/src/src/smtp_in.c
@@ -146,7 +146,6 @@ static BOOL helo_verify = FALSE;
 static BOOL helo_seen;
 static BOOL helo_accept_junk;
 static BOOL count_nonmail;
-static BOOL pipelining_advertised;
 static BOOL rcpt_smtp_response_same;
 static BOOL rcpt_in_progress;
 static int  nonmail_command_count;
@@ -389,7 +388,7 @@ static BOOL
 pipeline_response(void)
 {
 if (  !smtp_enforce_sync || !sender_host_address
-   || sender_host_notsocket || !pipelining_advertised)
+   || sender_host_notsocket || !smtp_in_pipelining_advertised)
   return FALSE;
 
 return !wouldblock_reading();
@@ -622,7 +621,7 @@ for(;;)
   /* Unless PIPELINING was offered, there should be no next command
   until after we ack that chunk */
 
-  if (!pipelining_advertised && !check_sync())
+  if (!smtp_in_pipelining_advertised && !check_sync())
     {
     unsigned n = smtp_inend - smtp_inptr;
     if (n > 32) n = 32;
@@ -2429,7 +2428,7 @@ count_nonmail = TRUE_UNSET;
 synprot_error_count = unknown_command_count = nonmail_command_count = 0;
 smtp_delay_mail = smtp_rlm_base;
 auth_advertised = FALSE;
-pipelining_advertised = FALSE;
+smtp_in_pipelining_advertised = FALSE;
 pipelining_enable = TRUE;
 sync_cmd_limit = NON_SYNC_CMD_NON_PIPELINING;
 smtp_exit_function_called = FALSE;    /* For avoiding loop in not-quit exit */
@@ -4182,7 +4181,7 @@ while (done <= 0)
     that the entire reply is sent in one write(). */
 
     auth_advertised = FALSE;
-    pipelining_advertised = FALSE;
+    smtp_in_pipelining_advertised = FALSE;
 #ifdef SUPPORT_TLS
     tls_advertised = FALSE;
 # ifdef EXPERIMENTAL_REQUIRETLS
@@ -4308,7 +4307,7 @@ while (done <= 0)
         g = string_catn(g, smtp_code, 3);
         g = string_catn(g, US"-PIPELINING\r\n", 13);
         sync_cmd_limit = NON_SYNC_CMD_PIPELINING;
-        pipelining_advertised = TRUE;
+	smtp_in_pipelining_advertised = TRUE;
         }
 
 
@@ -4873,7 +4872,7 @@ while (done <= 0)
     if (acl_smtp_mail)
       {
       rc = acl_check(ACL_WHERE_MAIL, NULL, acl_smtp_mail, &user_msg, &log_msg);
-      if (rc == OK && !pipelining_advertised && !check_sync())
+      if (rc == OK && !smtp_in_pipelining_advertised && !check_sync())
         goto SYNC_FAILURE;
       }
     else
@@ -4928,7 +4927,7 @@ while (done <= 0)
 
     if (sender_address == NULL)
       {
-      if (pipelining_advertised && last_was_rej_mail)
+      if (smtp_in_pipelining_advertised && last_was_rej_mail)
         {
         smtp_printf("503 sender not yet given\r\n", FALSE);
         was_rej_mail = TRUE;
@@ -5121,7 +5120,7 @@ while (done <= 0)
     else
       if (  (rc = acl_check(ACL_WHERE_RCPT, recipient, acl_smtp_rcpt, &user_msg,
 		    &log_msg)) == OK
-	 && !pipelining_advertised && !check_sync())
+	 && !smtp_in_pipelining_advertised && !check_sync())
         goto SYNC_FAILURE;
 
     /* The ACL was happy */
@@ -5251,7 +5250,7 @@ while (done <= 0)
           rcpt_smtp_response[len-2] = 0;
         smtp_respond(code, 3, FALSE, rcpt_smtp_response);
         }
-      if (pipelining_advertised && last_was_rcpt)
+      if (smtp_in_pipelining_advertised && last_was_rcpt)
         smtp_printf("503 Valid RCPT command must precede %s\r\n", FALSE,
 	  smtp_names[smtp_connection_had[smtp_ch_index-1]]);
       else
@@ -5461,7 +5460,7 @@ while (done <= 0)
     if ((rc = tls_server_start(tls_require_ciphers, &s)) == OK)
       {
       if (!tls_remember_esmtp)
-        helo_seen = esmtp = auth_advertised = pipelining_advertised = FALSE;
+        helo_seen = esmtp = auth_advertised = smtp_in_pipelining_advertised = FALSE;
       cmd_list[CMD_LIST_EHLO].is_mail_cmd = TRUE;
       cmd_list[CMD_LIST_AUTH].is_mail_cmd = TRUE;
       cmd_list[CMD_LIST_TLS_AUTH].is_mail_cmd = TRUE;
@@ -5809,7 +5808,7 @@ while (done <= 0)
     log_write(0, LOG_MAIN|LOG_REJECT, "SMTP protocol synchronization error "
       "(next input sent too soon: pipelining was%s advertised): "
       "rejected \"%s\" %s next input=\"%s\"",
-      pipelining_advertised? "" : " not",
+      smtp_in_pipelining_advertised ? "" : " not",
       smtp_cmd_buffer, host_and_ident(TRUE),
       string_printing(smtp_inptr));
     smtp_notquit_exit(US"synchronization-error", US"554",
diff --git a/src/src/structs.h b/src/src/structs.h
index 9ee3dba8d..bec2b2aa0 100644
--- a/src/src/structs.h
+++ b/src/src/structs.h
@@ -614,7 +614,8 @@ typedef struct address_item {
     BOOL af_pass_message:1;		/* pass message in bounces */
     BOOL af_bad_reply:1;		/* filter could not generate autoreply */
     BOOL af_tcp_fastopen_conn:1;	/* delivery connection used TCP Fast Open */
-    BOOL af_tcp_fastopen:1;		/* delivery usefuly used TCP Fast Open */
+    BOOL af_tcp_fastopen:1;		/* delivery usefully used TCP Fast Open */
+    BOOL af_pipelining:1;		/* delivery used (traditional) pipelining */
 #ifndef DISABLE_PRDR
     BOOL af_prdr_used:1;		/* delivery used SMTP PRDR */
 #endif
diff --git a/src/src/transports/smtp.c b/src/src/transports/smtp.c
index b95913c59..bca8c4941 100644
--- a/src/src/transports/smtp.c
+++ b/src/src/transports/smtp.c
@@ -795,6 +795,7 @@ responses before returning, except after I/O errors and timeouts. */
 
 if (sx->pending_MAIL)
   {
+  DEBUG(D_transport) debug_printf("%s expect mail\n", __FUNCTION__);
   count--;
   if (!smtp_read_response(&sx->inblock, sx->buffer, sizeof(sx->buffer),
 			  '2', ob->command_timeout))
@@ -846,6 +847,7 @@ while (count-- > 0)
   /* The address was accepted */
   addr->host_used = sx->host;
 
+  DEBUG(D_transport) debug_printf("%s expect rcpt\n", __FUNCTION__);
   if (smtp_read_response(&sx->inblock, sx->buffer, sizeof(sx->buffer),
 			  '2', ob->command_timeout))
     {
@@ -963,25 +965,28 @@ if (addr) sx->sync_addr = addr->next;
 /* Handle a response to DATA. If we have not had any good recipients, either
 previously or in this block, the response is ignored. */
 
-if (pending_DATA != 0 &&
-    !smtp_read_response(&sx->inblock, sx->buffer, sizeof(sx->buffer),
-			'3', ob->command_timeout))
+if (pending_DATA != 0)
   {
-  int code;
-  uschar *msg;
-  BOOL pass_message;
-  if (pending_DATA > 0 || (yield & 1) != 0)
+  DEBUG(D_transport) debug_printf("%s expect data\n", __FUNCTION__);
+  if (!smtp_read_response(&sx->inblock, sx->buffer, sizeof(sx->buffer),
+			'3', ob->command_timeout))
     {
-    if (errno == 0 && sx->buffer[0] == '4')
+    int code;
+    uschar *msg;
+    BOOL pass_message;
+    if (pending_DATA > 0 || (yield & 1) != 0)
       {
-      errno = ERRNO_DATA4XX;
-      sx->first_addr->more_errno |= ((sx->buffer[1] - '0')*10 + sx->buffer[2] - '0') << 8;
+      if (errno == 0 && sx->buffer[0] == '4')
+	{
+	errno = ERRNO_DATA4XX;
+	sx->first_addr->more_errno |= ((sx->buffer[1] - '0')*10 + sx->buffer[2] - '0') << 8;
+	}
+      return -3;
       }
-    return -3;
+    (void)check_response(sx->host, &errno, 0, sx->buffer, &code, &msg, &pass_message);
+    DEBUG(D_transport) debug_printf("%s\nerror for DATA ignored: pipelining "
+      "is in use and there were no good recipients\n", msg);
     }
-  (void)check_response(sx->host, &errno, 0, sx->buffer, &code, &msg, &pass_message);
-  DEBUG(D_transport) debug_printf("%s\nerror for DATA ignored: pipelining "
-    "is in use and there were no good recipients\n", msg);
   }
 
 /* All responses read and handled; MAIL (if present) received 2xx and DATA (if
@@ -1925,7 +1930,7 @@ else
      )
     {
     sx->peer_offered = smtp_peer_options;
-    pipelining_active = !!(smtp_peer_options & OPTION_PIPE);
+    sx->pipelining_used = pipelining_active = !!(smtp_peer_options & OPTION_PIPE);
     HDEBUG(D_transport) debug_printf("continued connection, %s TLS\n",
       continue_proxy_cipher ? "proxied" : "verify conn with");
     return OK;
@@ -2214,7 +2219,7 @@ if (continue_hostname == NULL
       }
     }
   }
-pipelining_active = !!(smtp_peer_options & OPTION_PIPE);
+sx->pipelining_used = pipelining_active = !!(smtp_peer_options & OPTION_PIPE);
 
 /* The setting up of the SMTP call is now complete. Any subsequent errors are
 message-specific. */
@@ -3320,6 +3325,8 @@ else
       addr->host_used = host;
       addr->special_action = flag;
       addr->message = conf;
+
+      if (sx.pipelining_used) setflag(addr, af_pipelining);
 #ifndef DISABLE_PRDR
       if (sx.prdr_active) setflag(addr, af_prdr_used);
 #endif
diff --git a/src/src/transports/smtp.h b/src/src/transports/smtp.h
index df9644377..7127fe31f 100644
--- a/src/src/transports/smtp.h
+++ b/src/src/transports/smtp.h
@@ -115,6 +115,7 @@ typedef struct {
   BOOL setting_up:1;
   BOOL esmtp:1;
   BOOL esmtp_sent:1;
+  BOOL pipelining_used:1;
 #ifndef DISABLE_PRDR
   BOOL prdr_active:1;
 #endif