summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorJeremy Harris <jgh146exb@wizmail.org>2017-08-06 15:44:13 +0100
committerJeremy Harris <jgh146exb@wizmail.org>2017-08-06 16:43:17 +0100
commit0f1a8658daf8689f0ef0afbb11d0cb589447a57d (patch)
treebdc50be908c1c095a19fd62f2b8ab65490edb780
parentcab0c27721a3c1f3a146e44bcc6462eefb9eb9e7 (diff)
Logging: millisecond time on 'no MAIL' lines. Bug 2102
-rw-r--r--doc/doc-docbook/spec.xfpt2
-rw-r--r--doc/doc-txt/NewStuff3
-rw-r--r--src/src/deliver.c2
-rw-r--r--src/src/functions.h1
-rw-r--r--src/src/globals.c2
-rw-r--r--src/src/globals.h2
-rw-r--r--src/src/smtp_in.c6
-rw-r--r--test/confs/05473
-rw-r--r--test/log/05479
-rw-r--r--test/log/34544
-rwxr-xr-xtest/runtest4
-rw-r--r--test/scripts/0000-Basic/05475
-rw-r--r--test/stderr/05474
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 ********