Debug: pass ACL-initiated debug through spool residencyexim-4.96-RC1

15 files changed, 239 insertions, 26 deletions

diff --git a/doc/doc-docbook/spec.xfpt b/doc/doc-docbook/spec.xfpt
index 76ff4f231..5a76ef215 100644
--- a/doc/doc-docbook/spec.xfpt
+++ b/doc/doc-docbook/spec.xfpt
@@ -31717,6 +31717,8 @@ with &`-d`&, with the output going to a new logfile in the usual logs directory,
 by default called &'debuglog'&.
 
 .new
+Logging set up by the control will be maintained across spool residency.
+
 Options are a slash-separated list.
 If an option takes an argument, the option name and argument are separated by
 an equals character.
diff --git a/doc/doc-txt/ChangeLog b/doc/doc-txt/ChangeLog
index d492a62b7..ac5354c73 100644
--- a/doc/doc-txt/ChangeLog
+++ b/doc/doc-txt/ChangeLog
@@ -70,8 +70,8 @@ JH/15 Fix a resource leak in *BSD.  An off-by-one error resulted in the daemon
       was touched.
 
 JH/16 Debugging initiated by an ACL control now continues through into routing
-      and transport processes, when delivery is immediate.  Previously debugging
-      stopped any time Exim re-execs.
+      and transport processes.  Previously debugging stopped any time Exim
+      re-execs, or for processing a queued message.
 
 JH/17 The "expand" debug selector now gives more detail, specifically on the
       result of expansion operators and items.
diff --git a/src/src/acl.c b/src/src/acl.c
index e2356e188..fb78a7b5f 100644
--- a/src/src/acl.c
+++ b/src/src/acl.c
@@ -3481,8 +3481,7 @@ for (; cb; cb = cb->next)
 
 	case CONTROL_DEBUG:
 	  {
-	  uschar * debug_tag = NULL;
-	  uschar * debug_opts = NULL;
+	  uschar * debug_tag = NULL, * debug_opts = NULL;
 	  BOOL kill = FALSE, stop = FALSE;
 
 	  while (*p == '/')
diff --git a/src/src/functions.h b/src/src/functions.h
index 07df8755b..224666cb1 100644
--- a/src/src/functions.h
+++ b/src/src/functions.h
@@ -187,7 +187,8 @@ extern void    daemon_go(void);
 extern int     dcc_process(uschar **);
 #endif
 
-extern void    debug_logging_activate(uschar *, uschar *);
+extern void    debug_logging_activate(const uschar *, const uschar *);
+extern void    debug_logging_from_spool(const uschar *);
 extern void    debug_logging_stop(BOOL);
 extern void    debug_print_argv(const uschar **);
 extern void    debug_print_ids(uschar *);
@@ -201,7 +202,7 @@ extern void    debug_print_socket(int);
 extern void    debug_trigger_fire(void);
 
 extern void    decode_bits(unsigned int *, size_t, int *,
-	           uschar *, bit_table *, int, uschar *, int);
+	           const uschar *, bit_table *, int, uschar *, int);
 extern void    delete_pid_file(void);
 extern void    deliver_local(address_item *, BOOL);
 extern address_item *deliver_make_addr(uschar *, BOOL);
@@ -323,7 +324,7 @@ extern int     ip_streamsocket(const uschar *, uschar **, int, host_item *);
 extern int     ipv6_nmtoa(int *, uschar *);
 
 extern uschar *local_part_quote(uschar *);
-extern int     log_open_as_exim(uschar * const);
+extern int     log_open_as_exim(const uschar * const);
 extern void    log_close_all(void);
 
 extern macro_item * macro_create(const uschar *, const uschar *, BOOL);
diff --git a/src/src/globals.c b/src/src/globals.c
index 918b2c304..ff246feb4 100644
--- a/src/src/globals.c
+++ b/src/src/globals.c
@@ -814,10 +814,11 @@ bit_table debug_options[]      = { /* must be in alphabetical order and use
   BIT_TABLE(D, uid),
   BIT_TABLE(D, verify),
 };
-int     debug_options_count    = nelem(debug_options);
-unsigned debug_pretrigger_bsize= 0;
-uschar * debug_pretrigger_buf  = NULL;
-unsigned int debug_selector    = 0;
+int      debug_options_count	= nelem(debug_options);
+uschar   debuglog_name[LOG_NAME_SIZE] = {0};
+unsigned debug_pretrigger_bsize	= 0;
+uschar * debug_pretrigger_buf	= NULL;
+unsigned int debug_selector	= 0;
 
 int     delay_warning[DELAY_WARNING_SIZE] = { DELAY_WARNING_SIZE, 1, 24*60*60 };
 uschar *delay_warning_condition=
diff --git a/src/src/globals.h b/src/src/globals.h
index f2de276f3..fe099e402 100644
--- a/src/src/globals.h
+++ b/src/src/globals.h
@@ -493,6 +493,8 @@ extern int     debug_options_count;    /* Size of table */
 extern unsigned debug_pretrigger_bsize;
 extern uschar *debug_pretrigger_buf;   /* circular buffer for precapture */
 extern BOOL    debug_store;	       /* Do extra checks on store_reset */
+extern uschar  debuglog_name[LOG_NAME_SIZE]; /* ACL-init debug */
+
 extern int     delay_warning[];        /* Times between warnings */
 extern uschar *delay_warning_condition; /* Condition string for warnings */
 extern BOOL    delivery_date_remove;   /* Remove delivery-date headers */
diff --git a/src/src/log.c b/src/src/log.c
index 18ea3e0cf..8ca973f2d 100644
--- a/src/src/log.c
+++ b/src/src/log.c
@@ -12,7 +12,6 @@ log files was originally contributed by Tony Sheen. */
 
 #include "exim.h"
 
-#define LOG_NAME_SIZE 256
 #define MAX_SYSLOG_LEN 870
 
 #define LOG_MODE_FILE   1
@@ -30,7 +29,6 @@ static uschar *log_names[] = { US"main", US"reject", US"panic", US"debug" };
 
 static uschar mainlog_name[LOG_NAME_SIZE];
 static uschar rejectlog_name[LOG_NAME_SIZE];
-static uschar debuglog_name[LOG_NAME_SIZE];
 
 static uschar *mainlog_datestamp = NULL;
 static uschar *rejectlog_datestamp = NULL;
@@ -268,7 +266,7 @@ Returns:       a file descriptor, or < 0 on failure (errno set)
 */
 
 static int
-log_open_already_exim(uschar * const name)
+log_open_already_exim(const uschar * const name)
 {
 int fd = -1;
 const int flags = O_WRONLY | O_APPEND | O_CREAT | O_NONBLOCK;
@@ -392,7 +390,7 @@ Returns:       a file descriptor, or < 0 on failure (errno set)
 */
 
 int
-log_open_as_exim(uschar * const name)
+log_open_as_exim(const uschar * const name)
 {
 int fd = -1;
 const uid_t euid = geteuid();
@@ -475,7 +473,7 @@ Returns:   nothing
 */
 
 static void
-open_log(int *fd, int type, uschar *tag)
+open_log(int * fd, int type, const uschar * tag)
 {
 uid_t euid;
 BOOL ok, ok2;
@@ -531,8 +529,8 @@ switch (type)
 
   default:
     /* Remove any datestamp if this is the panic log. This is rare, so there's no
-  need to optimize getting the datestamp length. We remove one non-alphanumeric
-  char afterwards if at the start, otherwise one before. */
+    need to optimize getting the datestamp length. We remove one non-alphanumeric
+    char afterwards if at the start, otherwise one before. */
     if (string_datestamp_offset >= 0)
       {
       uschar * from = buffer + string_datestamp_offset;
@@ -1365,8 +1363,9 @@ Returns:         nothing on success - bomb out on failure
 */
 
 void
-decode_bits(unsigned int *selector, size_t selsize, int *notall,
-  uschar *string, bit_table *options, int count, uschar *which, int flags)
+decode_bits(unsigned int * selector, size_t selsize, int * notall,
+  const uschar * string, bit_table * options, int count, uschar * which,
+  int flags)
 {
 uschar *errmsg;
 if (!string) return;
@@ -1375,7 +1374,7 @@ if (*string == '=')
   {
   char *end;    /* Not uschar */
   memset(selector, 0, sizeof(*selector)*selsize);
-  *selector = strtoul(CS string+1, &end, 0);
+  *selector = strtoul(CCS string+1, &end, 0);
   if (!*end) return;
   errmsg = string_sprintf("malformed numeric %s_selector setting: %s", which,
     string);
@@ -1387,9 +1386,9 @@ if (*string == '=')
 else for(;;)
   {
   BOOL adding;
-  uschar *s;
+  const uschar * s;
   int len;
-  bit_table *start, *end;
+  bit_table * start, * end;
 
   Uskip_whitespace(&string);
   if (!*string) return;
@@ -1485,7 +1484,7 @@ immediately but only upon a trigger - but we'd need another cmdline option
 to pass the name through child_exxec_exim(). */
 
 void
-debug_logging_activate(uschar *tag_name, uschar *opts)
+debug_logging_activate(const uschar * tag_name, const uschar * opts)
 {
 if (debug_file)
   {
@@ -1522,6 +1521,23 @@ else
 
 
 void
+debug_logging_from_spool(const uschar * filename)
+{
+if (debug_fd < 0)
+  {
+  Ustrncpy(debuglog_name, filename, sizeof(debuglog_name));
+  if ((debug_fd = log_open_as_exim(filename)) >= 0)
+    debug_file = fdopen(debug_fd, "w");
+  DEBUG(D_deliver) debug_printf("debug enabled by spoolfile\n");
+  }
+/*
+else DEBUG(D_deliver)
+  debug_printf("debug already active; ignoring spoolfile '%s'\n", filename);
+*/
+}
+
+
+void
 debug_logging_stop(BOOL kill)
 {
 debug_pretrigger_discard();
diff --git a/src/src/macros.h b/src/src/macros.h
index 304e45d33..fa89de12d 100644
--- a/src/src/macros.h
+++ b/src/src/macros.h
@@ -105,6 +105,7 @@ don't make the file descriptors two-way. */
 
 /* Debugging control */
 
+#define LOG_NAME_SIZE 256
 #define DEBUG(x)      if (debug_selector & (x))
 #define HDEBUG(x)     if (host_checking || debug_selector & (x))
 
diff --git a/src/src/spool_in.c b/src/src/spool_in.c
index 82885db56..2aa0b0b55 100644
--- a/src/src/spool_in.c
+++ b/src/src/spool_in.c
@@ -300,6 +300,9 @@ message_smtputf8 = FALSE;
 message_utf8_downconvert = 0;
 #endif
 
+#ifndef COMPILE_UTILITY
+debuglog_name[0] = '\0';
+#endif
 dsn_ret = 0;
 dsn_envid = NULL;
 }
@@ -594,11 +597,16 @@ for (;;)
     case 'd':
     if (Ustrcmp(p, "eliver_firsttime") == 0)
       f.deliver_firsttime = TRUE;
-    /* Check if the dsn flags have been set in the header file */
     else if (Ustrncmp(p, "sn_ret", 6) == 0)
       dsn_ret= atoi(CS var + 7);
     else if (Ustrncmp(p, "sn_envid", 8) == 0)
       dsn_envid = string_copy_taint(var + 10, proto_mem);
+#ifndef COMPILE_UTILITY
+    else if (Ustrncmp(p, "ebug_selector ", 14) == 0)
+      debug_selector = strtol(CS var + 15, NULL, 0);
+    else if (Ustrncmp(p, "ebuglog_name ", 13) == 0)
+      debug_logging_from_spool(var + 14);
+#endif
     break;
 
     case 'f':
diff --git a/src/src/spool_out.c b/src/src/spool_out.c
index e04917ca5..713584091 100644
--- a/src/src/spool_out.c
+++ b/src/src/spool_out.c
@@ -230,6 +230,12 @@ tree_walk(acl_var_m, &acl_var_write, fp);
 
 /* Now any other data that needs to be remembered. */
 
+if (*debuglog_name)
+  {
+  fprintf(fp, "-debug_selector 0x%x\n", debug_selector);
+  fprintf(fp, "-debuglog_name %s\n", debuglog_name);
+  }
+
 if (f.spool_file_wireformat)
   fprintf(fp, "-spool_file_wireformat\n");
 else
diff --git a/test/confs/0628 b/test/confs/0628
index 4369f5a99..9cc337845 100644
--- a/test/confs/0628
+++ b/test/confs/0628
@@ -21,7 +21,11 @@ chk_rcpt:
   accept control =		debug/kill
 
 chk_data:
-  accept control =		debug/tag=_2/opts=+all
+  warn   control =		debug/tag=_2/opts=+all
+.ifdef CONTROL
+	 control =		CONTROL
+.endif
+  accept
 
 
 # ----- Routers -----
diff --git a/test/log/0628 b/test/log/0628
index 1b544f951..9cff3eeef 100644
--- a/test/log/0628
+++ b/test/log/0628
@@ -4,3 +4,10 @@
 1999-03-02 09:44:33 10HmaX-0005vi-00 <= tester@test.ex H=(test.ex) [127.0.0.1] P=esmtp S=sss
 1999-03-02 09:44:33 10HmaX-0005vi-00 => :blackhole: <dest@test.ex> R=r1
 1999-03-02 09:44:33 10HmaX-0005vi-00 Completed
+1999-03-02 09:44:33 exim x.yz daemon started: pid=pppp, no queue runs, listening for SMTP on port PORT_D
+1999-03-02 09:44:33 10HmaY-0005vi-00 <= tester2@test.ex H=(test.ex) [127.0.0.1] P=esmtp S=sss
+1999-03-02 09:44:33 10HmaY-0005vi-00 no immediate delivery: queued by ACL
+1999-03-02 09:44:33 Start queue run: pid=pppp
+1999-03-02 09:44:33 10HmaY-0005vi-00 => :blackhole: <dest2@test.ex> R=r1
+1999-03-02 09:44:33 10HmaY-0005vi-00 Completed
+1999-03-02 09:44:33 End queue run: pid=pppp
diff --git a/test/scripts/0000-Basic/0628 b/test/scripts/0000-Basic/0628
index d227b5acc..e5f37771b 100644
--- a/test/scripts/0000-Basic/0628
+++ b/test/scripts/0000-Basic/0628
@@ -1,6 +1,7 @@
 # debug logging ACL modifier
 munge debuglog_stdout
 #
+# Immediate delivery variant
 exim -DSERVER=server -bd -oX PORT_D
 ****
 #
@@ -29,6 +30,38 @@ QUIT
 #
 killdaemon
 #
+#
+# This time going via a queue-run
+exim -DSERVER=server -DCONTROL=queue_only -bd -oX PORT_D
+****
+client 127.0.0.1 PORT_D
+??? 220
+EHLO test.ex
+??? 250-
+??? 250-
+??? 250-
+??? 250-
+??? 250 
+MAIL FROM:<tester2@test.ex>
+??? 250
+RCPT TO:<dest2@test.ex>
+??? 250
+DATA
+??? 354
+Subject: test.
+
+body
+.
+??? 250
+QUIT
+??? 221
+****
+exim -DNOTDAEMON -DSERVER=server -q
+****
+#
+killdaemon
+#
+#
 1
 cat DIR/spool/log/serverdebuglog_1
 #
diff --git a/test/stderr/0628 b/test/stderr/0628
index ab3ddcb3b..29c50af8c 100644
--- a/test/stderr/0628
+++ b/test/stderr/0628
@@ -1,3 +1,5 @@
+01:01:01 1234 warn: condition test succeeded in ACL "chk_data"
+01:01:01 1234 processing "accept" (TESTSUITE/test-config 28)
 01:01:01 1234 accept: condition test succeeded in ACL "chk_data"
 01:01:01 1234 end of ACL "chk_data": ACCEPT
 01:01:01 1234  ╭considering: ${tod_full}
@@ -106,5 +108,103 @@
 01:01:01 1234 search_tidyup called
 01:01:01 1234 SMTP>>(close on process exit)
 01:01:01 1234 >>>>>>>>>>>>>>>> Exim pid=pppp (daemon-accept) terminating with rc=0 >>>>>>>>>>>>>>>>
+01:01:01 1238 check control = queue_only
+01:01:01 1238 warn: condition test succeeded in ACL "chk_data"
+01:01:01 1238 processing "accept" (TESTSUITE/test-config 28)
+01:01:01 1238 accept: condition test succeeded in ACL "chk_data"
+01:01:01 1238 end of ACL "chk_data": ACCEPT
+01:01:01 1238  ╭considering: ${tod_full}
+01:01:01 1238  ├──expanding: ${tod_full}
+01:01:01 1238  ╰─────result: Tue, 2 Mar 1999 09:44:33 +0000
+01:01:01 1238 Writing spool header file: TESTSUITE/spool//input//hdr.10HmaY-0005vi-00
+01:01:01 1238 DSN: **** SPOOL_OUT - address: <dest2@test.ex> errorsto: <NULL> orcpt: <NULL> dsn_flags: 0x0
+01:01:01 1238 Renaming spool header file: TESTSUITE/spool//input//10HmaY-0005vi-00-H
+01:01:01 1238 Size of headers = sss
+01:01:01 1238 LOG: MAIN
+01:01:01 1238   <= tester2@test.ex H=(test.ex) [127.0.0.1] P=esmtp S=sss
+01:01:01 1238 LOG: delay_delivery MAIN
+01:01:01 1238   no immediate delivery: queued by ACL
+01:01:01 1238 SMTP>> 250 OK id=10HmaY-0005vi-00
+01:01:01 1238 search_tidyup called
+01:01:01 1238 Sender: tester2@test.ex
+01:01:01 1238 Recipients:
+01:01:01 1238   dest2@test.ex
+01:01:01 1238 Process1239  is ready for new message
+01:01:01 1238 smtp_setup_msg entered
+01:01:01 1238 SMTP<< QUIT
+01:01:01 1238 SMTP>> 221 myhost.test.ex closing connection
+01:01:01 1238 LOG: smtp_connection MAIN
+01:01:01 1238   SMTP connection from (test.ex) [127.0.0.1] closed by QUIT
+01:01:01 1238 search_tidyup called
+01:01:01 1238 SMTP>>(close on process exit)
+01:01:01 1238 >>>>>>>>>>>>>>>> Exim pid=pppp (daemon-accept) terminating with rc=0 >>>>>>>>>>>>>>>>
+01:01:01 1240 debug enabled by spoolfile
+01:01:01 1240 sender_fullhost = (test.ex) [127.0.0.1]
+01:01:01 1240 sender_rcvhost = [127.0.0.1] (helo=test.ex)
+01:01:01 1240 sender_local=0 ident=unset
+01:01:01 1240 Non-recipients:
+01:01:01 1240  Empty Tree
+01:01:01 1240 ---- End of tree ----
+01:01:01 1240 recipients_count=1
+01:01:01 1240 **** SPOOL_IN - No additional fields
+01:01:01 1240 body_linecount=1 message_linecount=7
+01:01:01 1240 DSN: set orcpt:   flags: 0x0
+01:01:01 1240 Delivery address list:
+01:01:01 1240   dest2@test.ex 
+01:01:01 1240  locking TESTSUITE/spool/db/retry.lockfile
+01:01:01 1240  locked  TESTSUITE/spool/db/retry.lockfile
+01:01:01 1240  EXIM_DBOPEN: file <TESTSUITE/spool/db/retry> dir <TESTSUITE/spool/db> flags=O_RDONLY
+01:01:01 1240  returned from EXIM_DBOPEN: (nil)
+01:01:01 1240  failed to open DB file TESTSUITE/spool/db/retry: No such file or directory
+01:01:01 1240 no retry data available
+01:01:01 1240 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
+01:01:01 1240 Considering: dest2@test.ex
+01:01:01 1240 unique = dest2@test.ex
+01:01:01 1240 no   domain  retry record
+01:01:01 1240 no   address retry record
+01:01:01 1240 dest2@test.ex: queued for routing
+01:01:01 1240 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
+01:01:01 1240 routing dest2@test.ex
+01:01:01 1240 --------> r1 router <--------
+01:01:01 1240 local_part=dest2 domain=test.ex
+01:01:01 1240 calling r1 router
+01:01:01 1240 rda_interpret (string): ':blackhole:'
+01:01:01 1240 expanded: ':blackhole:'
+01:01:01 1240 file is not a filter file
+01:01:01 1240 parse_forward_list: :blackhole:
+01:01:01 1240 extract item: :blackhole:
+01:01:01 1240 address :blackhole:d
+01:01:01 1240 LOG: MAIN
+01:01:01 1240   => :blackhole: <dest2@test.ex> R=r1
+01:01:01 1240 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
+01:01:01 1240 After routing:
+01:01:01 1240   Local deliveries:
+01:01:01 1240   Remote deliveries:
+01:01:01 1240   Failed addresses:
+01:01:01 1240   Deferred addresses:
+01:01:01 1240 search_tidyup called
+01:01:01 1240 >>>>>>>>>>>>>>>> deliveries are done >>>>>>>>>>>>>>>>
+01:01:01 1240 changed uid/gid: post-delivery tidying
+01:01:01 1240   uid=EXIM_UID gid=EXIM_GID pid=pppp
+01:01:01 1240 set_process_info: pppp tidying up after delivering 10HmaY-0005vi-00
+01:01:01 1240 Processing retry items
+01:01:01 1240 Succeeded addresses:
+01:01:01 1240  dest2@test.ex: no retry items
+01:01:01 1240 Failed addresses:
+01:01:01 1240 Deferred addresses:
+01:01:01 1240 end of retry processing
+01:01:01 1240 DSN: processing router : r1
+01:01:01 1240 DSN: processing successful delivery address: dest2@test.ex
+01:01:01 1240 DSN: Sender_address: tester2@test.ex
+01:01:01 1240 DSN: orcpt: NULL  flags: 0x0
+01:01:01 1240 DSN: envid: NULL  ret: 0
+01:01:01 1240 DSN: Final recipient: dest2@test.ex
+01:01:01 1240 DSN: Remote SMTP server supports DSN: 0
+01:01:01 1240 DSN: not sending DSN success message
+01:01:01 1240 LOG: MAIN
+01:01:01 1240   Completed
+01:01:01 1240 end delivery of 10HmaY-0005vi-00
+01:01:01 1240 search_tidyup called
+01:01:01 1240 >>>>>>>>>>>>>>>> Exim pid=pppp (qrun-delivery) terminating with rc=0 >>>>>>>>>>>>>>>>
 
 ******** SERVER ********
diff --git a/test/stdout/0628 b/test/stdout/0628
index 7311e2d77..959095ee3 100644
--- a/test/stdout/0628
+++ b/test/stdout/0628
@@ -31,3 +31,36 @@ Connecting to 127.0.0.1 port 1225 ... connected
 ??? 221
 <<< 221 myhost.test.ex closing connection
 End of script
+Connecting to 127.0.0.1 port 1225 ... connected
+??? 220
+<<< 220 myhost.test.ex ESMTP Exim x.yz Tue, 2 Mar 1999 09:44:33 +0000
+>>> EHLO test.ex
+??? 250-
+<<< 250-myhost.test.ex Hello test.ex [127.0.0.1]
+??? 250-
+<<< 250-SIZE 52428800
+??? 250-
+<<< 250-8BITMIME
+??? 250-
+<<< 250-PIPELINING
+??? 250 
+<<< 250 HELP
+>>> MAIL FROM:<tester2@test.ex>
+??? 250
+<<< 250 OK
+>>> RCPT TO:<dest2@test.ex>
+??? 250
+<<< 250 Accepted
+>>> DATA
+??? 354
+<<< 354 Enter message, ending with "." on a line by itself
+>>> Subject: test.
+>>> 
+>>> body
+>>> .
+??? 250
+<<< 250 OK id=10HmaY-0005vi-00
+>>> QUIT
+??? 221
+<<< 221 myhost.test.ex closing connection
+End of script