Debug: build a summary string tracking transport SMTP commands & responses

11 files changed, 106 insertions, 19 deletions

diff --git a/src/src/EDITME b/src/src/EDITME
index d21a45eda..53022e593 100644
--- a/src/src/EDITME
+++ b/src/src/EDITME
@@ -1489,4 +1489,9 @@ EXIM_TMPDIR="/tmp"
 # For development, add this to include code to time various stages and report.
 # CFLAGS += -DMEASURE_TIMING
 
+# For a very slightly smaller build, for constrained systems, uncomment this.
+# The feature involved is purely for debugging.
+
+# DISABLE_CLIENT_CMD_LOG=yes
+
 # End of EDITME for Exim 4.
diff --git a/src/src/config.h.defaults b/src/src/config.h.defaults
index 8a3de3f58..6ddece4d0 100644
--- a/src/src/config.h.defaults
+++ b/src/src/config.h.defaults
@@ -46,6 +46,9 @@ Do not put spaces between # and the 'define'.
 #define DEFAULT_CRYPT              crypt
 #define DELIVER_IN_BUFFER_SIZE     8192
 #define DELIVER_OUT_BUFFER_SIZE    8192
+
+#define DISABLE_CLIENT_CMD_LOG
+#define DISABLE_D_OPTION
 #define DISABLE_DNSSEC
 #define DISABLE_DKIM
 #define DISABLE_EVENT
@@ -55,7 +58,6 @@ Do not put spaces between # and the 'define'.
 #define DISABLE_QUEUE_RAMP
 #define DISABLE_TLS
 #define DISABLE_TLS_RESUME
-#define DISABLE_D_OPTION
 
 #define ENABLE_DISABLE_FSYNC
 
diff --git a/src/src/functions.h b/src/src/functions.h
index f52c155b0..5ecef6ad0 100644
--- a/src/src/functions.h
+++ b/src/src/functions.h
@@ -1253,6 +1253,42 @@ struct pollfd p = {.fd = fd, .events = pollbits};
 return poll(&p, 1, tmo_millisec);
 }
 
+/******************************************************************************/
+/* Client-side smtp log string, for debug */
+
+static inline void
+smtp_debug_cmd(const uschar * buf, int mode)
+{
+HDEBUG(D_transport|D_acl|D_v) debug_printf_indent("  SMTP%c> %s\n",
+  mode == SCMD_BUFFER ? '|' : mode == SCMD_MORE ? '+' : '>', buf);
+
+#  ifndef DISABLE_CLIENT_CMD_LOG
+  {
+  int old_pool = store_pool;
+  store_pool = POOL_PERM;	/* Main pool ACL allocations eg. callouts get released */
+  client_cmd_log = string_append_listele_n(client_cmd_log, ':', buf,
+  					  Ustrcspn(buf, " \n"));
+  if (mode == SCMD_BUFFER) 
+    {
+    client_cmd_log = string_catn(client_cmd_log, US"|", 1); 
+    (void) string_from_gstring(client_cmd_log);
+    }
+  store_pool = old_pool;
+  }
+#  endif
+}
+
+
+static inline void
+smtp_debug_cmd_report(void)
+{
+#  ifndef DISABLE_CLIENT_CMD_LOG
+debug_printf("cmdlog: '%s'\n", client_cmd_log ? client_cmd_log->s : US"(unset)");
+#  endif
+}
+
+
+
 # endif	/* !COMPILE_UTILITY */
 
 /******************************************************************************/
diff --git a/src/src/globals.c b/src/src/globals.c
index c3cccf1f2..844ff7bac 100644
--- a/src/src/globals.c
+++ b/src/src/globals.c
@@ -712,6 +712,9 @@ const pcre2_code *regex_LIMITS        = NULL;
 uschar *client_authenticator   = NULL;
 uschar *client_authenticated_id = NULL;
 uschar *client_authenticated_sender = NULL;
+#ifndef DISABLE_CLIENT_CMD_LOG
+gstring *client_cmd_log        = NULL;
+#endif
 int     clmacro_count          = 0;
 uschar *clmacros[MAX_CLMACROS];
 FILE   *config_file            = NULL;
diff --git a/src/src/globals.h b/src/src/globals.h
index f447b0096..8a6405b47 100644
--- a/src/src/globals.h
+++ b/src/src/globals.h
@@ -421,6 +421,9 @@ extern chunking_state_t chunking_state;
 extern uschar *client_authenticator;        /* Authenticator name used for smtp delivery */
 extern uschar *client_authenticated_id;     /* "login" name used for SMTP AUTH */
 extern uschar *client_authenticated_sender; /* AUTH option to SMTP MAIL FROM (not yet used) */
+#ifndef DISABLE_CLIENT_CMD_LOG
+extern gstring *client_cmd_log;	       /* debug log of client cmds & responses */
+#endif
 extern int     clmacro_count;          /* Number of command line macros */
 extern uschar *clmacros[];             /* Copy of them, for re-exec */
 extern BOOL    commandline_checks_require_admin; /* belt and braces for insecure setups */
diff --git a/src/src/smtp_out.c b/src/src/smtp_out.c
index 06f6ce29c..7b8212477 100644
--- a/src/src/smtp_out.c
+++ b/src/src/smtp_out.c
@@ -596,6 +596,22 @@ return TRUE;
 
 
 
+/* This might be called both due to callout and then from delivery.
+Use memory that will not be released between those phases.
+*/
+static void
+smtp_debug_resp(const uschar * buf)
+{
+#ifndef DISABLE_CLIENT_CMD_LOG
+int old_pool = store_pool;
+store_pool = POOL_PERM;
+client_cmd_log = string_append_listele_n(client_cmd_log, ':', buf,
+  buf[3] == ' ' ? 3 : 4);
+store_pool = old_pool;
+#endif
+}
+
+
 /*************************************************
 *             Write SMTP command                 *
 *************************************************/
@@ -617,7 +633,7 @@ Returns:     0 if command added to pipelining buffer, with nothing transmitted
 */
 
 int
-smtp_write_command(void * sx, int mode, const char *format, ...)
+smtp_write_command(void * sx, int mode, const char * format, ...)
 {
 smtp_outblock * outblock = &((smtp_context *)sx)->outblock;
 int rc = 0;
@@ -673,9 +689,7 @@ if (format)
     while (*p) *p++ = '*';
     }
 
-  HDEBUG(D_transport|D_acl|D_v) debug_printf_indent("  SMTP%c> %s\n",
-    mode == SCMD_BUFFER ? '|' : mode == SCMD_MORE ? '+' : '>',
-    big_buffer);
+  smtp_debug_cmd(big_buffer, mode);
   }
 
 if (mode != SCMD_BUFFER)
@@ -813,8 +827,10 @@ smtp_context * sx = sx0;
 uschar * ptr = buffer;
 int count = 0;
 time_t timelimit = time(NULL) + timeout;
+BOOL yield = FALSE;
 
 errno = 0;  /* Ensure errno starts out zero */
+buffer[0] = '\0';
 
 #ifndef DISABLE_PIPE_CONNECT
 if (sx->pending_BANNER || sx->pending_EHLO)
@@ -823,9 +839,8 @@ if (sx->pending_BANNER || sx->pending_EHLO)
   if ((rc = smtp_reap_early_pipe(sx, &count)) != OK)
     {
     DEBUG(D_transport) debug_printf("failed reaping pipelined cmd responsess\n");
-    buffer[0] = '\0';
     if (rc == DEFER) errno = ERRNO_TLSFAILURE;
-    return FALSE;
+    goto out;
     }
   }
 #endif
@@ -856,7 +871,7 @@ for (;;)
      (ptr[3] != '-' && ptr[3] != ' ' && ptr[3] != 0))
     {
     errno = ERRNO_SMTPFORMAT;    /* format error */
-    return FALSE;
+    goto out;
     }
 
   /* If the line we have just read is a terminal line, line, we are done.
@@ -884,7 +899,11 @@ distinguish between an unexpected return code and other errors such as
 timeouts, lost connections, etc. */
 
 errno = 0;
-return buffer[0] == okdigit;
+yield = buffer[0] == okdigit;
+
+out:
+  smtp_debug_resp(buffer);
+  return yield;
 }
 
 /* End of smtp_out.c */
diff --git a/src/src/store.c b/src/src/store.c
index 1e555cc18..ffc1ca8e6 100644
--- a/src/src/store.c
+++ b/src/src/store.c
@@ -259,7 +259,7 @@ return NULL;
 }
 
 static pooldesc *
-pool_for_pointer(const void * p)
+pool_for_pointer(const void * p, const char * func, int linenumber)
 {
 pooldesc * pp;
 storeblock * b;
@@ -274,7 +274,8 @@ for (pp = paired_pools; pp < paired_pools + N_PAIRED_POOLS; pp++)
   for (b = pp->chainbase; b; b = b->next)
     if (is_pointer_in_block(b, p)) return pp;
 
-log_write(0, LOG_MAIN|LOG_PANIC_DIE, "bad memory reference; pool not found");
+log_write(0, LOG_MAIN|LOG_PANIC_DIE,
+  "bad memory reference; pool not found, at %s %d", func, linenumber);
 return NULL;
 }
 
@@ -713,7 +714,7 @@ BOOL
 store_extend_3(void * ptr, int oldsize, int newsize,
    const char * func, int linenumber)
 {
-pooldesc * pp = pool_for_pointer(ptr);
+pooldesc * pp = pool_for_pointer(ptr, func, linenumber);
 int inc = newsize - oldsize;
 int rounded_oldsize = oldsize;
 
@@ -1105,7 +1106,7 @@ void *
 store_newblock_3(void * oldblock, int newsize, int len,
   const char * func, int linenumber)
 {
-pooldesc * pp = pool_for_pointer(oldblock);
+pooldesc * pp = pool_for_pointer(oldblock, func, linenumber);
 BOOL release_ok = !is_tainted(oldblock) && pp->store_last_get == oldblock;		/*XXX why tainted not handled? */
 uschar * newblock;
 
diff --git a/src/src/string.c b/src/src/string.c
index 4d870ec9a..c23055d47 100644
--- a/src/src/string.c
+++ b/src/src/string.c
@@ -1166,6 +1166,13 @@ if (!g)
   unsigned size = ((count + inc) &  ~inc) + 1;	/* round up requested count */
   g = string_get_tainted(size, s);
   }
+else if (!g->s)			/* should not happen */
+  {
+  g->s = string_copyn(s, count);
+  g->ptr = count;
+  g->size = count;	/*XXX suboptimal*/
+  return g;
+  }
 else if (is_incompatible(g->s, s))
   {
 /* debug_printf("rebuf A\n"); */
diff --git a/src/src/transport.c b/src/src/transport.c
index fbd0bb39b..428d522ad 100644
--- a/src/src/transport.c
+++ b/src/src/transport.c
@@ -1155,8 +1155,12 @@ f.spool_file_wireformat = FALSE;
 
 /* If requested, add a terminating "." line (SMTP output). */
 
-if (tctx->options & topt_end_dot && !write_chunk(tctx, US".\n", 2))
-  return FALSE;
+if (tctx->options & topt_end_dot)
+  {
+  smtp_debug_cmd(US".", 0);
+  if (!write_chunk(tctx, US".\n", 2))
+    return FALSE;
+  }
 
 /* Write out any remaining data in the buffer before returning. */
 
@@ -1426,7 +1430,7 @@ if (yield)
         ? !write_chunk(tctx, US".\n", 2)
 	: !write_chunk(tctx, US"\n.\n", 3)
      )  )
-    yield = FALSE;
+    { smtp_debug_cmd(US".", 0); yield = FALSE; }
 
   /* Write out any remaining data in the buffer. */
 
diff --git a/src/src/transports/smtp.c b/src/src/transports/smtp.c
index 524f18633..e38ea1502 100644
--- a/src/src/transports/smtp.c
+++ b/src/src/transports/smtp.c
@@ -2155,7 +2155,7 @@ if (continue_hostname && continue_proxy_cipher)
     DEBUG(D_transport)
       debug_printf("Closing proxied-TLS connection due to SNI mismatch\n");
 
-    HDEBUG(D_transport|D_acl|D_v) debug_printf_indent("  SMTP>> QUIT\n");
+    smtp_debug_cmd(US"QUIT", 0);
     write(0, "QUIT\r\n", 6);
     close(0);
     continue_hostname = continue_proxy_cipher = NULL;
@@ -2239,6 +2239,9 @@ if (!continue_hostname)
   sx->peer_limit_mail = sx->peer_limit_rcpt = sx->peer_limit_rcptdom =
 #endif
   sx->avoid_option = sx->peer_offered = smtp_peer_options = 0;
+#ifndef DISABLE_CLIENT_CMD_LOG
+  client_cmd_log = NULL;
+#endif
 
 #ifndef DISABLE_PIPE_CONNECT
   if (  verify_check_given_host(CUSS &ob->hosts_pipe_connect,
@@ -3170,6 +3173,7 @@ sx->cctx.sock = -1;
 (void) event_raise(sx->conn_args.tblock->event_action, US"tcp:close", NULL, NULL);
 #endif
 
+smtp_debug_cmd_report();
 continue_transport = NULL;
 continue_hostname = NULL;
 return yield;
@@ -4831,6 +4835,7 @@ HDEBUG(D_transport|D_acl|D_v) debug_printf_indent("  SMTP(close)>>\n");
 sx->cctx.sock = -1;
 continue_transport = NULL;
 continue_hostname = NULL;
+smtp_debug_cmd_report();
 
 #ifndef DISABLE_EVENT
 (void) event_raise(tblock->event_action, US"tcp:close", NULL, NULL);
diff --git a/src/src/verify.c b/src/src/verify.c
index d78b8bf24..12e39d603 100644
--- a/src/src/verify.c
+++ b/src/src/verify.c
@@ -1126,6 +1126,7 @@ no_conn:
 	HDEBUG(D_transport|D_acl|D_v) debug_printf_indent("  SMTP(close)>>\n");
 	(void)close(sx->cctx.sock);
 	sx->cctx.sock = -1;
+	smtp_debug_cmd_report();
 #ifndef DISABLE_EVENT
 	(void) event_raise(addr->transport->event_action, US"tcp:close", NULL, NULL);
 #endif
@@ -1346,7 +1347,7 @@ cutthrough_predata(void)
 if(cutthrough.cctx.sock < 0 || cutthrough.callout_hold_only)
   return FALSE;
 
-HDEBUG(D_transport|D_acl|D_v) debug_printf_indent("  SMTP>> DATA\n");
+smtp_debug_cmd(US"DATA", 0);
 cutthrough_puts(US"DATA\r\n", 6);
 cutthrough_flush_send();
 
@@ -1414,7 +1415,7 @@ if(fd >= 0)
   */
   client_conn_ctx tmp_ctx = cutthrough.cctx;
   ctctx.outblock.ptr = ctbuffer;
-  HDEBUG(D_transport|D_acl|D_v) debug_printf_indent("  SMTP>> QUIT\n");
+  smtp_debug_cmd(US"QUIT", 0);
   _cutthrough_puts(US"QUIT\r\n", 6);	/* avoid recursion */
   _cutthrough_flush_send();
   cutthrough.cctx.sock = -1;		/* avoid recursion via read timeout */
@@ -1433,6 +1434,7 @@ if(fd >= 0)
 #endif
   HDEBUG(D_transport|D_acl|D_v) debug_printf_indent("  SMTP(close)>>\n");
   (void)close(fd);
+  smtp_debug_cmd_report();
   HDEBUG(D_acl) debug_printf_indent("----------- cutthrough shutdown (%s) ------------\n", why);
   }
 ctctx.outblock.ptr = ctbuffer;