Logging: millisecond QT and DT. Bug 2102

37 files changed, 191 insertions, 86 deletions

diff --git a/doc/doc-docbook/spec.xfpt b/doc/doc-docbook/spec.xfpt
index a4b1926ec..0d03c2f9c 100644
--- a/doc/doc-docbook/spec.xfpt
+++ b/doc/doc-docbook/spec.xfpt
@@ -36118,7 +36118,7 @@ selection marked by asterisks:
 &` incoming_interface         `&  local interface on <= and => lines
 &` incoming_port              `&  remote port on <= lines
 &`*lost_incoming_connection   `&  as it says (includes timeouts)
-&` millisec                   `&  millisecond timestamps
+&` millisec                   `&  millisecond timestamps and QT/DT times
 &` outgoing_interface         `&  local interface on => lines
 &` outgoing_port              `&  add remote port to => lines
 &`*queue_run                  `&  start and end queue runs
@@ -36208,6 +36208,8 @@ process is started because &%queue_only%& is set or &%-odq%& was used.
 .cindex "log" "delivery duration"
 &%deliver_time%&: For each delivery, the amount of real time it has taken to
 perform the actual delivery is logged as DT=<&'time'&>, for example, &`DT=1s`&.
+If millisecond logging is enabled, short times will be shown with greater
+precision, eg. &`DT=0.304`&.
 .next
 .cindex "log" "message size on delivery"
 .cindex "size" "of message"
@@ -36329,6 +36331,8 @@ 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.
+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
diff --git a/src/exim_monitor/em_globals.c b/src/exim_monitor/em_globals.c
index 54032362c..46ad834da 100644
--- a/src/exim_monitor/em_globals.c
+++ b/src/exim_monitor/em_globals.c
@@ -191,7 +191,7 @@ uschar *queue_name             = US"";
 
 int     received_count         = 0;
 uschar *received_protocol      = NULL;
-int     received_time          = 0;
+struct timeval received_time   = { 0, 0 };
 int     recipients_count       = 0;
 recipient_item *recipients_list = NULL;
 int     recipients_list_max    = 0;
diff --git a/src/exim_monitor/em_queue.c b/src/exim_monitor/em_queue.c
index cb284eb48..e6b1e91d9 100644
--- a/src/exim_monitor/em_queue.c
+++ b/src/exim_monitor/em_queue.c
@@ -204,7 +204,7 @@ if it's there. */
 
 else
   {
-  q->update_time = q->input_time = received_time;
+  q->update_time = q->input_time = received_time.tv_sec;
   if ((p = strstric(sender_address+1, qualify_domain, FALSE)) != NULL &&
     *(--p) == '@') *p = 0;
   }
diff --git a/src/src/deliver.c b/src/src/deliver.c
index 49281f93d..2713cc56f 100644
--- a/src/src/deliver.c
+++ b/src/src/deliver.c
@@ -382,6 +382,7 @@ for (addr2 = addr->next; addr2; addr2 = addr2->next)
   addr2->transport_return = addr->transport_return;
   addr2->basic_errno =	    addr->basic_errno;
   addr2->more_errno =	    addr->more_errno;
+  addr2->delivery_usec =    addr->delivery_usec;
   addr2->special_action =   addr->special_action;
   addr2->message =	    addr->message;
   addr2->user_message =	    addr->user_message;
@@ -1029,6 +1030,43 @@ return str;
 }
 
 
+
+void
+timesince(struct timeval * diff, struct timeval * then)
+{
+gettimeofday(diff, NULL);
+diff->tv_sec -= then->tv_sec;
+if ((diff->tv_usec -= then->tv_usec) < 0)
+  {
+  diff->tv_sec--;
+  diff->tv_usec += 1000*1000;
+  }
+}
+
+
+
+static uschar *
+string_timediff(struct timeval * diff)
+{
+static uschar buf[sizeof("0.000s")];
+
+if (diff->tv_sec >= 5 || !LOGGING(millisec))
+  return readconf_printtime((int)diff->tv_sec);
+
+sprintf(CS buf, "%d.%03ds", (int)diff->tv_sec, (int)diff->tv_usec/1000);
+return buf;
+}
+
+
+static uschar *
+string_timesince(struct timeval * then)
+{
+struct timeval diff;
+
+timesince(&diff, then);
+return string_timediff(&diff);
+}
+
 /******************************************************************************/
 
 
@@ -1191,11 +1229,13 @@ if (  LOGGING(smtp_confirmation)
 
 if (LOGGING(queue_time))
   s = string_append(s, &size, &ptr, 2, US" QT=",
-    readconf_printtime( (int) ((long)time(NULL) - (long)received_time)) );
+    string_timesince(&received_time));
 
 if (LOGGING(deliver_time))
-  s = string_append(s, &size, &ptr, 2, US" DT=",
-    readconf_printtime(addr->more_errno));
+  {
+  struct timeval diff = {addr->more_errno, addr->delivery_usec};
+  s = string_append(s, &size, &ptr, 2, US" DT=", string_timediff(&diff));
+  }
 
 /* string_cat() always leaves room for the terminator. Release the
 store we used to build the line after writing it. */
@@ -2347,6 +2387,7 @@ if ((pid = fork()) == 0)
       || (ret = write(pfd[pipe_write], &addr2->flags, sizeof(addr2->flags))) != sizeof(addr2->flags)
       || (ret = write(pfd[pipe_write], &addr2->basic_errno,    sizeof(int))) != sizeof(int)
       || (ret = write(pfd[pipe_write], &addr2->more_errno,     sizeof(int))) != sizeof(int)
+      || (ret = write(pfd[pipe_write], &addr2->delivery_usec,  sizeof(int))) != sizeof(int)
       || (ret = write(pfd[pipe_write], &addr2->special_action, sizeof(int))) != sizeof(int)
       || (ret = write(pfd[pipe_write], &addr2->transport,
         sizeof(transport_instance *))) != sizeof(transport_instance *)
@@ -2414,6 +2455,7 @@ for (addr2 = addr; addr2; addr2 = addr2->next)
     len = read(pfd[pipe_read], &addr2->flags, sizeof(addr2->flags));
     len = read(pfd[pipe_read], &addr2->basic_errno,    sizeof(int));
     len = read(pfd[pipe_read], &addr2->more_errno,     sizeof(int));
+    len = read(pfd[pipe_read], &addr2->delivery_usec,  sizeof(int));
     len = read(pfd[pipe_read], &addr2->special_action, sizeof(int));
     len = read(pfd[pipe_read], &addr2->transport,
       sizeof(transport_instance *));
@@ -2639,8 +2681,8 @@ time_t now = time(NULL);
 
 while (addr_local)
   {
-  time_t delivery_start;
-  int deliver_time;
+  struct timeval delivery_start;
+  struct timeval deliver_time;
   address_item *addr2, *addr3, *nextaddr;
   int logflags = LOG_MAIN;
   int logchar = dont_deliver? '*' : '=';
@@ -2936,9 +2978,10 @@ while (addr_local)
   single delivery. */
 
   deliver_set_expansions(addr);
-  delivery_start = time(NULL);
+
+  gettimeofday(&delivery_start, NULL);
   deliver_local(addr, FALSE);
-  deliver_time = (int)(time(NULL) - delivery_start);
+  timesince(&deliver_time, &delivery_start);
 
   /* If a shadow transport (which must perforce be another local transport), is
   defined, and its condition is met, we must pass the message to the shadow
@@ -3075,7 +3118,11 @@ while (addr_local)
 
     /* Done with this address */
 
-    if (result == OK) addr2->more_errno = deliver_time;
+    if (result == OK)
+      {
+      addr2->more_errno = deliver_time.tv_sec;
+      addr2->delivery_usec = deliver_time.tv_usec;
+      }
     post_process_one(addr2, result, logflags, DTYPE_TRANSPORT, logchar);
 
     /* If a pipe delivery generated text to be sent back, the result may be
@@ -3417,9 +3464,9 @@ while (!done)
 	r->flags = *ptr++;
 	r->key = string_copy(ptr);
 	while (*ptr++);
-	memcpy(&(r->basic_errno), ptr, sizeof(r->basic_errno));
+	memcpy(&r->basic_errno, ptr, sizeof(r->basic_errno));
 	ptr += sizeof(r->basic_errno);
-	memcpy(&(r->more_errno), ptr, sizeof(r->more_errno));
+	memcpy(&r->more_errno, ptr, sizeof(r->more_errno));
 	ptr += sizeof(r->more_errno);
 	r->message = *ptr ? string_copy(ptr) : NULL;
 	DEBUG(D_deliver|D_retry) debug_printf("  added %s item\n",
@@ -3561,11 +3608,13 @@ while (!done)
 	  DEBUG(D_deliver) debug_printf("A0 %s tret %d\n", addr->address, *ptr);
 	  addr->transport_return = *ptr++;
 	  addr->special_action = *ptr++;
-	  memcpy(&(addr->basic_errno), ptr, sizeof(addr->basic_errno));
+	  memcpy(&addr->basic_errno, ptr, sizeof(addr->basic_errno));
 	  ptr += sizeof(addr->basic_errno);
-	  memcpy(&(addr->more_errno), ptr, sizeof(addr->more_errno));
+	  memcpy(&addr->more_errno, ptr, sizeof(addr->more_errno));
 	  ptr += sizeof(addr->more_errno);
-	  memcpy(&(addr->flags), ptr, sizeof(addr->flags));
+	  memcpy(&addr->delivery_usec, ptr, sizeof(addr->delivery_usec));
+	  ptr += sizeof(addr->delivery_usec);
+	  memcpy(&addr->flags, ptr, sizeof(addr->flags));
 	  ptr += sizeof(addr->flags);
 	  addr->message = *ptr ? string_copy(ptr) : NULL;
 	  while(*ptr++);
@@ -4815,9 +4864,9 @@ for (delivery_count = 0; addr_remote; delivery_count++)
         {
         sprintf(CS big_buffer, "%c%.500s", r->flags, r->key);
         ptr = big_buffer + Ustrlen(big_buffer+2) + 3;
-        memcpy(ptr, &(r->basic_errno), sizeof(r->basic_errno));
+        memcpy(ptr, &r->basic_errno, sizeof(r->basic_errno));
         ptr += sizeof(r->basic_errno);
-        memcpy(ptr, &(r->more_errno), sizeof(r->more_errno));
+        memcpy(ptr, &r->more_errno, sizeof(r->more_errno));
         ptr += sizeof(r->more_errno);
         if (!r->message) *ptr++ = 0; else
           {
@@ -4866,11 +4915,13 @@ for (delivery_count = 0; addr_remote; delivery_count++)
 
       sprintf(CS big_buffer, "%c%c", addr->transport_return, addr->special_action);
       ptr = big_buffer + 2;
-      memcpy(ptr, &(addr->basic_errno), sizeof(addr->basic_errno));
+      memcpy(ptr, &addr->basic_errno, sizeof(addr->basic_errno));
       ptr += sizeof(addr->basic_errno);
-      memcpy(ptr, &(addr->more_errno), sizeof(addr->more_errno));
+      memcpy(ptr, &addr->more_errno, sizeof(addr->more_errno));
       ptr += sizeof(addr->more_errno);
-      memcpy(ptr, &(addr->flags), sizeof(addr->flags));
+      memcpy(ptr, &addr->delivery_usec, sizeof(addr->delivery_usec));
+      ptr += sizeof(addr->delivery_usec);
+      memcpy(ptr, &addr->flags, sizeof(addr->flags));
       ptr += sizeof(addr->flags);
 
       if (!addr->message) *ptr++ = 0; else
@@ -4883,7 +4934,7 @@ for (delivery_count = 0; addr_remote; delivery_count++)
         {
         ptr += sprintf(CS ptr, "%.256s", addr->host_used->name) + 1;
         ptr += sprintf(CS ptr, "%.64s", addr->host_used->address) + 1;
-        memcpy(ptr, &(addr->host_used->port), sizeof(addr->host_used->port));
+        memcpy(ptr, &addr->host_used->port, sizeof(addr->host_used->port));
         ptr += sizeof(addr->host_used->port);
 
         /* DNS lookup status */
@@ -5559,14 +5610,15 @@ give up; if the message has been around for sufficiently long, remove it. */
 
     if (rc != spool_read_hdrerror)
       {
-      received_time = 0;
+      received_time.tv_sec = received_time.tv_usec = 0;
+      /*XXX subsec precision?*/
       for (i = 0; i < 6; i++)
-	received_time = received_time * BASE_62 + tab62[id[i] - '0'];
+	received_time.tv_sec = received_time.tv_sec * BASE_62 + tab62[id[i] - '0'];
       }
 
     /* If we've had this malformed message too long, sling it. */
 
-    if (now - received_time > keep_malformed)
+    if (now - received_time.tv_sec > keep_malformed)
       {
       Uunlink(spool_fname(US"msglog", message_subdir, id, US""));
       Uunlink(spool_fname(US"input", message_subdir, id, US"-D"));
@@ -7792,7 +7844,7 @@ wording. */
       if (rc != 0)
         {
         uschar *s = US"";
-        if (now - received_time < retry_maximum_timeout && !addr_defer)
+        if (now - received_time.tv_sec < retry_maximum_timeout && !addr_defer)
           {
           addr_defer = (address_item *)(+1);
           deliver_freeze = TRUE;
@@ -7878,7 +7930,7 @@ if (!addr_defer)
 
   if (LOGGING(queue_time_overall))
     log_write(0, LOG_MAIN, "Completed QT=%s",
-      readconf_printtime( (int) ((long)time(NULL) - (long)received_time)) );
+      string_timesince(&received_time));
   else
     log_write(0, LOG_MAIN, "Completed");
 
@@ -8016,7 +8068,7 @@ else if (addr_defer != (address_item *)(+1))
     {
     int count;
     int show_time;
-    int queue_time = time(NULL) - received_time;
+    int queue_time = time(NULL) - received_time.tv_sec;
 
     /* When running in the test harness, there's an option that allows us to
     fudge this time so as to get repeatability of the tests. Take the first
diff --git a/src/src/exim.c b/src/src/exim.c
index 581b16190..c990bc08c 100644
--- a/src/src/exim.c
+++ b/src/src/exim.c
@@ -345,7 +345,7 @@ Arguments:
 Returns:      -1, 0, or +1
 */
 
-int
+static int
 exim_tvcmp(struct timeval *t1, struct timeval *t2)
 {
 if (t1->tv_sec > t2->tv_sec) return +1;
@@ -4537,8 +4537,9 @@ if (test_retry_arg >= 0)
       }
     }
 
-  yield = retry_find_config(s1, s2, basic_errno, more_errno);
-  if (yield == NULL) printf("No retry information found\n"); else
+  if (!(yield = retry_find_config(s1, s2, basic_errno, more_errno)))
+    printf("No retry information found\n");
+  else
     {
     retry_rule *r;
     more_errno = yield->more_errno;
@@ -4570,7 +4571,7 @@ if (test_retry_arg >= 0)
       printf("auth_failed  ");
     else printf("*  ");
 
-    for (r = yield->rules; r != NULL; r = r->next)
+    for (r = yield->rules; r; r = r->next)
       {
       printf("%c,%s", r->rule, readconf_printtime(r->timeout)); /* Do not */
       printf(",%s", readconf_printtime(r->p1));                 /* amalgamate */
diff --git a/src/src/expand.c b/src/src/expand.c
index 4eb1818f1..d8d36a3b5 100644
--- a/src/src/expand.c
+++ b/src/src/expand.c
@@ -642,7 +642,7 @@ static var_entry var_table[] = {
   { "received_ip_address", vtype_stringptr,   &interface_address },
   { "received_port",       vtype_int,         &interface_port },
   { "received_protocol",   vtype_stringptr,   &received_protocol },
-  { "received_time",       vtype_int,         &received_time },
+  { "received_time",       vtype_int,         &received_time.tv_sec },
   { "recipient_data",      vtype_stringptr,   &recipient_data },
   { "recipient_verify_failure",vtype_stringptr,&recipient_verify_failure },
   { "recipients",          vtype_string_func, &fn_recipients },
@@ -1484,9 +1484,7 @@ while (*s != 0)
 /* If value2 is unset, just compute one number */
 
 if (value2 < 0)
-  {
   s = string_sprintf("%d", total % value1);
-  }
 
 /* Otherwise do a div/mod hash */
 
diff --git a/src/src/functions.h b/src/src/functions.h
index 9c9caaf97..5b2a683b8 100644
--- a/src/src/functions.h
+++ b/src/src/functions.h
@@ -184,7 +184,6 @@ extern const uschar * exim_errstr(int);
 extern void    exim_exit(int);
 extern void    exim_nullstd(void);
 extern void    exim_setugid(uid_t, gid_t, BOOL, uschar *);
-extern int     exim_tvcmp(struct timeval *, struct timeval *);
 extern void    exim_wait_tick(struct timeval *, int);
 extern int     exp_bool(address_item *addr,
   uschar *mtype, uschar *mname, unsigned dgb_opt, uschar *oname, BOOL bvalue,
@@ -474,9 +473,10 @@ extern int     strcmpic(const uschar *, const uschar *);
 extern int     strncmpic(const uschar *, const uschar *, int);
 extern uschar *strstric(uschar *, uschar *, BOOL);
 
+extern void    timesince(struct timeval * diff, struct timeval * then);
+extern void    tls_modify_variables(tls_support *);
 extern uschar *tod_stamp(int);
 
-extern void    tls_modify_variables(tls_support *);
 extern BOOL    transport_check_waiting(const uschar *, const uschar *, int, uschar *,
                  BOOL *, oicf, void*);
 extern void    transport_init(void);
diff --git a/src/src/globals.c b/src/src/globals.c
index 8c35c6fe2..894b59967 100644
--- a/src/src/globals.c
+++ b/src/src/globals.c
@@ -383,6 +383,7 @@ address_item address_defaults = {
   { 0 },                /* localpart_cache - ditto */
   -1,                   /* mode */
   0,                    /* more_errno */
+  0,			/* delivery_usec */
   ERRNO_UNKNOWNERROR,   /* basic_errno */
   0,                    /* child_count */
   -1,                   /* return_file */
@@ -1107,7 +1108,7 @@ uschar *received_header_text   = US
 
 int     received_headers_max   = 30;
 uschar *received_protocol      = NULL;
-int     received_time          = 0;
+struct timeval received_time   = { 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 4a54c3c73..2d26bd0d7 100644
--- a/src/src/globals.h
+++ b/src/src/globals.h
@@ -721,7 +721,7 @@ 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 int     received_time;          /* Time the message was received */
+extern struct timeval received_time;   /* Time the message was received */
 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/queue.c b/src/src/queue.c
index 5d8d610c6..60bf2ce77 100644
--- a/src/src/queue.c
+++ b/src/src/queue.c
@@ -880,7 +880,7 @@ for (reset_point = store_get(0); f; f = f->next)
 
     if (Ustat(fname, &statbuf) == 0)
       size = message_size + statbuf.st_size - SPOOL_DATA_START_OFFSET + 1;
-    i = (now - received_time)/60;  /* minutes on queue */
+    i = (now - received_time.tv_sec)/60;  /* minutes on queue */
     if (i > 90)
       {
       i = (i + 30)/60;
diff --git a/src/src/readconf.c b/src/src/readconf.c
index df3fe823c..1ed93eb64 100644
--- a/src/src/readconf.c
+++ b/src/src/readconf.c
@@ -2298,10 +2298,10 @@ t /= 24;
 d = t % 7;
 w = t/7;
 
-if (w > 0) { sprintf(CS p, "%dw", w); while (*p) p++; }
-if (d > 0) { sprintf(CS p, "%dd", d); while (*p) p++; }
-if (h > 0) { sprintf(CS p, "%dh", h); while (*p) p++; }
-if (m > 0) { sprintf(CS p, "%dm", m); while (*p) p++; }
+if (w > 0) p += sprintf(CS p, "%dw", w);
+if (d > 0) p += sprintf(CS p, "%dd", d);
+if (h > 0) p += sprintf(CS p, "%dh", h);
+if (m > 0) p += sprintf(CS p, "%dm", m);
 if (s > 0 || p == time_buffer) sprintf(CS p, "%ds", s);
 
 return time_buffer;
diff --git a/src/src/receive.c b/src/src/receive.c
index 9561a4baf..71026ff4a 100644
--- a/src/src/receive.c
+++ b/src/src/receive.c
@@ -1743,9 +1743,9 @@ message id creation below. */
 
 /* For other uses of the received time we can operate with granularity of one
 second, and for that we use the global variable received_time. This is for
-things like ultimate message timeouts. */
+things like ultimate message timeouts.XXX */
 
-received_time = message_id_tv.tv_sec;
+received_time = message_id_tv;
 
 /* If SMTP input, set the special handler for timeouts. The alarm() calls
 happen in the smtp_getc() function when it refills its buffer. */
diff --git a/src/src/retry.c b/src/src/retry.c
index abfeeb4fb..0bb33a053 100644
--- a/src/src/retry.c
+++ b/src/src/retry.c
@@ -54,8 +54,8 @@ if (retry != NULL && retry->rules != NULL)
        last_rule = last_rule->next);
   DEBUG(D_retry)
     debug_printf("  received_time=%d diff=%d timeout=%d\n",
-      received_time, (int)(now - received_time), last_rule->timeout);
-  address_timeout = (now - received_time > last_rule->timeout);
+      received_time.tv_sec, (int)(now - received_time.tv_sec), last_rule->timeout);
+  address_timeout = (now - received_time.tv_sec > last_rule->timeout);
   }
 else
   {
@@ -754,7 +754,7 @@ for (i = 0; i < 3; i++)
         this is a small bit of code, and it does no harm to leave it in place,
         just in case. */
 
-        if (  received_time <= retry_record->first_failed
+        if (  received_time.tv_sec <= retry_record->first_failed
 	   && addr == endaddr
 	   && !retry_record->expired
 	   && rule)
@@ -762,7 +762,7 @@ for (i = 0; i < 3; i++)
           retry_rule *last_rule;
           for (last_rule = rule; last_rule->next; last_rule = last_rule->next)
 	    ;
-          if (now - received_time > last_rule->timeout)
+          if (now - received_time.tv_sec > last_rule->timeout)
             {
             DEBUG(D_retry) debug_printf("on queue longer than maximum retry\n");
             timedout_count++;
diff --git a/src/src/spool_in.c b/src/src/spool_in.c
index 0bdf92e3b..a5b14959f 100644
--- a/src/src/spool_in.c
+++ b/src/src/spool_in.c
@@ -397,10 +397,11 @@ sender_address[n-3] = 0;
 
 /* time */
 if (Ufgets(big_buffer, big_buffer_size, f) == NULL) goto SPOOL_READ_ERROR;
-if (sscanf(CS big_buffer, "%d %d", &received_time, &warning_count) != 2)
+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;
 
-message_age = time(NULL) - received_time;
+message_age = time(NULL) - received_time.tv_sec;
 
 #ifndef COMPILE_UTILITY
 DEBUG(D_deliver) debug_printf("user=%s uid=%ld gid=%ld sender=%s\n",
@@ -573,7 +574,8 @@ for (;;)
     break;
 
     case 'l':
-    if (Ustrcmp(p, "ocal") == 0) sender_local = TRUE;
+    if (Ustrcmp(p, "ocal") == 0)
+      sender_local = TRUE;
     else if (Ustrcmp(big_buffer, "-localerror") == 0)
       local_error_message = TRUE;
     else if (Ustrncmp(p, "ocal_scan ", 10) == 0)
@@ -593,6 +595,12 @@ for (;;)
     case 'r':
     if (Ustrncmp(p, "eceived_protocol", 16) == 0)
       received_protocol = string_copy(big_buffer + 19);
+    else if (Ustrncmp(p, "eceived_time_usec", 17) == 0)
+      {
+      unsigned usec;
+      if (sscanf(CS big_buffer + 21, "%u", &usec) == 1)
+	received_time.tv_usec = usec;
+      }
     break;
 
     case 's':
diff --git a/src/src/spool_out.c b/src/src/spool_out.c
index ebe089d4f..ac3927910 100644
--- a/src/src/spool_out.c
+++ b/src/src/spool_out.c
@@ -154,26 +154,28 @@ fprintf(f, "%s-H\n", message_id);
 fprintf(f, "%.63s %ld %ld\n", originator_login, (long int)originator_uid,
   (long int)originator_gid);
 fprintf(f, "<%s>\n", sender_address);
-fprintf(f, "%d %d\n", received_time, warning_count);
+fprintf(f, "%d %d\n", received_time.tv_sec, warning_count);
+
+fprintf(f, "-received_time_usec .%06d\n", received_time.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 (sender_helo_name != NULL)
+if (sender_helo_name)
   fprintf(f, "-helo_name %s\n", sender_helo_name);
 
-if (sender_host_address != NULL)
+if (sender_host_address)
   {
   fprintf(f, "-host_address %s.%d\n", sender_host_address, sender_host_port);
-  if (sender_host_name != NULL)
+  if (sender_host_name)
     fprintf(f, "-host_name %s\n", sender_host_name);
-  if (sender_host_authenticated != NULL)
+  if (sender_host_authenticated)
     fprintf(f, "-host_auth %s\n", sender_host_authenticated);
   }
 
 /* Also about the interface a message came in on */
 
-if (interface_address != NULL)
+if (interface_address)
   fprintf(f, "-interface_address %s.%d\n", interface_address, interface_port);
 
 if (smtp_active_hostname != primary_hostname)
@@ -183,11 +185,11 @@ if (smtp_active_hostname != primary_hostname)
 likely to be the same as originator_login, but will be different if
 the originator was root, forcing a different ident. */
 
-if (sender_ident != NULL) fprintf(f, "-ident %s\n", sender_ident);
+if (sender_ident) fprintf(f, "-ident %s\n", sender_ident);
 
 /* Ditto for the received protocol */
 
-if (received_protocol != NULL)
+if (received_protocol)
   fprintf(f, "-received_protocol %s\n", received_protocol);
 
 /* Preserve any ACL variables that are set. */
@@ -205,9 +207,9 @@ fprintf(f, "-max_received_linelength %d\n", max_received_linelength);
 
 if (body_zerocount > 0) fprintf(f, "-body_zerocount %d\n", body_zerocount);
 
-if (authenticated_id != NULL)
+if (authenticated_id)
   fprintf(f, "-auth_id %s\n", authenticated_id);
-if (authenticated_sender != NULL)
+if (authenticated_sender)
   fprintf(f, "-auth_sender %s\n", authenticated_sender);
 
 if (allow_unqualified_recipient) fprintf(f, "-allow_unqualified_recipient\n");
@@ -261,7 +263,7 @@ if (message_smtputf8)
 
 /* Write the dsn flags to the spool header file */
 DEBUG(D_deliver) debug_printf("DSN: Write SPOOL :-dsn_envid %s\n", dsn_envid);
-if (dsn_envid != NULL) fprintf(f, "-dsn_envid %s\n", dsn_envid);
+if (dsn_envid) fprintf(f, "-dsn_envid %s\n", dsn_envid);
 DEBUG(D_deliver) debug_printf("DSN: Write SPOOL :-dsn_ret %d\n", dsn_ret);
 if (dsn_ret != 0) fprintf(f, "-dsn_ret %d\n", dsn_ret);
 
@@ -316,7 +318,7 @@ various other headers, or an asterisk for old headers that have been rewritten.
 These are saved as a record for debugging. Don't included them in the message's
 size. */
 
-for (h = header_list; h != NULL; h = h->next)
+for (h = header_list; h; h = h->next)
   {
   fprintf(f, "%03d%c %s", h->slen, h->type, h->text);
   size_correction += 5;
diff --git a/src/src/structs.h b/src/src/structs.h
index 885c1b500..3de8f3d41 100644
--- a/src/src/structs.h
+++ b/src/src/structs.h
@@ -631,6 +631,7 @@ typedef struct address_item {
   int     mode;                   /* mode for local transporting to a file */
   int     more_errno;             /* additional error information */
                                   /* (may need to hold a timestamp) */
+  unsigned int delivery_usec;	  /* subsecond part of delivery time */
 
   short int basic_errno;          /* status after failure */
   unsigned short child_count;     /* number of child addresses */
diff --git a/src/src/transport.c b/src/src/transport.c
index b26251c88..c6b4c77ef 100644
--- a/src/src/transport.c
+++ b/src/src/transport.c
@@ -1253,6 +1253,8 @@ if ((write_pid = fork()) == 0)
         != sizeof(int)
      || write(pfd[pipe_write], (void *)&tctx->addr->more_errno, sizeof(int))
         != sizeof(int)
+     || write(pfd[pipe_write], (void *)&tctx->addr->delivery_usec, sizeof(int))
+        != sizeof(int)
      )
     rc = FALSE;	/* compiler quietening */
   _exit(0);
@@ -1377,7 +1379,8 @@ if (write_pid > 0)
       else if (!ok)
         {
 	int dummy = read(pfd[pipe_read], (void *)&save_errno, sizeof(int));
-        dummy = read(pfd[pipe_read], (void *)&(tctx->addr->more_errno), sizeof(int));
+        dummy = read(pfd[pipe_read], (void *)&tctx->addr->more_errno, sizeof(int));
+        dummy = read(pfd[pipe_read], (void *)&tctx->addr->delivery_usec, sizeof(int));
         yield = FALSE;
         }
       }
diff --git a/src/src/transports/smtp.c b/src/src/transports/smtp.c
index 11a996c65..d424c182c 100644
--- a/src/src/transports/smtp.c
+++ b/src/src/transports/smtp.c
@@ -2714,7 +2714,7 @@ address_item *addr;
 int yield = OK;
 int save_errno;
 int rc;
-time_t start_delivery_time = time(NULL);
+struct timeval start_delivery_time;
 
 BOOL pass_message = FALSE;
 uschar *message = NULL;
@@ -2723,6 +2723,7 @@ uschar *p;
 
 smtp_context sx;
 
+gettimeofday(&start_delivery_time, NULL);
 suppress_tls = suppress_tls;  /* stop compiler warning when no TLS support */
 *message_defer = FALSE;
 
@@ -3036,10 +3037,11 @@ else
   if (sx.ok)
     {
     int flag = '=';
-    int delivery_time = (int)(time(NULL) - start_delivery_time);
+    struct timeval delivery_time;
     int len;
-    uschar *conf = NULL;
+    uschar * conf = NULL;
 
+    timesince(&delivery_time, &start_delivery_time);
     sx.send_rset = FALSE;
     pipelining_active = FALSE;
 
@@ -3114,7 +3116,8 @@ else
       actual host that was used. */
 
       addr->transport_return = OK;
-      addr->more_errno = delivery_time;
+      addr->more_errno = delivery_time.tv_sec;
+      addr->delivery_usec = delivery_time.tv_usec;
       addr->host_used = host;
       addr->special_action = flag;
       addr->message = conf;
@@ -4160,7 +4163,7 @@ for (cutoff_retry = 0;
       {
       if (  !host->address
          || host->status != hstatus_unusable_expired
-	 || host->last_try > received_time)
+	 || host->last_try > received_time.tv_sec)
         continue;
       DEBUG(D_transport) debug_printf("trying expired host %s [%s]%s\n",
           host->name, host->address, pistring);
@@ -4480,7 +4483,7 @@ for (cutoff_retry = 0;
         for (last_rule = retry->rules;
              last_rule->next;
              last_rule = last_rule->next);
-        timedout = time(NULL) - received_time > last_rule->timeout;
+        timedout = time(NULL) - received_time.tv_sec > last_rule->timeout;
         }
       else timedout = TRUE;    /* No rule => timed out */
 
diff --git a/test/log/0506 b/test/log/0506
index d74b21dab..e0140f58b 100644
--- a/test/log/0506
+++ b/test/log/0506
@@ -1,7 +1,7 @@
 1999-03-02 09:44:33 10HmaX-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss
 1999-03-02 09:44:33 10HmaX-0005vi-00 => discarded <exim-filter@test.ex> R=r1
 1999-03-02 09:44:33 10HmaX-0005vi-00 => discarded <sieve-filter@test.ex> R=r1
-1999-03-02 09:44:33 10HmaX-0005vi-00 Completed QT=0s
+1999-03-02 09:44:33 10HmaX-0005vi-00 Completed QT=qqs
 1999-03-02 09:44:33 10HmaY-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss
 1999-03-02 09:44:33 10HmaY-0005vi-00 => discarded <exim-filter@test.ex> R=r1
 1999-03-02 09:44:33 10HmaY-0005vi-00 == sieve-filter@test.ex R=r1 defer (-17): error in filter file: Sieve filtering not enabled
diff --git a/test/log/0551 b/test/log/0551
index 189bd380d..5baae67cb 100644
--- a/test/log/0551
+++ b/test/log/0551
@@ -3,9 +3,9 @@
 1999-03-02 09:44:33 [1235] 10HmaX-0005vi-00 => usery <usery@test.ex> R=r1 T=t1
 1999-03-02 09:44:33 [1235] 10HmaX-0005vi-00 Completed
 1999-03-02 09:44:33 [1236] 10HmaY-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss
-1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 => userx <userx@test.ex> R=r1 T=t1
-1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 => userz <userz@test.ex> R=r1 T=t1
+1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 => userx <userx@test.ex> R=r1 T=t1 QT=qqs
+1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 => userz <userz@test.ex> R=r1 T=t1 QT=qqs
 1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 Completed
 2017-07-30 18:51:05.712 10HmaZ-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss
-2017-07-30 18:51:05.712 10HmaZ-0005vi-00 => userx <userx@test.ex> R=r1 T=t1
-2017-07-30 18:51:05.712 10HmaZ-0005vi-00 Completed
+2017-07-30 18:51:05.712 10HmaZ-0005vi-00 => userx <userx@test.ex> R=r1 T=t1 QT=q.qqqs DT=q.qqqs
+2017-07-30 18:51:05.712 10HmaZ-0005vi-00 Completed QT=q.qqqs
diff --git a/test/runtest b/test/runtest
index b7339f5d0..90c1758ca 100755
--- a/test/runtest
+++ b/test/runtest
@@ -491,6 +491,9 @@ RESET_AFTER_EXTRA_LINE_READ:
   s/^\d{4}-\d\d-\d\d\s\d\d:\d\d:\d\d\.\d{3}(\s[+-]\d\d\d\d)?\s/2017-07-30 18:51:05.712 /gx;
   s/^Logwrite\s"\d{4}-\d\d-\d\d\s\d\d:\d\d:\d\d/Logwrite "1999-03-02 09:44:33/gx;
 
+  s/([QD]T=)\d+s/$1qqs/g;
+  s/([QD]T=)\d\.\d{3}s/$1q.qqqs/g;
+
   # Date/time in message separators
   s/(?:[A-Z][a-z]{2}\s){2}\d\d\s\d\d:\d\d:\d\d\s\d\d\d\d
     /Tue Mar 02 09:44:33 1999/gx;
@@ -518,9 +521,6 @@ RESET_AFTER_EXTRA_LINE_READ:
   # Date/time in exim -bV output
   s/\d\d-[A-Z][a-z]{2}-\d{4}\s\d\d:\d\d:\d\d/07-Mar-2000 12:21:52/g;
 
-  # Time on queue tolerance
-  s/(QT|D)=1s/$1=0s/;
-
   # Eximstats heading
   s/Exim\sstatistics\sfrom\s\d{4}-\d\d-\d\d\s\d\d:\d\d:\d\d\sto\s
     \d{4}-\d\d-\d\d\s\d\d:\d\d:\d\d/Exim statistics from <time> to <time>/x;
@@ -911,6 +911,9 @@ RESET_AFTER_EXTRA_LINE_READ:
     # optional IDN2 variant conversions.  Accept either IDN1 or IDN2
     s/conversion  strasse.de/conversion  xn--strae-oqa.de/;
     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/;
     }
 
   # ======== stderr ========
diff --git a/test/scripts/0000-Basic/0551 b/test/scripts/0000-Basic/0551
index b91f7e206..f71537ed3 100644
--- a/test/scripts/0000-Basic/0551
+++ b/test/scripts/0000-Basic/0551
@@ -3,10 +3,10 @@
 exim -odi userx@test.ex usery@test.ex
 Message 1
 ****
-exim -odi userx@test.ex userz@test.ex
+exim -DLOG_SELECTOR=+pid+queue_time -odi userx@test.ex userz@test.ex
 Message 2
 ****
-exim -DLOG_SELECTOR=+millisec -odi userx@test.ex
+exim -DLOG_SELECTOR=+queue_time+queue_time_overall+deliver_time+millisec -odi userx@test.ex
 Message 3
 ****
 exigrep userx
diff --git a/test/stdout/0035 b/test/stdout/0035
index 6855c1d31..60e2c62d2 100644
--- a/test/stdout/0035
+++ b/test/stdout/0035
@@ -144,6 +144,7 @@ End of script
 EXIMUSER EXIM_UID EXIM_GID
 <notsubmit@y>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -helo_name rhu.barb
 -host_address 127.0.0.1.9999
 -interface_address 127.0.0.1.1225
@@ -164,6 +165,7 @@ dddP Received: from [127.0.0.1] (helo=rhu.barb)
 EXIMUSER EXIM_UID EXIM_GID
 <a@y>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -helo_name rhu.barb
 -host_address 127.0.0.1.9999
 -interface_address 127.0.0.1.1225
@@ -187,6 +189,7 @@ dddF From: a@y
 EXIMUSER EXIM_UID EXIM_GID
 <>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -helo_name rhu.barb
 -host_address 127.0.0.1.9999
 -interface_address 127.0.0.1.1225
@@ -208,6 +211,7 @@ dddP Received: from [127.0.0.1] (helo=rhu.barb)
 EXIMUSER EXIM_UID EXIM_GID
 <notsubmit@y>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -helo_name rhu.barb
 -host_address 127.0.0.1.9999
 -interface_address 127.0.0.1.1225
@@ -229,6 +233,7 @@ dddS Sender: sender@some.where
 EXIMUSER EXIM_UID EXIM_GID
 <a@y>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -helo_name rhu.barb
 -host_address 127.0.0.1.9999
 -interface_address 127.0.0.1.1225
@@ -253,6 +258,7 @@ dddF From: a@y
 EXIMUSER EXIM_UID EXIM_GID
 <a@y>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -helo_name rhu.barb
 -host_address 127.0.0.1.9999
 -interface_address 127.0.0.1.1225
@@ -277,6 +283,7 @@ dddF From: a@y
 EXIMUSER EXIM_UID EXIM_GID
 <a@y>
 ddddddddd 0
+-received_time_usec .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 36332a61b..5d0f2df34 100644
--- a/test/stdout/0245
+++ b/test/stdout/0245
@@ -7,6 +7,7 @@
 CALLER UID GID
 <CALLER@myhost.test.ex>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -ident CALLER
 -received_protocol local
 -body_linecount 1
diff --git a/test/stdout/0250 b/test/stdout/0250
index 1d364b4e9..c19185e84 100644
--- a/test/stdout/0250
+++ b/test/stdout/0250
@@ -2,6 +2,7 @@
 CALLER UID GID
 <CALLER-rewritten@test.ex>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -ident CALLER
 -received_protocol local
 -body_linecount 0
@@ -32,6 +33,7 @@ ddd* X-rewrote-sender: CALLER@test.ex
 CALLER UID GID
 <CALLER-rewritten@test.ex>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -ident CALLER
 -received_protocol local
 -body_linecount 0
@@ -62,6 +64,7 @@ ddd* X-rewrote-sender: CALLER@test.ex
 CALLER UID GID
 <CALLER-rewritten@test.ex>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -ident CALLER
 -received_protocol local
 -body_linecount 0
diff --git a/test/stdout/0254 b/test/stdout/0254
index 3e044dd6f..69b80a192 100644
--- a/test/stdout/0254
+++ b/test/stdout/0254
@@ -2,6 +2,7 @@
 CALLER UID GID
 <CALLER@myhost.test.ex>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -ident CALLER
 -received_protocol local
 -body_linecount 0
@@ -38,6 +39,7 @@ dddS Resent-Sender: CALLER_NAME <CALLER@myhost.test.ex>
 CALLER UID GID
 <CALLER@myhost.test.ex>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -ident CALLER
 -received_protocol local
 -body_linecount 0
@@ -67,6 +69,7 @@ dddS Resent-Sender: CALLER_NAME <CALLER@myhost.test.ex>
 CALLER UID GID
 <CALLER@myhost.test.ex>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -ident CALLER
 -received_protocol local
 -body_linecount 0
diff --git a/test/stdout/0311 b/test/stdout/0311
index 45190072f..960e8e0b7 100644
--- a/test/stdout/0311
+++ b/test/stdout/0311
@@ -2,6 +2,7 @@
 CALLER UID GID
 <CALLER@myhost.test.ex>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -ident CALLER
 -received_protocol local
 -body_linecount 0
@@ -30,6 +31,7 @@ dddF From: CALLER_NAME <CALLER@myhost.test.ex>
 CALLER UID GID
 <CALLER@myhost.test.ex>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -ident CALLER
 -received_protocol local
 -body_linecount 0
diff --git a/test/stdout/0338 b/test/stdout/0338
index 52bd7ee37..fbbbc69c5 100644
--- a/test/stdout/0338
+++ b/test/stdout/0338
@@ -6,6 +6,7 @@
 CALLER UID GID
 <CALLER@test.ex>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -ident CALLER
 -received_protocol local
 -body_linecount 0
diff --git a/test/stdout/0377 b/test/stdout/0377
index 59742e666..de1e5e305 100644
--- a/test/stdout/0377
+++ b/test/stdout/0377
@@ -2,6 +2,7 @@
 CALLER UID GID
 <CALLER@myhost.test.ex>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -ident CALLER
 -received_protocol local
 -body_linecount 0
diff --git a/test/stdout/0378 b/test/stdout/0378
index e64fdef16..c60701cbc 100644
--- a/test/stdout/0378
+++ b/test/stdout/0378
@@ -2,6 +2,7 @@
 CALLER UID GID
 <CALLER@myhost.test.ex>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -ident CALLER
 -received_protocol local
 -body_linecount 0
diff --git a/test/stdout/0379 b/test/stdout/0379
index 7bfea116f..d26d23523 100644
--- a/test/stdout/0379
+++ b/test/stdout/0379
@@ -2,6 +2,7 @@
 CALLER UID GID
 <CALLER@myhost.test.ex>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -ident CALLER
 -received_protocol local
 -body_linecount 0
diff --git a/test/stdout/0389 b/test/stdout/0389
index 69b1bfc00..bb5977af7 100644
--- a/test/stdout/0389
+++ b/test/stdout/0389
@@ -8,6 +8,7 @@
 CALLER UID GID
 <CALLER@myhost.test.ex>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -ident CALLER
 -received_protocol local-smtp
 -aclm 0 22
diff --git a/test/stdout/0488 b/test/stdout/0488
index ff89ff2f7..d6d3b4b18 100644
--- a/test/stdout/0488
+++ b/test/stdout/0488
@@ -8,6 +8,7 @@
 CALLER UID GID
 <CALLER@myhost.test.ex>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -ident CALLER
 -received_protocol local-smtp
 -body_linecount 0
diff --git a/test/stdout/0490 b/test/stdout/0490
index f9cb83d19..ee77a71e6 100644
--- a/test/stdout/0490
+++ b/test/stdout/0490
@@ -12,6 +12,7 @@
 CALLER UID GID
 <CALLER@myhost.test.ex>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -ident CALLER
 -received_protocol local-smtp
 -body_linecount 2
diff --git a/test/stdout/0514 b/test/stdout/0514
index 83111ea92..5b8677c65 100644
--- a/test/stdout/0514
+++ b/test/stdout/0514
@@ -5,6 +5,7 @@
 CALLER UID GID
 <"spaced user"@myhost.test.ex>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -ident spaced user
 -received_protocol local
 -body_linecount 1
diff --git a/test/stdout/0551 b/test/stdout/0551
index 9212d1410..9b99fcc54 100644
--- a/test/stdout/0551
+++ b/test/stdout/0551
@@ -4,13 +4,13 @@
 1999-03-02 09:44:33 [1235] 10HmaX-0005vi-00 Completed
 
 1999-03-02 09:44:33 [1236] 10HmaY-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss
-1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 => userx <userx@test.ex> R=r1 T=t1
-1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 => userz <userz@test.ex> R=r1 T=t1
+1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 => userx <userx@test.ex> R=r1 T=t1 QT=qqs
+1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 => userz <userz@test.ex> R=r1 T=t1 QT=qqs
 1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 Completed
 
 2017-07-30 18:51:05.712 10HmaZ-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss
-2017-07-30 18:51:05.712 10HmaZ-0005vi-00 => userx <userx@test.ex> R=r1 T=t1
-2017-07-30 18:51:05.712 10HmaZ-0005vi-00 Completed
+2017-07-30 18:51:05.712 10HmaZ-0005vi-00 => userx <userx@test.ex> R=r1 T=t1 QT=q.qqqs DT=q.qqqs
+2017-07-30 18:51:05.712 10HmaZ-0005vi-00 Completed QT=q.qqqs
 
 exigrep exit code = 0
 
diff --git a/test/stdout/3415 b/test/stdout/3415
index f675c6c74..8e20252e2 100644
--- a/test/stdout/3415
+++ b/test/stdout/3415
@@ -155,6 +155,7 @@ End of script
 EXIMUSER EXIM_UID EXIM_GID
 <username@myhost.test.ex>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -helo_name rhu.barb
 -host_address 127.0.0.1.9999
 -host_auth au1
@@ -181,6 +182,7 @@ dddS Sender: username@myhost.test.ex
 EXIMUSER EXIM_UID EXIM_GID
 <>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -helo_name rhu.barb
 -host_address 127.0.0.1.9999
 -host_auth au1
@@ -205,6 +207,7 @@ dddF From: username@myhost.test.ex
 EXIMUSER EXIM_UID EXIM_GID
 <>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -helo_name rhu.barb
 -host_address 127.0.0.1.9999
 -host_auth au1
@@ -229,6 +232,7 @@ dddF From: username@another.domain
 EXIMUSER EXIM_UID EXIM_GID
 <>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -helo_name rhu.barb
 -host_address 127.0.0.1.9999
 -host_auth au1
@@ -253,6 +257,7 @@ dddF From: username@auth.id.domain
 EXIMUSER EXIM_UID EXIM_GID
 <>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -helo_name rhu.barb
 -host_address 127.0.0.1.9999
 -host_auth au1