Logging: millisecond timestamps. Bug 2102

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

diff --git a/doc/doc-docbook/spec.xfpt b/doc/doc-docbook/spec.xfpt
index 84540508f88978c25306be3f7a61fb3b673ba811..a4b1926ecfa3dede4b7755768bb9ebe518de0c35 100644 (file)
--- 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)
 &` 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
 &` 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
 &%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"
 .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 f3050a950fc1caea7c3a4d07013ea811ee9257c3..ea757f0591adc7910e405ea0a66424f74c11e644 100644 (file)
--- 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.
 
 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
 ------------
 
 Version 4.89
 ------------

diff --git a/src/OS/Makefile-Base b/src/OS/Makefile-Base
index 11f4dad0c13ed5fdd52f22a6915cd467e9d5c555..b4345e86f541043c1e89aaaa8353c48b49f94651 100644 (file)
--- 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 \
             util-store.o \
             util-string.o \
             util-queue.o \

-            tod.o \
+            util-tod.o \

             tree.o \
             $(MONBIN)
 
             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
 
        @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) \
 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 851ca63bba57750e0d05e928f1794c1e0d83f507..1899267be74d048bef2d313f7b8fe9e876582787 100644 (file)
--- 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) =
 
 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;
 
 
 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
 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
 
 # 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 &&
   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)
     {
     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 a2113f1068949fc661f000041638124a9c015a94..727ee44b9d4a2d96a0b0bc7998f02166785ff15e 100644 (file)
--- 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
 # 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
 # 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);
 
   # 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;
 
   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 $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;
   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) {
     #$time -= $this_offset;
     $time -= $offset_seconds;
   } elsif (defined $localtime_offset) {


@@ -1853,12 +1854,23 @@ sub generate_parser {
 
     $length = length($_);
     next if ($length < 38);
 
     $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.
 
     # PH - watch for GMT offsets in the timestamp.

-    if (defined($4)) {
+    if (defined($5)) {

       $extra = 6;
       next if ($length < 44);
     }
       $extra = 6;
       next if ($length < 44);
     }


@@ -1866,9 +1878,15 @@ sub generate_parser {
       $extra = 0;
     }
 
       $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.
     # 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);
     }
 
       next if ($length < 38 + $extra);
     }
 

diff --git a/src/src/globals.c b/src/src/globals.c
index bfb1c21666b770bf964b91056fc09ef84a6c1824..8c35c6fe2c58c5caed4d98a966f17dded768322c 100644 (file)
--- 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, 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),
   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 62ee629b00320c23e8abec7ea3cbeff825033c2a..d12989b6fb7c016061f4abc52889d7c40cd1e40a 100644 (file)
--- a/src/src/log.c
+++ b/src/src/log.c
@@ -147,7 +147,7 @@ int linecount = 0;
 
 if (running_in_test_harness) return;
 
 
 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]);
 
 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)
 {
 static void
 die(uschar *s1, uschar *s2)
 {

-if (s1 != NULL)
+if (s1)

   {
   write_syslog(LOG_CRIT, 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);
   }
   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",
   *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
   *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)
 /* 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");
   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. */
 
 /* 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)
   }
 
 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;
 
 Ustrcpy(ptr, ":\n  ");
 return ptr + 4;


@@ -736,7 +731,7 @@ Returns:    nothing
 void
 log_write(unsigned int selector, int flags, const char *format, ...)
 {
 void
 log_write(unsigned int selector, int flags, const char *format, ...)
 {

-uschar *ptr;
+uschar * ptr;

 int length;
 int paniclogfd;
 ssize_t written_len;
 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;
 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))
   {
 
 if (LOGGING(pid))
   {

-  sprintf(CS ptr, "[%d] ", (int)getpid());

   if (!syslog_pid) pid_position[0] = ptr - log_buffer; /* remember begin … */
   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)
   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);
 
 
 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))
 
 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
 
 /* 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;
      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++)
     {
   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;
     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.
 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 */
 
 
     /* 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 */
         "%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;
 
     {
     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)
       {
       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)
     fprintf(log_stderr, "%s", CS log_buffer);
 
   if ((logging_mode & LOG_MODE_SYSLOG) != 0)

-    {

     write_syslog(LOG_ALERT, log_buffer);
     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. */
 
   /* 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 a8022adf689b63e668a89ca469eaf6f0ba22ca48..937722494344d0bbec11546a544a393a60a6a474 100644 (file)
--- 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_ident_timeout,
   Li_incoming_interface,
   Li_incoming_port,

+  Li_millisec,

   Li_outgoing_interface,
   Li_outgoing_port,
   Li_pid,
   Li_outgoing_interface,
   Li_outgoing_port,
   Li_pid,

diff --git a/src/src/tod.c b/src/src/tod.c
index 5f451ba96de445e6b52a60b01f5a04a9ed4bc8dd..dac8b27f3d1a23cb13640fc3cf807e8166fea5ac 100644 (file)
--- a/src/src/tod.c
+++ b/src/src/tod.c
@@ -13,7 +13,7 @@
 /* #define TESTING_LOG_DATESTAMP */
 
 
 /* #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)
 {
 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 */
 
 
 /* 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 */
 
 
 /* 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 */
 
 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:
   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:
   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:
 
   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:
 
   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;
 }
 
 return timebuf;
 }
 

diff --git a/test/log/0551 b/test/log/0551
index 831e11a89f879d112c425eb7a8bc4f75d6d06959..189bd380d1fb96e87ff55498e9ba6f4c92f68a5b 100644 (file)
--- 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 [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 0e7e8ee0bc5be23acdbd43784b1e1f30ec9e9a28..b7339f5d0519fa37e7f369cf3925b218b1a7828d 100755 (executable)
--- 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
     /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
   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 d11064c0020016d1cebeb13551207c6da2f7f24b..b91f7e206826c654bbdccbb84d19b5125231f5fe 100644 (file)
--- 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
 #
 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 -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
 Message 3
 ****
 exigrep userx

diff --git a/test/stdout/0551 b/test/stdout/0551
index 8af281557d36908d10d1e680b0aa227e9ec88b95..9212d14107d55e34358c1bb067bfc7ec945c46cd 100644 (file)
--- 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 [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
 
 
 exigrep exit code = 0