Log queue_time and queue_time_overall exclusive of receive time. Bug 2672

27 files changed, 86 insertions, 21 deletions

diff --git a/doc/doc-docbook/spec.xfpt b/doc/doc-docbook/spec.xfpt
index 437b13df0..36be62f7a 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 db4735f8f..916a4c470 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 50f7b4357..0ac271eaf 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 30d22b5eb..88d5103fc 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 ef6eb22e2..0cddec758 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 f1e5b466e..0f962b313 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 04e47050e..7ee7c38b5 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 652518ade..58bf3c428 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 0b647569b..43217807f 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 3e950ffc6..ce7da5719 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 9794e93d1..f64c52c5a 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 113765bab..bbc798fb4 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 6050411ed..8ebba5023 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 09b5df4e9..94b08fcd6 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 5d0f2df34..da28e7e94 100644
--- a/test/stdout/0245
+++ b/test/stdout/0245
@@ -8,6 +8,7 @@ CALLER UID GID
 <CALLER@myhost.test.ex>
 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 c19185e84..d4d723725 100644
--- a/test/stdout/0250
+++ b/test/stdout/0250
@@ -3,6 +3,7 @@ CALLER UID GID
 <CALLER-rewritten@test.ex>
 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@test.ex>
 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@test.ex>
 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 69b80a192..1fcd3fd45 100644
--- a/test/stdout/0254
+++ b/test/stdout/0254
@@ -3,6 +3,7 @@ CALLER UID GID
 <CALLER@myhost.test.ex>
 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@myhost.test.ex>
 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@myhost.test.ex>
 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 960e8e0b7..a26b24c55 100644
--- a/test/stdout/0311
+++ b/test/stdout/0311
@@ -3,6 +3,7 @@ CALLER UID GID
 <CALLER@myhost.test.ex>
 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@myhost.test.ex>
 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 fbbbc69c5..06aab63cf 100644
--- a/test/stdout/0338
+++ b/test/stdout/0338
@@ -7,6 +7,7 @@ CALLER UID GID
 <CALLER@test.ex>
 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 de1e5e305..f6d8fc6f6 100644
--- a/test/stdout/0377
+++ b/test/stdout/0377
@@ -3,6 +3,7 @@ CALLER UID GID
 <CALLER@myhost.test.ex>
 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 c60701cbc..e163ed170 100644
--- a/test/stdout/0378
+++ b/test/stdout/0378
@@ -3,6 +3,7 @@ CALLER UID GID
 <CALLER@myhost.test.ex>
 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 d26d23523..d3bd25e7b 100644
--- a/test/stdout/0379
+++ b/test/stdout/0379
@@ -3,6 +3,7 @@ CALLER UID GID
 <CALLER@myhost.test.ex>
 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 bb5977af7..758f2614d 100644
--- a/test/stdout/0389
+++ b/test/stdout/0389
@@ -9,6 +9,7 @@ CALLER UID GID
 <CALLER@myhost.test.ex>
 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 d6d3b4b18..680def49c 100644
--- a/test/stdout/0488
+++ b/test/stdout/0488
@@ -9,6 +9,7 @@ CALLER UID GID
 <CALLER@myhost.test.ex>
 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 ee77a71e6..cc71d26e1 100644
--- a/test/stdout/0490
+++ b/test/stdout/0490
@@ -13,6 +13,7 @@ CALLER UID GID
 <CALLER@myhost.test.ex>
 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 5b8677c65..913378aef 100644
--- a/test/stdout/0514
+++ b/test/stdout/0514
@@ -6,6 +6,7 @@ CALLER UID GID
 <"spaced user"@myhost.test.ex>
 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 d806fa66c..7c6e90bdb 100644
--- a/test/stdout/3415
+++ b/test/stdout/3415
@@ -156,6 +156,7 @@ EXIMUSER EXIM_UID EXIM_GID
 <username@myhost.test.ex>
 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