From c9771b0f607127d89018dd79bab6febb14db3d6d Mon Sep 17 00:00:00 2001 From: Jeremy Harris Date: Sun, 15 May 2022 17:10:59 +0100 Subject: [PATCH] Debug: pass ACL-initiated debug through spool residency --- doc/doc-docbook/spec.xfpt | 2 + doc/doc-txt/ChangeLog | 4 +- src/src/acl.c | 3 +- src/src/functions.h | 7 +-- src/src/globals.c | 9 ++-- src/src/globals.h | 2 + src/src/log.c | 42 ++++++++++----- src/src/macros.h | 1 + src/src/spool_in.c | 10 +++- src/src/spool_out.c | 6 +++ test/confs/0628 | 6 ++- test/log/0628 | 7 +++ test/scripts/0000-Basic/0628 | 33 ++++++++++++ test/stderr/0628 | 100 +++++++++++++++++++++++++++++++++++ test/stdout/0628 | 33 ++++++++++++ 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) { @@ -1521,6 +1520,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) { 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: 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: 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: +??? 250 +RCPT TO: +??? 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: errorsto: orcpt: 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 dir 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: 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: +??? 250 +<<< 250 OK +>>> RCPT TO: +??? 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 -- 2.30.2