Gitweb:
https://git.exim.org/exim.git/commitdiff/f870028fd26f8ac1a2fcb6e43e0d7d1c76c110ec
Commit: f870028fd26f8ac1a2fcb6e43e0d7d1c76c110ec
Parent: 5cd1d1356732d96d49a1f7c682d1b8a33b2576f9
Author: Jeremy Harris <jgh146exb@???>
AuthorDate: Sun Apr 11 16:39:06 2021 +0100
Committer: Jeremy Harris <jgh146exb@???>
CommitDate: Fri Apr 16 15:38:09 2021 +0100
Log queue_time and queue_time_overall exclusive of receive time. Bug 2672
---
doc/doc-docbook/spec.xfpt | 10 +++-------
doc/doc-txt/ChangeLog | 5 +++++
doc/doc-txt/NewStuff | 3 +++
src/exim_monitor/em_globals.c | 1 +
src/src/deliver.c | 4 ++--
src/src/functions.h | 19 +++++++++++++------
src/src/globals.c | 4 +++-
src/src/globals.h | 4 ++--
src/src/macros.h | 1 +
src/src/receive.c | 8 ++++++--
src/src/spool_in.c | 14 ++++++++++++++
src/src/spool_out.c | 2 ++
test/runtest | 3 ++-
test/stdout/0035 | 7 +++++++
test/stdout/0245 | 1 +
test/stdout/0250 | 3 +++
test/stdout/0254 | 3 +++
test/stdout/0311 | 2 ++
test/stdout/0338 | 1 +
test/stdout/0377 | 1 +
test/stdout/0378 | 1 +
test/stdout/0379 | 1 +
test/stdout/0389 | 1 +
test/stdout/0488 | 1 +
test/stdout/0490 | 1 +
test/stdout/0514 | 1 +
test/stdout/3415 | 5 +++++
27 files changed, 86 insertions(+), 21 deletions(-)
diff --git a/doc/doc-docbook/spec.xfpt b/doc/doc-docbook/spec.xfpt
index 437b13d..36be62f 100644
--- a/doc/doc-docbook/spec.xfpt
+++ b/doc/doc-docbook/spec.xfpt
@@ -38672,6 +38672,7 @@ selection marked by asterisks:
&` outgoing_port `& add remote port to => lines
&`*queue_run `& start and end queue runs
&` queue_time `& time on queue for one recipient
+&`*queue_time_exclusive `& exclude recieve time from QT times
&` queue_time_overall `& time on queue for whole message
&` pid `& Exim process id
&` pipelining `& PIPELINING use, on <= and => lines
@@ -38913,18 +38914,13 @@ Delivery "L" fields have an asterisk appended if used.
.cindex "log" "queue time"
&%queue_time%&: The amount of time the message has been in the queue on the
local host is logged as QT=<&'time'&> on delivery (&`=>`&) lines, for example,
-&`QT=3m45s`&. The clock starts when Exim starts to receive the message, so it
-includes reception time as well as the delivery time for the current address.
-This means that it may be longer than the difference between the arrival and
-delivery log line times, because the arrival log line is not written until the
-message has been successfully received.
+&`QT=3m45s`&.
If millisecond logging is enabled, short times will be shown with greater
precision, eg. &`QT=1.578s`&.
.next
&%queue_time_overall%&: The amount of time the message has been in the queue on
the local host is logged as QT=<&'time'&> on &"Completed"& lines, for
-example, &`QT=3m45s`&. The clock starts when Exim starts to receive the
-message, so it includes reception time as well as the total delivery time.
+example, &`QT=3m45s`&.
.next
.cindex "log" "receive duration"
&%receive_time%&: For each message, the amount of real time it has taken to
diff --git a/doc/doc-txt/ChangeLog b/doc/doc-txt/ChangeLog
index db4735f..916a4c4 100644
--- a/doc/doc-txt/ChangeLog
+++ b/doc/doc-txt/ChangeLog
@@ -236,6 +236,11 @@ JH/49 Bug 2710: when using SOCKS for additional messages after the first (a
transport executions. This also mean that the log lines for the
messages can show the proxy information.
+JH/50 Bug 2672: QT elements in log lines, unless disabled, now exclude the
+ receive time. With modern systems the difference is significant.
+ The historical behaviour can be restored by disabling (a new) log_selector
+ "queue_time_exclusive".
+
Exim version 4.94
diff --git a/doc/doc-txt/NewStuff b/doc/doc-txt/NewStuff
index 50f7b43..0ac271e 100644
--- a/doc/doc-txt/NewStuff
+++ b/doc/doc-txt/NewStuff
@@ -48,6 +48,9 @@ Version 4.95
13. Option "smtp_accept_msx_per_connection" is now expanded.
+14. Log selector "queue_size_exclusive", enabled by default, to exclude the
+ time taken for reception from QT log elements.
+
Version 4.94
------------
diff --git a/src/exim_monitor/em_globals.c b/src/exim_monitor/em_globals.c
index 30d22b5..88d5103 100644
--- a/src/exim_monitor/em_globals.c
+++ b/src/exim_monitor/em_globals.c
@@ -196,6 +196,7 @@ uschar *queue_name = US"";
int received_count = 0;
uschar *received_protocol = NULL;
struct timeval received_time = { 0, 0 };
+struct timeval received_time_complete = { 0, 0 };
int recipients_count = 0;
recipient_item *recipients_list = NULL;
int recipients_list_max = 0;
diff --git a/src/src/deliver.c b/src/src/deliver.c
index ef6eb22..0cddec7 100644
--- a/src/src/deliver.c
+++ b/src/src/deliver.c
@@ -1269,8 +1269,8 @@ if ( LOGGING(smtp_confirmation)
/* Time on queue and actual time taken to deliver */
if (LOGGING(queue_time))
- g = string_append(g, 2, US" QT=",
- string_timesince(&received_time));
+ g = string_append(g, 2, US" QT=", string_timesince(
+ LOGGING(queue_time_exclusive) ? &received_time_complete : &received_time));
if (LOGGING(deliver_time))
g = string_append(g, 2, US" DT=", string_timediff(&addr->delivery_time));
diff --git a/src/src/functions.h b/src/src/functions.h
index f1e5b46..0f962b3 100644
--- a/src/src/functions.h
+++ b/src/src/functions.h
@@ -1059,18 +1059,25 @@ subdir_str[1] = '\0';
/******************************************************************************/
/* Time calculations */
+/* Diff two times (later, earlier) returning diff in 1st arg */
static inline void
-timesince(struct timeval * diff, const struct timeval * then)
+timediff(struct timeval * later, const struct timeval * earlier)
{
-gettimeofday(diff, NULL);
-diff->tv_sec -= then->tv_sec;
-if ((diff->tv_usec -= then->tv_usec) < 0)
+later->tv_sec -= earlier->tv_sec;
+if ((later->tv_usec -= earlier->tv_usec) < 0)
{
- diff->tv_sec--;
- diff->tv_usec += 1000*1000;
+ later->tv_sec--;
+ later->tv_usec += 1000*1000;
}
}
+static inline void
+timesince(struct timeval * diff, const struct timeval * then)
+{
+gettimeofday(diff, NULL);
+timediff(diff, then);
+}
+
static inline uschar *
string_timediff(const struct timeval * diff)
{
diff --git a/src/src/globals.c b/src/src/globals.c
index 04e4705..7ee7c38 100644
--- a/src/src/globals.c
+++ b/src/src/globals.c
@@ -1034,6 +1034,7 @@ int log_default[] = { /* for initializing log_selector */
Li_outgoing_interface, /* see d_log_interface in deliver.c */
Li_msg_id,
Li_queue_run,
+ Li_queue_time_exclusive,
Li_rejected_header,
Li_retry_defer,
Li_sender_verify_fail,
@@ -1088,6 +1089,7 @@ bit_table log_options[] = { /* must be in alphabetical order,
#endif
BIT_TABLE(L, queue_run),
BIT_TABLE(L, queue_time),
+ BIT_TABLE(L, queue_time_exclusive),
BIT_TABLE(L, queue_time_overall),
BIT_TABLE(L, receive_time),
BIT_TABLE(L, received_recipients),
@@ -1274,7 +1276,7 @@ uschar *received_header_text = US
int received_headers_max = 30;
uschar *received_protocol = NULL;
struct timeval received_time = { 0, 0 };
-struct timeval received_time_taken = { 0, 0 };
+struct timeval received_time_complete = { 0, 0 };
uschar *recipient_data = NULL;
uschar *recipient_unqualified_hosts = NULL;
uschar *recipient_verify_failure = NULL;
diff --git a/src/src/globals.h b/src/src/globals.h
index 652518a..58bf3c4 100644
--- a/src/src/globals.h
+++ b/src/src/globals.h
@@ -841,8 +841,8 @@ extern int received_count; /* Count of Received: headers */
extern uschar *received_for; /* For "for" field */
extern uschar *received_header_text; /* Definition of Received: header */
extern int received_headers_max; /* Max count of Received: headers */
-extern struct timeval received_time; /* Time the message was received */
-extern struct timeval received_time_taken; /* Interval the message took to be received */
+extern struct timeval received_time; /* Time the message started to be received */
+extern struct timeval received_time_complete; /* Time the message completed reception */
extern uschar *recipient_data; /* lookup data for recipients */
extern uschar *recipient_unqualified_hosts; /* Permitted unqualified recipients */
extern uschar *recipient_verify_failure; /* What went wrong */
diff --git a/src/src/macros.h b/src/src/macros.h
index 0b64756..4321780 100644
--- a/src/src/macros.h
+++ b/src/src/macros.h
@@ -480,6 +480,7 @@ enum logbit {
Li_protocol_detail,
Li_proxy,
Li_queue_time,
+ Li_queue_time_exclusive,
Li_queue_time_overall,
Li_receive_time,
Li_received_sender,
diff --git a/src/src/receive.c b/src/src/receive.c
index 3e950ff..ce7da57 100644
--- a/src/src/receive.c
+++ b/src/src/receive.c
@@ -3272,7 +3272,7 @@ if (fflush(spool_data_file) == EOF || ferror(spool_data_file) ||
/* No I/O errors were encountered while writing the data file. */
DEBUG(D_receive) debug_printf("Data file written for message %s\n", message_id);
-if (LOGGING(receive_time)) timesince(&received_time_taken, &received_time);
+gettimeofday(&received_time_complete, NULL);
/* If there were any bad addresses extracted by -t, or there were no recipients
@@ -4050,7 +4050,11 @@ if (LOGGING(dkim) && arc_state && Ustrcmp(arc_state, "pass") == 0)
#endif
if (LOGGING(receive_time))
- g = string_append(g, 2, US" RT=", string_timediff(&received_time_taken));
+ {
+ struct timeval diff = received_time_complete;
+ timediff(&diff, &received_time);
+ g = string_append(g, 2, US" RT=", string_timediff(&diff));
+ }
if (*queue_name)
g = string_append(g, 2, US" Q=", queue_name);
diff --git a/src/src/spool_in.c b/src/src/spool_in.c
index 9794e93..f64c52c 100644
--- a/src/src/spool_in.c
+++ b/src/src/spool_in.c
@@ -422,6 +422,8 @@ if (Ufgets(big_buffer, big_buffer_size, fp) == NULL) goto SPOOL_READ_ERROR;
if (sscanf(CS big_buffer, TIME_T_FMT " %d", &received_time.tv_sec, &warning_count) != 2)
goto SPOOL_FORMAT_ERROR;
received_time.tv_usec = 0;
+received_time_complete = received_time;
+
message_age = time(NULL) - received_time.tv_sec;
#ifndef COMPILE_UTILITY
@@ -639,7 +641,19 @@ for (;;)
{
unsigned usec;
if (sscanf(CS var + 20, "%u", &usec) == 1)
+ {
received_time.tv_usec = usec;
+ if (!received_time_complete.tv_sec) received_time_complete.tv_usec = usec;
+ }
+ }
+ else if (Ustrncmp(p, "eceived_time_complete", 21) == 0)
+ {
+ unsigned sec, usec;
+ if (sscanf(CS var + 23, "%u.%u", &sec, &usec) == 2)
+ {
+ received_time_complete.tv_sec = sec;
+ received_time_complete.tv_usec = usec;
+ }
}
break;
diff --git a/src/src/spool_out.c b/src/src/spool_out.c
index 113765b..bbc798f 100644
--- a/src/src/spool_out.c
+++ b/src/src/spool_out.c
@@ -162,6 +162,8 @@ fprintf(fp, "<%s>\n", sender_address);
fprintf(fp, "%d %d\n", (int)received_time.tv_sec, warning_count);
fprintf(fp, "-received_time_usec .%06d\n", (int)received_time.tv_usec);
+fprintf(fp, "-received_time_complete %d.%06d\n",
+ (int)received_time_complete.tv_sec, (int)received_time_complete.tv_usec);
/* If there is information about a sending host, remember it. The HELO
data can be set for local SMTP as well as remote. */
diff --git a/test/runtest b/test/runtest
index 6050411..8ebba50 100755
--- a/test/runtest
+++ b/test/runtest
@@ -1007,7 +1007,8 @@ RESET_AFTER_EXTRA_LINE_READ:
s/conversion: german.xn--strae-oqa.de/conversion: german.straße.de/;
# subsecond timstamp info in reported header-files
- s/^(-received_time_usec \.)\d{6}$/$1uuuuuu/;
+ s/^-received_time_usec \.\K\d{6}$/uuuuuu/;
+ s/^-received_time_complete \K\d+\.\d{6}$/tttt.uuuuuu/;
# Postgres server takes varible time to shut down; lives in various places
s/^waiting for server to shut down\.+ done$/waiting for server to shut down.... done/;
diff --git a/test/stdout/0035 b/test/stdout/0035
index 09b5df4..94b08fc 100644
--- a/test/stdout/0035
+++ b/test/stdout/0035
@@ -145,6 +145,7 @@ EXIMUSER EXIM_UID EXIM_GID
<notsubmit@y>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
--helo_name rhu.barb
-host_address 127.0.0.1.9999
-interface_address 127.0.0.1.1225
@@ -166,6 +167,7 @@ EXIMUSER EXIM_UID EXIM_GID
<a@y>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
--helo_name rhu.barb
-host_address 127.0.0.1.9999
-interface_address 127.0.0.1.1225
@@ -190,6 +192,7 @@ EXIMUSER EXIM_UID EXIM_GID
<>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
--helo_name rhu.barb
-host_address 127.0.0.1.9999
-interface_address 127.0.0.1.1225
@@ -212,6 +215,7 @@ EXIMUSER EXIM_UID EXIM_GID
<notsubmit@y>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
--helo_name rhu.barb
-host_address 127.0.0.1.9999
-interface_address 127.0.0.1.1225
@@ -234,6 +238,7 @@ EXIMUSER EXIM_UID EXIM_GID
<a@y>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
--helo_name rhu.barb
-host_address 127.0.0.1.9999
-interface_address 127.0.0.1.1225
@@ -259,6 +264,7 @@ EXIMUSER EXIM_UID EXIM_GID
<a@y>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
--helo_name rhu.barb
-host_address 127.0.0.1.9999
-interface_address 127.0.0.1.1225
@@ -284,6 +290,7 @@ EXIMUSER EXIM_UID EXIM_GID
<a@y>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
--helo_name rhu.barb
-host_address 127.0.0.1.9999
-interface_address 127.0.0.1.1225
diff --git a/test/stdout/0245 b/test/stdout/0245
index 5d0f2df..da28e7e 100644
--- a/test/stdout/0245
+++ b/test/stdout/0245
@@ -8,6 +8,7 @@ CALLER UID GID
<CALLER@???>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 1
diff --git a/test/stdout/0250 b/test/stdout/0250
index c19185e..d4d7237 100644
--- a/test/stdout/0250
+++ b/test/stdout/0250
@@ -3,6 +3,7 @@ CALLER UID GID
<CALLER-rewritten@???>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
@@ -34,6 +35,7 @@ CALLER UID GID
<CALLER-rewritten@???>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
@@ -65,6 +67,7 @@ CALLER UID GID
<CALLER-rewritten@???>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
diff --git a/test/stdout/0254 b/test/stdout/0254
index 69b80a1..1fcd3fd 100644
--- a/test/stdout/0254
+++ b/test/stdout/0254
@@ -3,6 +3,7 @@ CALLER UID GID
<CALLER@???>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
@@ -40,6 +41,7 @@ CALLER UID GID
<CALLER@???>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
@@ -70,6 +72,7 @@ CALLER UID GID
<CALLER@???>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
diff --git a/test/stdout/0311 b/test/stdout/0311
index 960e8e0..a26b24c 100644
--- a/test/stdout/0311
+++ b/test/stdout/0311
@@ -3,6 +3,7 @@ CALLER UID GID
<CALLER@???>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
@@ -32,6 +33,7 @@ CALLER UID GID
<CALLER@???>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
diff --git a/test/stdout/0338 b/test/stdout/0338
index fbbbc69..06aab63 100644
--- a/test/stdout/0338
+++ b/test/stdout/0338
@@ -7,6 +7,7 @@ CALLER UID GID
<CALLER@???>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
diff --git a/test/stdout/0377 b/test/stdout/0377
index de1e5e3..f6d8fc6 100644
--- a/test/stdout/0377
+++ b/test/stdout/0377
@@ -3,6 +3,7 @@ CALLER UID GID
<CALLER@???>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
diff --git a/test/stdout/0378 b/test/stdout/0378
index c60701c..e163ed1 100644
--- a/test/stdout/0378
+++ b/test/stdout/0378
@@ -3,6 +3,7 @@ CALLER UID GID
<CALLER@???>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
diff --git a/test/stdout/0379 b/test/stdout/0379
index d26d235..d3bd25e 100644
--- a/test/stdout/0379
+++ b/test/stdout/0379
@@ -3,6 +3,7 @@ CALLER UID GID
<CALLER@???>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
-ident CALLER
-received_protocol local
-body_linecount 0
diff --git a/test/stdout/0389 b/test/stdout/0389
index bb5977a..758f261 100644
--- a/test/stdout/0389
+++ b/test/stdout/0389
@@ -9,6 +9,7 @@ CALLER UID GID
<CALLER@???>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
-ident CALLER
-received_protocol local-smtp
-aclm 0 22
diff --git a/test/stdout/0488 b/test/stdout/0488
index d6d3b4b..680def4 100644
--- a/test/stdout/0488
+++ b/test/stdout/0488
@@ -9,6 +9,7 @@ CALLER UID GID
<CALLER@???>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
-ident CALLER
-received_protocol local-smtp
-body_linecount 0
diff --git a/test/stdout/0490 b/test/stdout/0490
index ee77a71..cc71d26 100644
--- a/test/stdout/0490
+++ b/test/stdout/0490
@@ -13,6 +13,7 @@ CALLER UID GID
<CALLER@???>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
-ident CALLER
-received_protocol local-smtp
-body_linecount 2
diff --git a/test/stdout/0514 b/test/stdout/0514
index 5b8677c..913378a 100644
--- a/test/stdout/0514
+++ b/test/stdout/0514
@@ -6,6 +6,7 @@ CALLER UID GID
<"spaced user"@???>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
-ident spaced user
-received_protocol local
-body_linecount 1
diff --git a/test/stdout/3415 b/test/stdout/3415
index d806fa6..7c6e90b 100644
--- a/test/stdout/3415
+++ b/test/stdout/3415
@@ -156,6 +156,7 @@ EXIMUSER EXIM_UID EXIM_GID
<username@???>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
--helo_name rhu.barb
-host_address 127.0.0.1.9999
-host_auth au1
@@ -184,6 +185,7 @@ EXIMUSER EXIM_UID EXIM_GID
<>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
--helo_name rhu.barb
-host_address 127.0.0.1.9999
-host_auth au1
@@ -210,6 +212,7 @@ EXIMUSER EXIM_UID EXIM_GID
<>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
--helo_name rhu.barb
-host_address 127.0.0.1.9999
-host_auth au1
@@ -236,6 +239,7 @@ EXIMUSER EXIM_UID EXIM_GID
<>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
--helo_name rhu.barb
-host_address 127.0.0.1.9999
-host_auth au1
@@ -262,6 +266,7 @@ EXIMUSER EXIM_UID EXIM_GID
<>
ddddddddd 0
-received_time_usec .uuuuuu
+-received_time_complete tttt.uuuuuu
--helo_name rhu.barb
-host_address 127.0.0.1.9999
-host_auth au1
