Logging: millisecond QT and DT. Bug 2102

diff --git a/doc/doc-docbook/spec.xfpt b/doc/doc-docbook/spec.xfpt
index a4b1926ecfa3dede4b7755768bb9ebe518de0c35..0d03c2f9c315765d1e989345f22333f709557b0e 100644 (file)
--- 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 54032362c1775b66380f492ce187299d5fe82203..46ad834daea4f561900b8da84bace937ff0191d1 100644 (file)
--- 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 cb284eb4827d0a73839d1c0d084f5d346b31dc1d..e6b1e91d90d93dd44219100f58bff7c24a054750 100644 (file)
--- 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 49281f93d47aa835f4ab9f4f28d734ba17a835f5..2713cc56ffb3bddfa64677c0bf6cb872057db7ef 100644 (file)
--- 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 581b161903d6e7b20fb3bdfd4e18b02fe3c6fcd1..c990bc08ca4c22b1d1cf10599a614508cfe434d1 100644 (file)
--- 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 4eb1818f10ab859e9b61a1c9908c2485b3d85626..d8d36a3b5f5115e945e3279499a3d59b954c178a 100644 (file)
--- 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 9c9caaf97d8fb23878c00c2f8df6d13e3b98c309..5b2a683b846f2e7d7ac6834fca50b4f62138c7a3 100644 (file)
--- 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 8c35c6fe2c58c5caed4d98a966f17dded768322c..894b599673fe954b4a836cba3b89031fd59c2acd 100644 (file)
--- 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 4a54c3c73c13ddef57bdb160433bc0e41abe5906..2d26bd0d7901150ffa84179ce1982602f4b7af5c 100644 (file)
--- 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 5d8d610c651f6c0b3c0e78ba29aea9cbdd15f0c4..60bf2ce77c39b67f2ef40a6670ea7a8a32a01127 100644 (file)
--- 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 df3fe823cbf527541eaef8457136576f5852992f..1ed93eb642055758d53eb7153c5dc9d97ea57dad 100644 (file)
--- 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 9561a4baf79bcdc1f577be207ab5ee73d8ebd14f..71026ff4a903d8c7cc311bcf7182092b3ed88f2e 100644 (file)
--- 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 abfeeb4fbd073454123b12ebe57544477b2c0887..0bb33a05348a7ec2c99f1905a7ead13497b99913 100644 (file)
--- 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 0bdf92e3b2f02059026b63dc018dd4c67edc0307..a5b14959fa4c2fcc347125bcc0f58994100f9c3d 100644 (file)
--- 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 ebe089d4f656f8439a833bdb0c0cecb4bb0a8b54..ac3927910034e52c75121172a49bca45c5155ffb 100644 (file)
--- 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 885c1b50047e41f9ac8a412ff8f24ff1b4693e81..3de8f3d415b51c074b486687debb91cb59187841 100644 (file)
--- 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 b26251c88f5d66c7ff665e0fd6d9d116a770e6bf..c6b4c77ef6dcfd4014cedb3c0b4dc78beb2283a6 100644 (file)
--- 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 11a996c6515f9eeea008397eed703c96a62c5d95..d424c182cdf85208ed3008d223ee50997a8b120c 100644 (file)
--- 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 d74b21dabb6e65cb729d1138ed425659e3d1bfe4..e0140f58b632fd2a73ff8b48b053c80df1c8eeea 100644 (file)
--- 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 189bd380d1fb96e87ff55498e9ba6f4c92f68a5b..5baae67cb60a7976dd4b5667e8f32a0163ad9d6b 100644 (file)
--- 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 b7339f5d0519fa37e7f369cf3925b218b1a7828d..90c1758ca31431af5dda65c6ddcb71320c9af4b9 100755 (executable)
--- 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 b91f7e206826c654bbdccbb84d19b5125231f5fe..f71537ed377b1fb8a1a62ec16a87cda45e36b66f 100644 (file)
--- 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 6855c1d3189209b077706b188b9788db5d4de233..60e2c62d2a9f1a232c99adf53d3a19c92bde3474 100644 (file)
--- 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 36332a61b6f811d33557fa334f6bd41b456d07eb..5d0f2df346be976354118fed6e501617eb02e497 100644 (file)
--- 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 1d364b4e9b64bc114c44c1ae5bb7a776e21c354e..c19185e84b59cb551e25de42e0c926ed6f8cac58 100644 (file)
--- 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 3e044dd6f3123279ba067e33de9debee376c5d35..69b80a19283f23d4c6221266f89a621218e5ac0e 100644 (file)
--- 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 45190072f2fb0d1e7b1ae2a37fede3d495d18310..960e8e0b7183ee6ce2c9f53e5546f6272d799ee8 100644 (file)
--- 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 52bd7ee37b7fbd2bd60d8bfe2720bbeb7f5d4b9a..fbbbc69c516bca0ee21ded96aee4850984d77966 100644 (file)
--- 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 59742e66692ad878471ef73f7f054c4e5794f78a..de1e5e3056b531a65d5c30a77211bebabc739167 100644 (file)
--- 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 e64fdef167c632a45d725025c691f5b63b74acd5..c60701cbc62d78c0d7b2449b2376c1bc9ed89f0c 100644 (file)
--- 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 7bfea116f33cf4d4766adf89ac1bf6d6d21529cb..d26d23523fc103fe344b201b83aec30c6e868804 100644 (file)
--- 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 69b1bfc001239c4cf1748b58d2274655e4f34c9b..bb5977af7ddc7473aa1231f7ec2515971be64593 100644 (file)
--- 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 ff89ff2f76ca37f74db9c2bd7b85c5e645c4d6cc..d6d3b4b188ed8422b46d4d4263e4f3a4ed746c9a 100644 (file)
--- 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 f9cb83d19b1edf81523dfda6d2d95f000bc91261..ee77a71e68d738e4062755d6e969c608086eedec 100644 (file)
--- 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 83111ea92dce253162246b367ace186850f78a4f..5b8677c653cc928e3e6eb0fe2f8e56a39982569e 100644 (file)
--- 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 9212d14107d55e34358c1bb067bfc7ec945c46cd..9b99fcc5486e1ffc2ae209b394f5e5d8e1e24980 100644 (file)
--- 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 f675c6c74d45883a1dd1084695c9a9153448daf4..8e20252e24bfbb4d9cfb4a28db466c2429ffc199 100644 (file)
--- 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