From: Jeremy Harris Date: Sun, 6 Aug 2017 14:44:13 +0000 (+0100) Subject: Logging: millisecond time on 'no MAIL' lines. Bug 2102 X-Git-Tag: exim-4_90_RC1~96 X-Git-Url: https://git.exim.org/exim.git/commitdiff_plain/0f1a8658daf8689f0ef0afbb11d0cb589447a57d Logging: millisecond time on 'no MAIL' lines. Bug 2102 --- diff --git a/doc/doc-docbook/spec.xfpt b/doc/doc-docbook/spec.xfpt index 0d03c2f9c..35f3eb80e 100644 --- a/doc/doc-docbook/spec.xfpt +++ b/doc/doc-docbook/spec.xfpt @@ -36118,7 +36118,7 @@ selection marked by asterisks: &` incoming_interface `& local interface on <= and => lines &` incoming_port `& remote port on <= lines &`*lost_incoming_connection `& as it says (includes timeouts) -&` millisec `& millisecond timestamps and QT/DT times +&` millisec `& millisecond timestamps and QT,DT,D times &` outgoing_interface `& local interface on => lines &` outgoing_port `& add remote port to => lines &`*queue_run `& start and end queue runs diff --git a/doc/doc-txt/NewStuff b/doc/doc-txt/NewStuff index ea757f059..3e1da34ee 100644 --- a/doc/doc-txt/NewStuff +++ b/doc/doc-txt/NewStuff @@ -44,7 +44,8 @@ Version 4.90 10. Variable $smtp_command_history returning a comma-sep list of recent SMTP commands. -11. Millisecond timetamps in logs, on log_selector "millisec". +11. Millisecond timetamps in logs, on log_selector "millisec". Also affects + log elements QT, DT and D, and timstamps in debug output. Version 4.89 diff --git a/src/src/deliver.c b/src/src/deliver.c index e7ca9e054..0f2efbecf 100644 --- a/src/src/deliver.c +++ b/src/src/deliver.c @@ -1058,7 +1058,7 @@ return buf; } -static uschar * +uschar * string_timesince(struct timeval * then) { struct timeval diff; diff --git a/src/src/functions.h b/src/src/functions.h index 5b2a683b8..c9d00df10 100644 --- a/src/src/functions.h +++ b/src/src/functions.h @@ -460,6 +460,7 @@ extern uschar *string_nextinlist(const uschar **, int *, uschar *, int); extern uschar *string_open_failed(int, const char *, ...) PRINTF_FUNCTION(2,3); extern const uschar *string_printing2(const uschar *, BOOL); extern uschar *string_split_message(uschar *); +extern uschar *string_timesince(struct timeval *); extern uschar *string_unprinting(uschar *); #ifdef SUPPORT_I18N extern uschar *string_address_utf8_to_alabel(const uschar *, uschar **); diff --git a/src/src/globals.c b/src/src/globals.c index 894b59967..9abacff8c 100644 --- a/src/src/globals.c +++ b/src/src/globals.c @@ -1308,7 +1308,7 @@ BOOL smtp_check_spool_space = TRUE; int smtp_ch_index = 0; uschar *smtp_cmd_argument = NULL; uschar *smtp_cmd_buffer = NULL; -time_t smtp_connection_start = 0; +struct timeval smtp_connection_start = {0,0}; uschar smtp_connection_had[SMTP_HBUFF_SIZE]; int smtp_connect_backlog = 20; double smtp_delay_mail = 0.0; diff --git a/src/src/globals.h b/src/src/globals.h index 2d26bd0d7..bd8d14288 100644 --- a/src/src/globals.h +++ b/src/src/globals.h @@ -820,7 +820,7 @@ extern BOOL smtp_check_spool_space; /* TRUE to check SMTP SIZE value */ extern int smtp_ch_index; /* Index in smtp_connection_had */ extern uschar *smtp_cmd_argument; /* For all SMTP commands */ extern uschar *smtp_cmd_buffer; /* SMTP command buffer */ -extern time_t smtp_connection_start; /* Start time of SMTP connection */ +extern struct timeval smtp_connection_start; /* Start time of SMTP connection */ extern uschar smtp_connection_had[]; /* Recent SMTP commands */ extern int smtp_connect_backlog; /* Max backlog permitted */ extern double smtp_delay_mail; /* Current MAIL delay */ diff --git a/src/src/smtp_in.c b/src/src/smtp_in.c index 3d5ad863f..48437c380 100644 --- a/src/src/smtp_in.c +++ b/src/src/smtp_in.c @@ -1797,9 +1797,7 @@ for (i = 0; i < smtp_ch_index; i++) if (s) s[ptr] = 0; else s = US""; log_write(0, LOG_MAIN, "no MAIL in SMTP connection from %s D=%s%s", - host_and_ident(FALSE), - readconf_printtime( (int) ((long)time(NULL) - (long)smtp_connection_start)), - s); + host_and_ident(FALSE), string_timesince(&smtp_connection_start), s); } @@ -2353,7 +2351,7 @@ uschar *user_msg, *log_msg; uschar *code, *esc; uschar *p, *s, *ss; -smtp_connection_start = time(NULL); +gettimeofday(&smtp_connection_start, NULL); for (smtp_ch_index = 0; smtp_ch_index < SMTP_HBUFF_SIZE; smtp_ch_index++) smtp_connection_had[smtp_ch_index] = SCH_NONE; smtp_ch_index = 0; diff --git a/test/confs/0547 b/test/confs/0547 index 5d172447e..f3442b25b 100644 --- a/test/confs/0547 +++ b/test/confs/0547 @@ -1,6 +1,7 @@ # Exim test configuration 0547 MAXNM = 100 +LOG_SELECTOR = .include DIR/aux-var/std_conf_prefix @@ -10,7 +11,7 @@ primary_hostname = myhost.test.ex acl_smtp_rcpt = accept -log_selector = +smtp_no_mail +log_selector = +smtp_no_mail LOG_SELECTOR smtp_accept_max_nonmail = MAXNM diff --git a/test/log/0547 b/test/log/0547 index 34defc347..79b4ace5b 100644 --- a/test/log/0547 +++ b/test/log/0547 @@ -1,9 +1,10 @@ 1999-03-02 09:44:33 U=CALLER rejected EXPN x@y -1999-03-02 09:44:33 no MAIL in SMTP connection from CALLER D=0s C=EXPN,QUIT +1999-03-02 09:44:33 no MAIL in SMTP connection from CALLER D=qqs C=EXPN,QUIT ******** SERVER ******** +2017-07-30 18:51:05.712 exim x.yz daemon started: pid=pppp, no queue runs, listening for SMTP on port 1225 +2017-07-30 18:51:05.712 no MAIL in SMTP connection from [127.0.0.1] D=q.qqqs 1999-03-02 09:44:33 exim x.yz daemon started: pid=pppp, no queue runs, listening for SMTP on port 1225 -1999-03-02 09:44:33 no MAIL in SMTP connection from [127.0.0.1] D=0s -1999-03-02 09:44:33 no MAIL in SMTP connection from [127.0.0.1] D=0s C=QUIT +1999-03-02 09:44:33 no MAIL in SMTP connection from [127.0.0.1] D=qqs C=QUIT 1999-03-02 09:44:33 H=(x.y.z) [127.0.0.1] rejected VRFY a@b.c -1999-03-02 09:44:33 no MAIL in SMTP connection from (x.y.z) [127.0.0.1] D=0s C=EHLO,VRFY,QUIT +1999-03-02 09:44:33 no MAIL in SMTP connection from (x.y.z) [127.0.0.1] D=qqs C=EHLO,VRFY,QUIT diff --git a/test/log/3454 b/test/log/3454 index d047667e7..7578fc090 100644 --- a/test/log/3454 +++ b/test/log/3454 @@ -3,5 +3,5 @@ 1999-03-02 09:44:33 exim x.yz daemon started: pid=pppp, no queue runs, listening for SMTP on port 1225 1999-03-02 09:44:33 TLS error on connection from [127.0.0.1] (recv): The TLS connection was non-properly terminated. 1999-03-02 09:44:33 TLS error on connection from [127.0.0.1] (send): The specified session has been invalidated for some reason. -1999-03-02 09:44:33 no MAIL in SMTP connection from [127.0.0.1] D=0s X=TLS1.x:xxxxRSA_AES_256_CBC_SHAnnn:256 CV=no C=EHLO,STARTTLS,AUTH -1999-03-02 09:44:33 no MAIL in SMTP connection from (foobar) [127.0.0.1] D=0s A=plain:userx X=TLS1.x:xxxxRSA_AES_256_CBC_SHAnnn:256 CV=no C=EHLO,STARTTLS,EHLO,AUTH,QUIT +1999-03-02 09:44:33 no MAIL in SMTP connection from [127.0.0.1] D=qqs X=TLS1.x:xxxxRSA_AES_256_CBC_SHAnnn:256 CV=no C=EHLO,STARTTLS,AUTH +1999-03-02 09:44:33 no MAIL in SMTP connection from (foobar) [127.0.0.1] D=qqs A=plain:userx X=TLS1.x:xxxxRSA_AES_256_CBC_SHAnnn:256 CV=no C=EHLO,STARTTLS,EHLO,AUTH,QUIT diff --git a/test/runtest b/test/runtest index 90c1758ca..712ab79bc 100755 --- a/test/runtest +++ b/test/runtest @@ -491,8 +491,8 @@ RESET_AFTER_EXTRA_LINE_READ: s/^\d{4}-\d\d-\d\d\s\d\d:\d\d:\d\d\.\d{3}(\s[+-]\d\d\d\d)?\s/2017-07-30 18:51:05.712 /gx; s/^Logwrite\s"\d{4}-\d\d-\d\d\s\d\d:\d\d:\d\d/Logwrite "1999-03-02 09:44:33/gx; - s/([QD]T=)\d+s/$1qqs/g; - s/([QD]T=)\d\.\d{3}s/$1q.qqqs/g; + s/((D|[QD]T)=)\d+s/$1qqs/g; + s/((D|[QD]T)=)\d\.\d{3}s/$1q.qqqs/g; # Date/time in message separators s/(?:[A-Z][a-z]{2}\s){2}\d\d\s\d\d:\d\d:\d\d\s\d\d\d\d diff --git a/test/scripts/0000-Basic/0547 b/test/scripts/0000-Basic/0547 index 2595eff48..a645802a1 100644 --- a/test/scripts/0000-Basic/0547 +++ b/test/scripts/0000-Basic/0547 @@ -1,11 +1,14 @@ # log_selector = +smtp_no_mail need_ipv4 # -exim -DSERVER=server -bd -oX PORT_D +exim -DSERVER=server -DLOG_SELECTOR=+millisec -bd -oX PORT_D **** client 127.0.0.1 PORT_D ??? 220 **** +killdaemon +exim -DSERVER=server -bd -oX PORT_D +**** client 127.0.0.1 PORT_D ??? 220 quit diff --git a/test/stderr/0547 b/test/stderr/0547 index 980da7a0b..539328631 100644 --- a/test/stderr/0547 +++ b/test/stderr/0547 @@ -8,7 +8,7 @@ >>> host in helo_accept_junk_hosts? no (option unset) >>> rhu.barb in helo_lookup_domains? no (end of list) >>> host in smtp_accept_max_nonmail_hosts? yes (matched "*") -LOG: no MAIL in SMTP connection from (rhu.barb) [10.9.8.7] D=0s C=...HELP,RSET,NOOP,HELP,RSET,NOOP,HELP,RSET,NOOP,HELP,RSET,NOOP,HELP,RSET,NOOP,HELP,RSET,NOOP,HELP,QUIT +LOG: no MAIL in SMTP connection from (rhu.barb) [10.9.8.7] D=qqs C=...HELP,RSET,NOOP,HELP,RSET,NOOP,HELP,RSET,NOOP,HELP,RSET,NOOP,HELP,RSET,NOOP,HELP,RSET,NOOP,HELP,QUIT >>> host in hosts_connection_nolog? no (option unset) >>> host in host_lookup? no (option unset) >>> host in host_reject_connection? no (option unset) @@ -20,6 +20,6 @@ LOG: no MAIL in SMTP connection from (rhu.barb) [10.9.8.7] D=0s C=...HELP,RSET,N >>> rhu.barb in helo_lookup_domains? no (end of list) >>> host in smtp_accept_max_nonmail_hosts? yes (matched "*") LOG: SMTP call from (rhu.barb) [10.9.8.7] dropped: too many nonmail commands (last was "HELP") -LOG: no MAIL in SMTP connection from (rhu.barb) [10.9.8.7] D=0s C=HELO,RSET,NOOP,HELP,RSET,NOOP,HELP,RSET,NOOP,HELP,RSET,NOOP +LOG: no MAIL in SMTP connection from (rhu.barb) [10.9.8.7] D=qqs C=HELO,RSET,NOOP,HELP,RSET,NOOP,HELP,RSET,NOOP,HELP,RSET,NOOP ******** SERVER ********