Logging: millisecond QT and DT. Bug 2102
authorJeremy Harris <jgh146exb@wizmail.org>
Fri, 4 Aug 2017 14:13:17 +0000 (15:13 +0100)
committerJeremy Harris <jgh146exb@wizmail.org>
Fri, 4 Aug 2017 14:13:17 +0000 (15:13 +0100)
37 files changed:
doc/doc-docbook/spec.xfpt
src/exim_monitor/em_globals.c
src/exim_monitor/em_queue.c
src/src/deliver.c
src/src/exim.c
src/src/expand.c
src/src/functions.h
src/src/globals.c
src/src/globals.h
src/src/queue.c
src/src/readconf.c
src/src/receive.c
src/src/retry.c
src/src/spool_in.c
src/src/spool_out.c
src/src/structs.h
src/src/transport.c
src/src/transports/smtp.c
test/log/0506
test/log/0551
test/runtest
test/scripts/0000-Basic/0551
test/stdout/0035
test/stdout/0245
test/stdout/0250
test/stdout/0254
test/stdout/0311
test/stdout/0338
test/stdout/0377
test/stdout/0378
test/stdout/0379
test/stdout/0389
test/stdout/0488
test/stdout/0490
test/stdout/0514
test/stdout/0551
test/stdout/3415

index a4b1926..0d03c2f 100644 (file)
@@ -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
index 5403236..46ad834 100644 (file)
@@ -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;
index cb284eb..e6b1e91 100644 (file)
@@ -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;
   }
index 49281f9..2713cc5 100644 (file)
@@ -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
index 581b161..c990bc0 100644 (file)
@@ -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 */
index 4eb1818..d8d36a3 100644 (file)
@@ -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 */
 
index 9c9caaf..5b2a683 100644 (file)
@@ -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);
index 8c35c6f..894b599 100644 (file)
@@ -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;
index 4a54c3c..2d26bd0 100644 (file)
@@ -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 */
index 5d8d610..60bf2ce 100644 (file)
@@ -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;
index df3fe82..1ed93eb 100644 (file)
@@ -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;
index 9561a4b..71026ff 100644 (file)
@@ -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. */
index abfeeb4..0bb33a0 100644 (file)
@@ -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++;
index 0bdf92e..a5b1495 100644 (file)
@@ -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':
index ebe089d..ac39279 100644 (file)
@@ -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;
index 885c1b5..3de8f3d 100644 (file)
@@ -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 */
index b26251c..c6b4c77 100644 (file)
@@ -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;
         }
       }
index 11a996c..d424c18 100644 (file)
@@ -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 */
 
index d74b21d..e0140f5 100644 (file)
@@ -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
index 189bd38..5baae67 100644 (file)
@@ -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
index b7339f5..90c1758 100755 (executable)
@@ -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 ========
index b91f7e2..f71537e 100644 (file)
@@ -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
index 6855c1d..60e2c62 100644 (file)
@@ -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
index 36332a6..5d0f2df 100644 (file)
@@ -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
index 1d364b4..c19185e 100644 (file)
@@ -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
index 3e044dd..69b80a1 100644 (file)
@@ -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
index 4519007..960e8e0 100644 (file)
@@ -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
index 52bd7ee..fbbbc69 100644 (file)
@@ -6,6 +6,7 @@
 CALLER UID GID
 <CALLER@test.ex>
 ddddddddd 0
+-received_time_usec .uuuuuu
 -ident CALLER
 -received_protocol local
 -body_linecount 0
index 59742e6..de1e5e3 100644 (file)
@@ -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
index e64fdef..c60701c 100644 (file)
@@ -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
index 7bfea11..d26d235 100644 (file)
@@ -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
index 69b1bfc..bb5977a 100644 (file)
@@ -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
index ff89ff2..d6d3b4b 100644 (file)
@@ -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
index f9cb83d..ee77a71 100644 (file)
@@ -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
index 83111ea..5b8677c 100644 (file)
@@ -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
index 9212d14..9b99fcc 100644 (file)
@@ -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
 
index f675c6c..8e20252 100644 (file)
@@ -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