Logging: millisecond time on 'no MAIL' lines. Bug 2102

13 files changed, 26 insertions, 21 deletions

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 ********