Logging: millisecond QT and DT. Bug 2102

17 files changed, 140 insertions, 71 deletions

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