Logging: millisecond time on 'no MAIL' lines. Bug 2102
authorJeremy Harris <jgh146exb@wizmail.org>
Sun, 6 Aug 2017 14:44:13 +0000 (15:44 +0100)
committerJeremy Harris <jgh146exb@wizmail.org>
Sun, 6 Aug 2017 15:43:17 +0000 (16:43 +0100)
13 files changed:
doc/doc-docbook/spec.xfpt
doc/doc-txt/NewStuff
src/src/deliver.c
src/src/functions.h
src/src/globals.c
src/src/globals.h
src/src/smtp_in.c
test/confs/0547
test/log/0547
test/log/3454
test/runtest
test/scripts/0000-Basic/0547
test/stderr/0547

index 0d03c2f..35f3eb8 100644 (file)
@@ -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
index ea757f0..3e1da34 100644 (file)
@@ -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
index e7ca9e0..0f2efbe 100644 (file)
@@ -1058,7 +1058,7 @@ return buf;
 }
 
 
-static uschar *
+uschar *
 string_timesince(struct timeval * then)
 {
 struct timeval diff;
index 5b2a683..c9d00df 100644 (file)
@@ -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 **);
index 894b599..9abacff 100644 (file)
@@ -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;
index 2d26bd0..bd8d142 100644 (file)
@@ -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 */
index 3d5ad86..48437c3 100644 (file)
@@ -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;
index 5d17244..f3442b2 100644 (file)
@@ -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
 
index 34defc3..79b4ace 100644 (file)
@@ -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
index d047667..7578fc0 100644 (file)
@@ -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
index 90c1758..712ab79 100755 (executable)
@@ -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
index 2595eff..a645802 100644 (file)
@@ -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
index 980da7a..5393286 100644 (file)
@@ -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 ********