summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorJeremy Harris <jgh146exb@wizmail.org>2022-05-15 17:10:59 +0100
committerJeremy Harris <jgh146exb@wizmail.org>2022-05-15 17:10:59 +0100
commitc9771b0f607127d89018dd79bab6febb14db3d6d (patch)
tree01ad3b7e0253c225f7e2d5782d5c0ecf18a4c774
parent758fe60790c2f22e2823b5969a622371f03466f8 (diff)
Debug: pass ACL-initiated debug through spool residencyexim-4.96-RC1
-rw-r--r--doc/doc-docbook/spec.xfpt2
-rw-r--r--doc/doc-txt/ChangeLog4
-rw-r--r--src/src/acl.c3
-rw-r--r--src/src/functions.h7
-rw-r--r--src/src/globals.c9
-rw-r--r--src/src/globals.h2
-rw-r--r--src/src/log.c42
-rw-r--r--src/src/macros.h1
-rw-r--r--src/src/spool_in.c10
-rw-r--r--src/src/spool_out.c6
-rw-r--r--test/confs/06286
-rw-r--r--test/log/06287
-rw-r--r--test/scripts/0000-Basic/062833
-rw-r--r--test/stderr/0628100
-rw-r--r--test/stdout/062833
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