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
 &` 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
 &` 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,
 .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
 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
 .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.
 
       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
 
 
 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.
 
 
 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
 ------------
 
 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 };
 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;
 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))
 /* 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));
 
 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 */
 
 /******************************************************************************/
 /* Time calculations */
 

+/* Diff two times (later, earlier) returning diff in 1st arg */

 static inline void
 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)
 {
 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_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,
   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),
 #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),
   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 };
 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;
 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 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 */
 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_protocol_detail,
   Li_proxy,
   Li_queue_time,

+  Li_queue_time_exclusive,

   Li_queue_time_overall,
   Li_receive_time,
   Li_received_sender,
   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);
 /* 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
 
 
 /* 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))
 #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);
 
 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;
 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
 
 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)
       {
       unsigned usec;
       if (sscanf(CS var + 20, "%u", &usec) == 1)

+       {

        received_time.tv_usec = usec;
        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;
 
       }
     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, "%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. */
 
 /* 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/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/;
 
     # 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
 <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
 --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
 <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
 --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
 <>
 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
 --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
 <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
 --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
 <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
 --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
 <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
 --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
 <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
 --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
 <CALLER@myhost.test.ex>
 ddddddddd 0
 -received_time_usec .uuuuuu

+-received_time_complete tttt.uuuuuu

 -ident CALLER
 -received_protocol local
 -body_linecount 1
 -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
 <CALLER-rewritten@test.ex>
 ddddddddd 0
 -received_time_usec .uuuuuu

+-received_time_complete tttt.uuuuuu

 -ident CALLER
 -received_protocol local
 -body_linecount 0
 -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
 <CALLER-rewritten@test.ex>
 ddddddddd 0
 -received_time_usec .uuuuuu

+-received_time_complete tttt.uuuuuu

 -ident CALLER
 -received_protocol local
 -body_linecount 0
 -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
 <CALLER-rewritten@test.ex>
 ddddddddd 0
 -received_time_usec .uuuuuu

+-received_time_complete tttt.uuuuuu

 -ident CALLER
 -received_protocol local
 -body_linecount 0
 -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
 <CALLER@myhost.test.ex>
 ddddddddd 0
 -received_time_usec .uuuuuu

+-received_time_complete tttt.uuuuuu

 -ident CALLER
 -received_protocol local
 -body_linecount 0
 -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
 <CALLER@myhost.test.ex>
 ddddddddd 0
 -received_time_usec .uuuuuu

+-received_time_complete tttt.uuuuuu

 -ident CALLER
 -received_protocol local
 -body_linecount 0
 -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
 <CALLER@myhost.test.ex>
 ddddddddd 0
 -received_time_usec .uuuuuu

+-received_time_complete tttt.uuuuuu

 -ident CALLER
 -received_protocol local
 -body_linecount 0
 -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
 <CALLER@myhost.test.ex>
 ddddddddd 0
 -received_time_usec .uuuuuu

+-received_time_complete tttt.uuuuuu

 -ident CALLER
 -received_protocol local
 -body_linecount 0
 -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
 <CALLER@myhost.test.ex>
 ddddddddd 0
 -received_time_usec .uuuuuu

+-received_time_complete tttt.uuuuuu

 -ident CALLER
 -received_protocol local
 -body_linecount 0
 -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
 <CALLER@test.ex>
 ddddddddd 0
 -received_time_usec .uuuuuu

+-received_time_complete tttt.uuuuuu

 -ident CALLER
 -received_protocol local
 -body_linecount 0
 -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
 <CALLER@myhost.test.ex>
 ddddddddd 0
 -received_time_usec .uuuuuu

+-received_time_complete tttt.uuuuuu

 -ident CALLER
 -received_protocol local
 -body_linecount 0
 -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
 <CALLER@myhost.test.ex>
 ddddddddd 0
 -received_time_usec .uuuuuu

+-received_time_complete tttt.uuuuuu

 -ident CALLER
 -received_protocol local
 -body_linecount 0
 -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
 <CALLER@myhost.test.ex>
 ddddddddd 0
 -received_time_usec .uuuuuu

+-received_time_complete tttt.uuuuuu

 -ident CALLER
 -received_protocol local
 -body_linecount 0
 -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
 <CALLER@myhost.test.ex>
 ddddddddd 0
 -received_time_usec .uuuuuu

+-received_time_complete tttt.uuuuuu

 -ident CALLER
 -received_protocol local-smtp
 -aclm 0 22
 -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
 <CALLER@myhost.test.ex>
 ddddddddd 0
 -received_time_usec .uuuuuu

+-received_time_complete tttt.uuuuuu

 -ident CALLER
 -received_protocol local-smtp
 -body_linecount 0
 -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
 <CALLER@myhost.test.ex>
 ddddddddd 0
 -received_time_usec .uuuuuu

+-received_time_complete tttt.uuuuuu

 -ident CALLER
 -received_protocol local-smtp
 -body_linecount 2
 -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
 <"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
 -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
 <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
 --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
 <>
 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
 --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
 <>
 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
 --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
 <>
 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
 --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
 <>
 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
 --helo_name rhu.barb
 -host_address 127.0.0.1.9999
 -host_auth au1