Logging: millisecond timestamps. Bug 2102

No change to QT logging yet as that will need a spool format update

13 files changed, 207 insertions, 181 deletions

diff --git a/doc/doc-docbook/spec.xfpt b/doc/doc-docbook/spec.xfpt
index 84540508f..a4b1926ec 100644
--- a/doc/doc-docbook/spec.xfpt
+++ b/doc/doc-docbook/spec.xfpt
@@ -36118,6 +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
 &` outgoing_interface         `&  local interface on => lines
 &` outgoing_port              `&  add remote port to => lines
 &`*queue_run                  `&  start and end queue runs
@@ -36282,6 +36283,14 @@ important with the widening use of NAT (see RFC 2505).
 &%lost_incoming_connection%&: A log line is written when an incoming SMTP
 connection is unexpectedly dropped.
 .next
+.new
+.cindex "log" "millisecond timestamps"
+.cindex millisecond logging
+.cindex timstamps "millisecond, in logs"
+&%millisec%&: Timestamps have a period and three decimal places of finer granularity
+appended to the seconds value.
+.wen
+.next
 .cindex "log" "outgoing interface"
 .cindex "log" "local interface"
 .cindex "log" "local address and port"
diff --git a/doc/doc-txt/NewStuff b/doc/doc-txt/NewStuff
index f3050a950..ea757f059 100644
--- a/doc/doc-txt/NewStuff
+++ b/doc/doc-txt/NewStuff
@@ -44,6 +44,8 @@ Version 4.90
 10. Variable $smtp_command_history returning a comma-sep list of recent
     SMTP commands.
 
+11. Millisecond timetamps in logs, on log_selector "millisec".
+
 
 Version 4.89
 ------------
diff --git a/src/OS/Makefile-Base b/src/OS/Makefile-Base
index 11f4dad0c..b4345e86f 100644
--- a/src/OS/Makefile-Base
+++ b/src/OS/Makefile-Base
@@ -487,7 +487,7 @@ OBJ_MONBIN = util-spool_in.o \
 	     util-store.o \
 	     util-string.o \
 	     util-queue.o \
-	     tod.o \
+	     util-tod.o \
 	     tree.o \
 	     $(MONBIN)
 
@@ -614,6 +614,10 @@ util-queue.o:   $(HDRS) queue.c
 	@echo "$(CC) -DCOMPILE_UTILITY queue.c"
 	$(FE)$(CC) -c $(CFLAGS) $(INCLUDE) -DCOMPILE_UTILITY -o util-queue.o queue.c
 
+util-tod.o:   $(HDRS) tod.c
+	@echo "$(CC) -DCOMPILE_UTILITY tod.c"
+	$(FE)$(CC) -c $(CFLAGS) $(INCLUDE) -DCOMPILE_UTILITY -o util-tod.o tod.c
+
 util-os.o:       $(HDRS) os.c
 	@echo "$(CC) -DCOMPILE_UTILITY os.c"
 	$(FE)$(CC) -c $(CFLAGS) $(INCLUDE) \
diff --git a/src/src/exigrep.src b/src/src/exigrep.src
index 851ca63bb..1899267be 100644
--- a/src/src/exigrep.src
+++ b/src/src/exigrep.src
@@ -45,7 +45,7 @@ use POSIX qw(mktime);
 
 sub seconds {
 my($year,$month,$day,$hour,$min,$sec,$tzs,$tzh,$tzm) =
-  $_[0] =~ /^(\d{4})-(\d\d)-(\d\d)\s(\d\d):(\d\d):(\d\d)(?>\s([+-])(\d\d)(\d\d))?/o;
+  $_[0] =~ /^(\d{4})-(\d\d)-(\d\d)\s(\d\d):(\d\d):(\d\d)(?:.\d+)?(?>\s([+-])(\d\d)(\d\d))?/o;
 
 my $seconds = mktime $sec, $min, $hour, $day, $month - 1, $year - 1900;
 
@@ -83,7 +83,7 @@ sub do_line {
 if (!/^\d{4}-/o) { $_ =~ s/^.*? exim\b.*?: //o; }
 
 return unless
-  my($date,$id) = /^(\d{4}-\d\d-\d\d \d\d:\d\d:\d\d (?:[+-]\d{4} )?)(?:\[\d+\] )?(\w{6}\-\w{6}\-\w{2})?/o;
+  my($date,$id) = /^(\d{4}-\d\d-\d\d \d\d:\d\d:\d\d(?:\.\d+)? (?:[+-]\d{4} )?)(?:\[\d+\] )?(\w{6}\-\w{6}\-\w{2})?/o;
 
 # Handle the case when the log line belongs to a specific message. We save
 # lines for specific messages until the message is complete. Then either print
@@ -124,7 +124,7 @@ if (defined $id)
   if (index($_, 'Completed') != -1 ||
       index($_, 'SMTP data timeout') != -1 ||
         (index($_, 'rejected') != -1 &&
-          /^(\d{4}-\d\d-\d\d \d\d:\d\d:\d\d (?:[+-]\d{4} )?)(?:\[\d+\] )?\w{6}\-\w{6}\-\w{2} rejected/o))
+          /^(\d{4}-\d\d-\d\d \d\d:\d\d:\d\d(?:\.\d+)? (?:[+-]\d{4} )?)(?:\[\d+\] )?\w{6}\-\w{6}\-\w{2} rejected/o))
     {
     if ($queue_time != -1 &&
         $saved{$id} =~ /^(\d{4}-\d\d-\d\d \d\d:\d\d:\d\d ([+-]\d{4} )?)/o)
diff --git a/src/src/eximstats.src b/src/src/eximstats.src
index a2113f106..727ee44b9 100644
--- a/src/src/eximstats.src
+++ b/src/src/eximstats.src
@@ -896,6 +896,7 @@ sub unformat_time {
 # POSIX::mktime.  We expect the timestamp to be of the form
 # "$year-$mon-$day $hour:$min:$sec", with month going from 1 to 12,
 # and the year to be absolute (we do the necessary conversions). The
+# seconds value can be followed by decimals, which we ignore. The
 # timestamp may be followed with an offset from UTC like "+$hh$mm"; if the
 # offset is not present, and we have not been told that the log is in UTC
 # (with the -utc option), then we adjust the time by the current local
@@ -919,7 +920,7 @@ sub seconds {
   # Is the timestamp the same as the last one?
   return $last_time if ($last_timestamp eq $timestamp);
 
-  return 0 unless ($timestamp =~ /^((\d{4})\-(\d\d)-(\d\d))\s(\d\d):(\d\d):(\d\d)( ([+-])(\d\d)(\d\d))?/o);
+  return 0 unless ($timestamp =~ /^((\d{4})\-(\d\d)-(\d\d))\s(\d\d):(\d\d):(\d\d)(?:\.\d+)?( ([+-])(\d\d)(\d\d))?/o);
 
   unless ($last_date eq $1) {
     $last_date = $1;
@@ -931,7 +932,7 @@ sub seconds {
   my $time = $date_seconds + ($5 * 3600) + ($6 * 60) + $7;
 
   # SC. Use caching. Also note we want seconds not minutes.
-  #my($this_offset) = ($10 * 60 + $11) * ($9 . "1") if defined $8;
+  #my($this_offset) = ($10 * 60 + $12) * ($9 . "1") if defined $8;
   if (defined $8 && ($8 ne $last_offset)) {
     $last_offset = $8;
     $offset_seconds = ($10 * 60 + $11) * 60;
@@ -939,7 +940,7 @@ sub seconds {
   }
 
 
-  if (defined $7) {
+  if (defined $8) {
     #$time -= $this_offset;
     $time -= $offset_seconds;
   } elsif (defined $localtime_offset) {
@@ -1853,12 +1854,23 @@ sub generate_parser {
 
     $length = length($_);
     next if ($length < 38);
-    next unless /^(\\d{4}\\-\\d\\d-\\d\\d\\s(\\d\\d):(\\d\\d):\\d\\d( [-+]\\d\\d\\d\\d)?)( \\[\\d+\\])?/o;
-
-    ($tod,$m_hour,$m_min) = ($1,$2,$3);
+    next unless /^
+		(\\d{4}\\-\\d\\d-\\d\\d\\s	# 1: YYYYMMDD HHMMSS
+			(\\d\\d)		# 2: HH
+			:
+			(\\d\\d)		# 3: MM
+			:\\d\\d
+		)
+		(\\.\\d+)?			# 4: subseconds
+		(\s[-+]\\d\\d\\d\\d)?		# 5: tz-offset
+		(\s\\[\\d+\\])?			# 6: pid
+		/ox;
+
+    $tod = defined($5) ?  $1 . $5 : $1;
+    ($m_hour,$m_min) = ($2,$3);
 
     # PH - watch for GMT offsets in the timestamp.
-    if (defined($4)) {
+    if (defined($5)) {
       $extra = 6;
       next if ($length < 44);
     }
@@ -1866,9 +1878,15 @@ sub generate_parser {
       $extra = 0;
     }
 
+    # watch for subsecond precision
+    if (defined($4)) {
+      $extra += length($4);
+      next if ($length < 38 + $extra);
+    }
+
     # PH - watch for PID added after the timestamp.
-    if (defined($5)) {
-      $extra += length($5);
+    if (defined($6)) {
+      $extra += length($6);
       next if ($length < 38 + $extra);
     }
 
diff --git a/src/src/globals.c b/src/src/globals.c
index bfb1c2166..8c35c6fe2 100644
--- a/src/src/globals.c
+++ b/src/src/globals.c
@@ -893,6 +893,7 @@ bit_table log_options[]        = { /* must be in alphabetical order */
   BIT_TABLE(L, incoming_interface),
   BIT_TABLE(L, incoming_port),
   BIT_TABLE(L, lost_incoming_connection),
+  BIT_TABLE(L, millisec),
   BIT_TABLE(L, outgoing_interface),
   BIT_TABLE(L, outgoing_port),
   BIT_TABLE(L, pid),
diff --git a/src/src/log.c b/src/src/log.c
index 62ee629b0..d12989b6f 100644
--- a/src/src/log.c
+++ b/src/src/log.c
@@ -147,7 +147,7 @@ int linecount = 0;
 
 if (running_in_test_harness) return;
 
-if (!syslog_timestamp) s += log_timezone? 26 : 20;
+if (!syslog_timestamp) s += log_timezone ? 26 : 20;
 if (!syslog_pid && LOGGING(pid))
     memmove(s + pid_position[0], s + pid_position[1], pid_position[1] - pid_position[0]);
 
@@ -223,10 +223,10 @@ Returns:     The function does not return
 static void
 die(uschar *s1, uschar *s2)
 {
-if (s1 != NULL)
+if (s1)
   {
   write_syslog(LOG_CRIT, s1);
-  if (debug_file != NULL) debug_printf("%s\n", s1);
+  if (debug_file) debug_printf("%s\n", s1);
   if (log_stderr != NULL && log_stderr != debug_file)
     fprintf(log_stderr, "%s\n", s1);
   }
@@ -272,7 +272,7 @@ if (fd < 0 && errno == ENOENT)
   *lastslash = 0;
   created = directory_make(NULL, name, LOG_DIRECTORY_MODE, FALSE);
   DEBUG(D_any) debug_printf("%s log directory %s\n",
-    created? "created" : "failed to create", name);
+    created ? "created" : "failed to create", name);
   *lastslash = '/';
   if (created) fd = Uopen(name,
 #ifdef O_CLOEXEC
@@ -446,10 +446,8 @@ else if (string_datestamp_offset >= 0)
 /* If the file name is too long, it is an unrecoverable disaster */
 
 if (!ok)
-  {
   die(US"exim: log file path too long: aborting",
       US"Logging failure; please try later");
-  }
 
 /* We now have the file name. Try to open an existing file. After a successful
 open, arrange for automatic closure on exec(), and then return. */
@@ -559,10 +557,7 @@ if ((flags & (LOG_CONFIG_FOR & ~LOG_CONFIG)) != 0)
   }
 
 if ((flags & (LOG_CONFIG_IN & ~LOG_CONFIG)) != 0)
-  {
-  sprintf(CS ptr, " in line %d of %s", config_lineno, config_filename);
-  while (*ptr) ptr++;
-  }
+  ptr += sprintf(CS ptr, " in line %d of %s", config_lineno, config_filename);
 
 Ustrcpy(ptr, ":\n  ");
 return ptr + 4;
@@ -736,7 +731,7 @@ Returns:    nothing
 void
 log_write(unsigned int selector, int flags, const char *format, ...)
 {
-uschar *ptr;
+uschar * ptr;
 int length;
 int paniclogfd;
 ssize_t written_len;
@@ -903,22 +898,17 @@ if (!write_rejectlog) flags &= ~LOG_REJECT;
 when called by a utility. */
 
 ptr = log_buffer;
-sprintf(CS ptr, "%s ", tod_stamp(tod_log));
-while(*ptr) ptr++;
+ptr += sprintf(CS ptr, "%s ", tod_stamp(tod_log));
 
 if (LOGGING(pid))
   {
-  sprintf(CS ptr, "[%d] ", (int)getpid());
   if (!syslog_pid) pid_position[0] = ptr - log_buffer;	/* remember begin … */
-  while (*ptr) ptr++;
+  ptr += sprintf(CS ptr, "[%d] ", (int)getpid());
   if (!syslog_pid) pid_position[1] = ptr - log_buffer;	/*  … and end+1 of the PID */
   }
 
 if (really_exim && message_id[0] != 0)
-  {
-  sprintf(CS ptr, "%s ", message_id);
-  while(*ptr) ptr++;
-  }
+  ptr += sprintf(CS ptr, "%s ", message_id);
 
 if ((flags & LOG_CONFIG) != 0) ptr = log_config_info(ptr, flags);
 
@@ -933,10 +923,7 @@ this way because it kind of fits with LOG_RECIPIENTS. */
 
 if ((flags & LOG_SENDER) != 0 &&
     ptr < log_buffer + LOG_BUFFER_SIZE - 10 - Ustrlen(raw_sender))
-  {
-  sprintf(CS ptr, " from <%s>", raw_sender);
-  while (*ptr) ptr++;
-  }
+  ptr += sprintf(CS ptr, " from <%s>", raw_sender);
 
 /* Add list of recipients to the message if required; the raw list,
 before rewriting, was saved in raw_recipients. There may be none, if an ACL
@@ -946,19 +933,16 @@ if ((flags & LOG_RECIPIENTS) != 0 && ptr < log_buffer + LOG_BUFFER_SIZE - 6 &&
      raw_recipients_count > 0)
   {
   int i;
-  sprintf(CS ptr, " for");
-  while (*ptr) ptr++;
+  ptr += sprintf(CS ptr, " for");
   for (i = 0; i < raw_recipients_count; i++)
     {
-    uschar *s = raw_recipients[i];
+    uschar * s = raw_recipients[i];
     if (log_buffer + LOG_BUFFER_SIZE - ptr < Ustrlen(s) + 3) break;
-    sprintf(CS ptr, " %s", s);
-    while (*ptr) ptr++;
+    ptr += sprintf(CS ptr, " %s", s);
     }
   }
 
-sprintf(CS  ptr, "\n");
-while(*ptr) ptr++;
+ptr += sprintf(CS  ptr, "\n");
 length = ptr - log_buffer;
 
 /* Handle loggable errors when running a utility, or when address testing.
@@ -1084,11 +1068,9 @@ if ((flags & LOG_REJECT) != 0)
 
     /* A header with a NULL text is an unfilled in Received: header */
 
-    for (h = header_list; h != NULL; h = h->next)
+    for (h = header_list; h; h = h->next) if (h->text)
       {
-      BOOL fitted;
-      if (h->text == NULL) continue;
-      fitted = string_format(ptr, LOG_BUFFER_SIZE - (ptr-log_buffer),
+      BOOL fitted = string_format(ptr, LOG_BUFFER_SIZE - (ptr-log_buffer),
         "%c %s", h->type, h->text);
       while(*ptr) ptr++;
       if (!fitted)         /* Buffer is full; truncate */
@@ -1118,7 +1100,7 @@ if ((flags & LOG_REJECT) != 0)
     {
     struct stat statbuf;
 
-    if (rejectlog_datestamp != NULL)
+    if (rejectlog_datestamp)
       {
       uschar *nowstamp = tod_stamp(string_datestamp_type);
       if (Ustrncmp (rejectlog_datestamp, nowstamp, Ustrlen(nowstamp)) != 0)
@@ -1175,9 +1157,7 @@ if ((flags & LOG_PANIC) != 0)
     fprintf(log_stderr, "%s", CS log_buffer);
 
   if ((logging_mode & LOG_MODE_SYSLOG) != 0)
-    {
     write_syslog(LOG_ALERT, log_buffer);
-    }
 
   /* If this panic logging was caused by a failure to open the main log,
   the original log line is in panic_save_buffer. Make an attempt to write it. */
diff --git a/src/src/macros.h b/src/src/macros.h
index a8022adf6..937722494 100644
--- a/src/src/macros.h
+++ b/src/src/macros.h
@@ -467,6 +467,7 @@ enum {
   Li_ident_timeout,
   Li_incoming_interface,
   Li_incoming_port,
+  Li_millisec,
   Li_outgoing_interface,
   Li_outgoing_port,
   Li_pid,
diff --git a/src/src/tod.c b/src/src/tod.c
index 5f451ba96..dac8b27f3 100644
--- a/src/src/tod.c
+++ b/src/src/tod.c
@@ -13,7 +13,7 @@
 /* #define TESTING_LOG_DATESTAMP */
 
 
-static uschar timebuf[sizeof("www, dd-mmm-yyyy hh:mm:ss +zzzz")];
+static uschar timebuf[sizeof("www, dd-mmm-yyyy hh:mm:ss.ddd +zzzz")];
 
 
 /*************************************************
@@ -52,159 +52,169 @@ Returns:   pointer to fixed buffer containing the timestamp
 uschar *
 tod_stamp(int type)
 {
-time_t now;
-struct tm *t;
+struct timeval now;
+struct tm * t;
+int off = 0;
 
-if (type == tod_epoch_l)
-  {
-  struct timeval tv;
-  gettimeofday(&tv, NULL);
-  /* Unix epoch/usec format */
-  (void) sprintf(CS timebuf, TIME_T_FMT "%06ld", tv.tv_sec, (long) tv.tv_usec );
-  return timebuf;
-  }
-
-now = time(NULL);
-
-/* Vary log type according to timezone requirement */
-
-if (type == tod_log) type = log_timezone? tod_log_zone : tod_log_bare;
+gettimeofday(&now, NULL);
 
 /* Styles that don't need local time */
 
-else if (type == tod_epoch)
+switch(type)
   {
-  (void) sprintf(CS timebuf, TIME_T_FMT, now);  /* Unix epoch format */
-  return timebuf;	/* NB the above will be wrong if time_t is FP */
+  case tod_epoch:
+    (void) sprintf(CS timebuf, TIME_T_FMT, now.tv_sec);  /* Unix epoch format */
+    return timebuf;	/* NB the above will be wrong if time_t is FP */
+
+  case tod_epoch_l:
+    /* Unix epoch/usec format */
+    (void) sprintf(CS timebuf, TIME_T_FMT "%06ld", now.tv_sec, (long) now.tv_usec );
+    return timebuf;
+
+  case tod_zulu:
+    t = gmtime(&now.tv_sec);
+    (void) sprintf(CS timebuf, "%04d%02d%02d%02d%02d%02dZ",
+      1900 + t->tm_year, 1 + t->tm_mon, t->tm_mday, t->tm_hour, t->tm_min,
+      t->tm_sec);
+    return timebuf;
   }
 
-else if (type == tod_zulu)
-  {
-  t = gmtime(&now);
-  (void) sprintf(CS timebuf, "%04d%02d%02d%02d%02d%02dZ",
-    1900 + t->tm_year, 1 + t->tm_mon, t->tm_mday, t->tm_hour, t->tm_min,
-    t->tm_sec);
-  return timebuf;
-  }
+/* Vary log type according to timezone requirement */
+
+if (type == tod_log) type = log_timezone ? tod_log_zone : tod_log_bare;
 
 /* Convert to local time or UTC */
 
-t = timestamps_utc? gmtime(&now) : localtime(&now);
+t = timestamps_utc ? gmtime(&now.tv_sec) : localtime(&now.tv_sec);
 
 switch(type)
   {
   case tod_log_bare:          /* Format used in logging without timezone */
-  (void) sprintf(CS timebuf, "%04d-%02d-%02d %02d:%02d:%02d",
-    1900 + t->tm_year, 1 + t->tm_mon, t->tm_mday,
-    t->tm_hour, t->tm_min, t->tm_sec);
-  break;
+    off = sprintf(CS timebuf, "%04d-%02d-%02d %02d:%02d:%02d",
+      1900 + t->tm_year, 1 + t->tm_mon, t->tm_mday,
+      t->tm_hour, t->tm_min, t->tm_sec);
+    break;
 
-  /* Format used as suffix of log file name when 'log_datestamp' is active. For
-  testing purposes, it changes the file every second. */
+    /* Format used as suffix of log file name when 'log_datestamp' is active. For
+    testing purposes, it changes the file every second. */
 
-  #ifdef TESTING_LOG_DATESTAMP
+#ifdef TESTING_LOG_DATESTAMP
   case tod_log_datestamp_daily:
   case tod_log_datestamp_monthly:
-  (void) sprintf(CS timebuf, "%04d%02d%02d%02d%02d",
-    1900 + t->tm_year, 1 + t->tm_mon, t->tm_mday, t->tm_hour, t->tm_min);
-  break;
+    off = sprintf(CS timebuf, "%04d%02d%02d%02d%02d",
+      1900 + t->tm_year, 1 + t->tm_mon, t->tm_mday, t->tm_hour, t->tm_min);
+    break;
 
-  #else
+#else
   case tod_log_datestamp_daily:
-  (void) sprintf(CS timebuf, "%04d%02d%02d",
-    1900 + t->tm_year, 1 + t->tm_mon, t->tm_mday);
-  break;
+    off = sprintf(CS timebuf, "%04d%02d%02d",
+      1900 + t->tm_year, 1 + t->tm_mon, t->tm_mday);
+    break;
 
   case tod_log_datestamp_monthly:
-  (void) sprintf(CS timebuf, "%04d%02d",
-    1900 + t->tm_year, 1 + t->tm_mon);
-  break;
-  #endif
+    off = sprintf(CS timebuf, "%04d%02d",
+      1900 + t->tm_year, 1 + t->tm_mon);
+    break;
+#endif
 
-  /* Format used in BSD inbox separator lines. Sort-of documented in RFC 976
-  ("UUCP Mail Interchange Format Standard") but only by example, not by
-  explicit definition. The examples show no timezone offsets, and some MUAs
-  appear to be sensitive to this, so Exim has been changed to remove the
-  timezone offsets that originally appeared. */
+    /* Format used in BSD inbox separator lines. Sort-of documented in RFC 976
+    ("UUCP Mail Interchange Format Standard") but only by example, not by
+    explicit definition. The examples show no timezone offsets, and some MUAs
+    appear to be sensitive to this, so Exim has been changed to remove the
+    timezone offsets that originally appeared. */
 
   case tod_bsdin:
-    {
-    int len = Ustrftime(timebuf, sizeof(timebuf), "%a %b %d %H:%M:%S", t);
-    Ustrftime(timebuf + len, sizeof(timebuf) - len, " %Y", t);
-    }
-  break;
-
-  /* Other types require the GMT offset to be calculated, or just set up in the
-  case of UTC timestamping. We need to take a copy of the local time first. */
-
-  default:
-    {
-    int diff_hour, diff_min;
-    struct tm local;
-    memcpy(&local, t, sizeof(struct tm));
-
-    if (timestamps_utc)
       {
-      diff_hour = diff_min = 0;
-      }
-    else
-      {
-      struct tm *gmt = gmtime(&now);
-      diff_min = 60*(local.tm_hour - gmt->tm_hour) + local.tm_min - gmt->tm_min;
-      if (local.tm_year != gmt->tm_year)
-        diff_min += (local.tm_year > gmt->tm_year)? 1440 : -1440;
-      else if (local.tm_yday != gmt->tm_yday)
-        diff_min += (local.tm_yday > gmt->tm_yday)? 1440 : -1440;
-      diff_hour = diff_min/60;
-      diff_min  = abs(diff_min - diff_hour*60);
+      int len = Ustrftime(timebuf, sizeof(timebuf), "%a %b %d %H:%M:%S", t);
+      Ustrftime(timebuf + len, sizeof(timebuf) - len, " %Y", t);
       }
+    break;
+
+    /* Other types require the GMT offset to be calculated, or just set up in the
+    case of UTC timestamping. We need to take a copy of the local time first. */
 
-    switch(type)
+  default:
       {
-      case tod_log_zone:          /* Format used in logging with timezone */
-      (void) sprintf(CS timebuf, "%04d-%02d-%02d %02d:%02d:%02d %+03d%02d",
-        1900 + local.tm_year, 1 + local.tm_mon, local.tm_mday,
-        local.tm_hour, local.tm_min, local.tm_sec,
-        diff_hour, diff_min);
-      break;
-
-      case tod_zone:              /* Just the timezone offset */
-      (void) sprintf(CS timebuf, "%+03d%02d", diff_hour, diff_min);
-      break;
-
-      /* tod_mbx: format used in MBX mailboxes - subtly different to tod_full */
-
-      #ifdef SUPPORT_MBX
-      case tod_mbx:
-        {
-        int len;
-        (void) sprintf(CS timebuf, "%02d-", local.tm_mday);
-        len = Ustrlen(timebuf);
-        len += Ustrftime(timebuf + len, sizeof(timebuf) - len, "%b-%Y %H:%M:%S",
-          &local);
-        (void) sprintf(CS timebuf + len, " %+03d%02d", diff_hour, diff_min);
-        }
-      break;
-      #endif
-
-      /* tod_full: format used in Received: headers (use as default just in case
-      called with a junk type value) */
-
-      default:
-        {
-        int len = Ustrftime(timebuf, sizeof(timebuf), "%a, ", &local);
-        (void) sprintf(CS timebuf + len, "%02d ", local.tm_mday);
-        len += Ustrlen(timebuf + len);
-        len += Ustrftime(timebuf + len, sizeof(timebuf) - len, "%b %Y %H:%M:%S",
-          &local);
-        (void) sprintf(CS timebuf + len, " %+03d%02d", diff_hour, diff_min);
-        }
-      break;
+      int diff_hour, diff_min;
+      struct tm local;
+      memcpy(&local, t, sizeof(struct tm));
+
+      if (timestamps_utc)
+	diff_hour = diff_min = 0;
+      else
+	{
+	struct tm * gmt = gmtime(&now.tv_sec);
+
+	diff_min = 60*(local.tm_hour - gmt->tm_hour) + local.tm_min - gmt->tm_min;
+	if (local.tm_year != gmt->tm_year)
+	  diff_min += (local.tm_year > gmt->tm_year)? 1440 : -1440;
+	else if (local.tm_yday != gmt->tm_yday)
+	  diff_min += (local.tm_yday > gmt->tm_yday)? 1440 : -1440;
+	diff_hour = diff_min/60;
+	diff_min  = abs(diff_min - diff_hour*60);
+	}
+
+      switch(type)
+	{
+	case tod_log_zone:          /* Format used in logging with timezone */
+#ifndef COMPILE_UTILITY
+	  if (LOGGING(millisec))
+	    (void) sprintf(CS timebuf,
+	      "%04d-%02d-%02d %02d:%02d:%02d.%03d %+03d%02d",
+	      1900 + local.tm_year, 1 + local.tm_mon, local.tm_mday,
+	      local.tm_hour, local.tm_min, local.tm_sec, now.tv_usec/1000,
+	      diff_hour, diff_min);
+	  else
+#endif
+	    (void) sprintf(CS timebuf,
+	      "%04d-%02d-%02d %02d:%02d:%02d %+03d%02d",
+	      1900 + local.tm_year, 1 + local.tm_mon, local.tm_mday,
+	      local.tm_hour, local.tm_min, local.tm_sec,
+	      diff_hour, diff_min);
+	  break;
+
+	case tod_zone:              /* Just the timezone offset */
+	  (void) sprintf(CS timebuf, "%+03d%02d", diff_hour, diff_min);
+	  break;
+
+	/* tod_mbx: format used in MBX mailboxes - subtly different to tod_full */
+
+	  #ifdef SUPPORT_MBX
+	case tod_mbx:
+	    {
+	    int len;
+	    (void) sprintf(CS timebuf, "%02d-", local.tm_mday);
+	    len = Ustrlen(timebuf);
+	    len += Ustrftime(timebuf + len, sizeof(timebuf) - len, "%b-%Y %H:%M:%S",
+	      &local);
+	    (void) sprintf(CS timebuf + len, " %+03d%02d", diff_hour, diff_min);
+	    }
+	  break;
+	  #endif
+
+	/* tod_full: format used in Received: headers (use as default just in case
+	called with a junk type value) */
+
+	default:
+	    {
+	    int len = Ustrftime(timebuf, sizeof(timebuf), "%a, ", &local);
+	    (void) sprintf(CS timebuf + len, "%02d ", local.tm_mday);
+	    len += Ustrlen(timebuf + len);
+	    len += Ustrftime(timebuf + len, sizeof(timebuf) - len, "%b %Y %H:%M:%S",
+	      &local);
+	    (void) sprintf(CS timebuf + len, " %+03d%02d", diff_hour, diff_min);
+	    }
+	  break;
+	}
       }
-    }
-  break;
+    break;
   }
 
+#ifndef COMPILE_UTILITY
+if (LOGGING(millisec) && off > 0)
+  (void) sprintf(CS timebuf + off, ".%03d", now.tv_usec/1000);
+#endif
+
 return timebuf;
 }
 
diff --git a/test/log/0551 b/test/log/0551
index 831e11a89..189bd380d 100644
--- a/test/log/0551
+++ b/test/log/0551
@@ -6,6 +6,6 @@
 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 Completed
-1999-03-02 09:44:33 10HmaZ-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss
-1999-03-02 09:44:33 10HmaZ-0005vi-00 => userx <userx@test.ex> R=r1 T=t1
-1999-03-02 09:44:33 10HmaZ-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
diff --git a/test/runtest b/test/runtest
index 0e7e8ee0b..b7339f5d0 100755
--- a/test/runtest
+++ b/test/runtest
@@ -487,7 +487,8 @@ RESET_AFTER_EXTRA_LINE_READ:
     /Tue, 2 Mar 1999 09:44:33 +0000/gx;
 
   # Date/time in logs and in one instance of a filter test
-  s/^\d{4}-\d\d-\d\d\s\d\d:\d\d:\d\d(\s[+-]\d\d\d\d)?/1999-03-02 09:44:33/gx;
+  s/^\d{4}-\d\d-\d\d\s\d\d:\d\d:\d\d(\s[+-]\d\d\d\d)?\s/1999-03-02 09:44:33 /gx;
+  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;
 
   # Date/time in message separators
diff --git a/test/scripts/0000-Basic/0551 b/test/scripts/0000-Basic/0551
index d11064c00..b91f7e206 100644
--- a/test/scripts/0000-Basic/0551
+++ b/test/scripts/0000-Basic/0551
@@ -1,4 +1,4 @@
-# log_selector = +pid
+# log_selector = +pid , +millisec
 #
 exim -odi userx@test.ex usery@test.ex
 Message 1
@@ -6,7 +6,7 @@ Message 1
 exim -odi userx@test.ex userz@test.ex
 Message 2
 ****
-exim -DLOG_SELECTOR= -odi userx@test.ex
+exim -DLOG_SELECTOR=+millisec -odi userx@test.ex
 Message 3
 ****
 exigrep userx
diff --git a/test/stdout/0551 b/test/stdout/0551
index 8af281557..9212d1410 100644
--- a/test/stdout/0551
+++ b/test/stdout/0551
@@ -8,9 +8,9 @@
 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 Completed
 
-1999-03-02 09:44:33 10HmaZ-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss
-1999-03-02 09:44:33 10HmaZ-0005vi-00 => userx <userx@test.ex> R=r1 T=t1
-1999-03-02 09:44:33 10HmaZ-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
 
 exigrep exit code = 0