Log queue_time and queue_time_overall exclusive of receive time. Bug 2672

9 files changed, 44 insertions, 13 deletions

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. */