From 571b27158aa468eda77b1a20ed80bed1f342e15d Mon Sep 17 00:00:00 2001 From: Jeremy Harris Date: Sun, 30 Jul 2017 20:51:10 +0100 Subject: [PATCH] Logging: millisecond timestamps. Bug 2102 No change to QT logging yet as that will need a spool format update --- doc/doc-docbook/spec.xfpt | 9 ++ doc/doc-txt/NewStuff | 2 + src/OS/Makefile-Base | 6 +- src/src/exigrep.src | 6 +- src/src/eximstats.src | 36 +++-- src/src/globals.c | 1 + src/src/log.c | 54 +++----- src/src/macros.h | 1 + src/src/tod.c | 254 ++++++++++++++++++----------------- test/log/0551 | 6 +- test/runtest | 3 +- test/scripts/0000-Basic/0551 | 4 +- test/stdout/0551 | 6 +- 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 R=r1 T=t1 1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 => userz 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 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 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 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 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 R=r1 T=t1 +2017-07-30 18:51:05.712 10HmaZ-0005vi-00 Completed exigrep exit code = 0 -- 2.30.2