Log queue_time and queue_time_overall exclusive of receive time. Bug 2672

diff --git a/doc/doc-docbook/spec.xfpt b/doc/doc-docbook/spec.xfpt
index 437b13df0410c4e0c62abeb2b508876f834657f2..36be62f7a1ed408be112819b4a03b8d7f4ba475c 100644 (file)
--- 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 db4735f8fa3c33d4d5d82494bff1053973c1961a..916a4c47070706b9e516c65fdeec5b57e4ed5db9 100644 (file)
--- 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 50f7b435777e1f0c0d01df8fe4188eecb336a09f..0ac271eaf07aad626cd1ab88e4b1e4a674efa286 100644 (file)
--- 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 30d22b5ebca2bb34b7483dbb640ec2e660a69fd0..88d5103fc9cd8839651e3353edada3d41982a880 100644 (file)
--- 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 ef6eb22e2037cd19a8510ece30c6206d83d84e98..0cddec7584a38cf6c635d0fa23b87ed06f9c5bc5 100644 (file)
--- 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 f1e5b466e0f8dcae5a7db7d72f8d0da217fd171a..0f962b313d7ab9eb90fb888384748f4e16d961d4 100644 (file)
--- 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 04e47050ec190b556490fb287cd1c335f9b94af7..7ee7c38b5833e928398f5e1dd24a8967c58edf08 100644 (file)
--- 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 652518ade62252292298d808fbcf4eb4eaddcb1e..58bf3c42872b2ac448e41cd8d416ca66411a72af 100644 (file)
--- 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 0b647569b1148a3d7470e82790c8974fe804fe0a..43217807f27e8c2da9c830648c60199882e3d404 100644 (file)
--- 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 3e950ffc6e86280a8487848a18a4cd4eb939b0cb..ce7da57192afa77b5afff9b9d6a760e5d70061ec 100644 (file)
--- 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 9794e93d1309d8ecd940fb6a6d15a1c070c6c453..f64c52c5a57ad411b2fed5cff1771a3ad8081ba3 100644 (file)
--- 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 113765babb90dbaedaf23d64e7e2edac78b43b05..bbc798fb46577074d911cc924cc3c36eb8589f65 100644 (file)
--- 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 6050411ed7eca99756e5dfa8a3b53f1dd4436b95..8ebba5023efcaf65f99861313d7a53f09514e676 100755 (executable)
--- 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 09b5df4e90ab91394bd7dac0b155546e0154007d..94b08fcd6156617f0b57f81ee9464c8561de4ad5 100644 (file)
--- 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 5d0f2df346be976354118fed6e501617eb02e497..da28e7e942c0707fbaf7ea7d88aa70ff9bef972e 100644 (file)
--- 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 c19185e84b59cb551e25de42e0c926ed6f8cac58..d4d723725a64ed3ffeb36c04c89795a3823a3017 100644 (file)
--- 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 69b80a19283f23d4c6221266f89a621218e5ac0e..1fcd3fd45b4e45d43fbac62f862ba0f288f98e4d 100644 (file)
--- 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 960e8e0b7183ee6ce2c9f53e5546f6272d799ee8..a26b24c555c7065aa9a09b5b8f71df5e643c2cb5 100644 (file)
--- 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 fbbbc69c516bca0ee21ded96aee4850984d77966..06aab63cf316c156e7269c7b44268589f0b3a425 100644 (file)
--- 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 de1e5e3056b531a65d5c30a77211bebabc739167..f6d8fc6f63dcfa26e381773129b3a6aece444474 100644 (file)
--- 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 c60701cbc62d78c0d7b2449b2376c1bc9ed89f0c..e163ed1701bf52b12d28ef5c86284ee0eb35e58e 100644 (file)
--- 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 d26d23523fc103fe344b201b83aec30c6e868804..d3bd25e7b50b37e472442d667fd66ae0f72c0e39 100644 (file)
--- 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 bb5977af7ddc7473aa1231f7ec2515971be64593..758f2614d5161b806a2e215c71f157d8e91fa0bc 100644 (file)
--- 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 d6d3b4b188ed8422b46d4d4263e4f3a4ed746c9a..680def49c6bda89d1da82aa68366c0026692fd0a 100644 (file)
--- 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 ee77a71e68d738e4062755d6e969c608086eedec..cc71d26e10cf4b8e0e9136f7cbb32ecb09b56b80 100644 (file)
--- 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 5b8677c653cc928e3e6eb0fe2f8e56a39982569e..913378aefe726f4fb5968ffa28acd9a96acd49ad 100644 (file)
--- 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 d806fa66cf5dbac41aa6d6a5cb33134180082b28..7c6e90bdbcba19d4cf9be6200315c78af40c3800 100644 (file)
--- 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