- Fix #1144: [FR] log timestamps in ISO8601 format with timezone.

  This adds the option `log-time-iso: yes` that logs in ISO8601
  format.

diff --git a/doc/Changelog b/doc/Changelog
index 9cf000016120b855c256ee066caa58389eb918ae..9172b2199bf584ed839304042b36b5bfc903bc8c 100644 (file)
--- a/doc/Changelog
+++ b/doc/Changelog
@@ -1,3 +1,8 @@
+25 September 2024: Wouter
+       - Fix #1144: [FR] log timestamps in ISO8601 format with timezone.
+         This adds the option `log-time-iso: yes` that logs in ISO8601
+         format.
+
 24 September 2024: Yorgos
        - Attempt to further fix doh_downstream_buffer_size.tdir flakiness.
        - More clear text for prefetch and minimal-responses in the

diff --git a/doc/example.conf.in b/doc/example.conf.in
index e5bb5029f94617e04a63cd5c5514f93381ba79a4..2d16ee75fe4f2350e58bbc63a626aae7ad7ff0f8 100644 (file)
--- a/doc/example.conf.in
+++ b/doc/example.conf.in
@@ -461,6 +461,10 @@ server:
        # print UTC timestamp in ascii to logfile, default is epoch in seconds.
        # log-time-ascii: no
 
+       # log timestamp in ISO8601 format if also log-time-ascii is enabled.
+       # (y-m-dTh:m:s.msec[+-]tzhours:tzminutes)
+       # log-time-iso: no
+
        # print one line with time, IP, name, type, class for every query.
        # log-queries: no
 

diff --git a/doc/unbound.conf.5.in b/doc/unbound.conf.5.in
index d9c7f249a0b4e1a932b36caca6a4e253b7f3feb4..bc48db4787692b23c0570392badd21580c429561 100644 (file)
--- a/doc/unbound.conf.5.in
+++ b/doc/unbound.conf.5.in
@@ -936,6 +936,10 @@ Sets logfile lines to use a timestamp in UTC ascii. Default is no, which
 prints the seconds since 1970 in brackets. No effect if using syslog, in
 that case syslog formats the timestamp printed into the log files.
 .TP
+.B log\-time\-iso:\fR <yes or no>
+Log time in ISO8601 format, if \fBlog\-time\-ascii:\fR yes is also set.
+Default is no.
+.TP
 .B log\-queries: \fI<yes or no>
 Prints one line per query to the log, with the log timestamp and IP address,
 name, type and class.  Default is no.  Note that it takes time to print these

diff --git a/util/config_file.c b/util/config_file.c
index 3898a8b0ae67d7ab118e5f041222d23cee148e86..2eb81fcee33885f252aaa425465d44f68c6cb6c5 100644 (file)
--- a/util/config_file.c
+++ b/util/config_file.c
@@ -138,6 +138,7 @@ config_create(void)
        cfg->use_syslog = 1;
        cfg->log_identity = NULL; /* changed later with argv[0] */
        cfg->log_time_ascii = 0;
+       cfg->log_time_iso = 0;
        cfg->log_queries = 0;
        cfg->log_replies = 0;
        cfg->log_tag_queryreply = 0;
@@ -547,6 +548,9 @@ int config_set_option(struct config_file* cfg, const char* opt,
        else if(strcmp(opt, "log-time-ascii:") == 0)
        { IS_YES_OR_NO; cfg->log_time_ascii = (strcmp(val, "yes") == 0);
          log_set_time_asc(cfg->log_time_ascii); }
+       else if(strcmp(opt, "log-time-iso:") == 0)
+       { IS_YES_OR_NO; cfg->log_time_iso = (strcmp(val, "yes") == 0);
+         log_set_time_iso(cfg->log_time_iso); }
        else S_SIZET_NONZERO("max-udp-size:", max_udp_size)
        else S_YNO("use-syslog:", use_syslog)
        else S_STR("log-identity:", log_identity)
@@ -1066,6 +1070,7 @@ config_get_option(struct config_file* cfg, const char* opt,
        else O_YNO(opt, "use-syslog", use_syslog)
        else O_STR(opt, "log-identity", log_identity)
        else O_YNO(opt, "log-time-ascii", log_time_ascii)
+       else O_YNO(opt, "log-time-iso", log_time_iso)
        else O_DEC(opt, "num-threads", num_threads)
        else O_IFC(opt, "interface", num_ifs, ifs)
        else O_IFC(opt, "outgoing-interface", num_out_ifs, out_ifs)
@@ -2413,6 +2418,7 @@ config_apply(struct config_file* config)
        USEFUL_SERVER_TOP_TIMEOUT = RTT_MAX_TIMEOUT;
        BLACKLIST_PENALTY = USEFUL_SERVER_TOP_TIMEOUT*4;
        log_set_time_asc(config->log_time_ascii);
+       log_set_time_iso(config->log_time_iso);
        autr_permit_small_holddown = config->permit_small_holddown;
        stream_wait_max = config->stream_wait_size;
        http2_query_buffer_max = config->http_query_buffer_size;

diff --git a/util/config_file.h b/util/config_file.h
index 29dd7162013097d35c15ea00c4ff93492e6fa38d..fbb09aa62bdce4f96e502489585e2a08fcef1bc6 100644 (file)
--- a/util/config_file.h
+++ b/util/config_file.h
@@ -341,6 +341,8 @@ struct config_file {
        int use_syslog;
        /** log timestamp in ascii UTC */
        int log_time_ascii;
+       /** log timestamp in ISO8601 format */
+       int log_time_iso;
        /** log queries with one line per query */
        int log_queries;
        /** log replies with one line per reply */

diff --git a/util/configlexer.lex b/util/configlexer.lex
index b4442e913ef87159b28989277d839e93740b07d2..dbf2910de89bf9fe73107539269bb22202502281 100644 (file)
--- a/util/configlexer.lex
+++ b/util/configlexer.lex
@@ -431,6 +431,7 @@ permit-small-holddown{COLON}        { YDVAR(1, VAR_PERMIT_SMALL_HOLDDOWN) }
 use-syslog{COLON}              { YDVAR(1, VAR_USE_SYSLOG) }
 log-identity{COLON}            { YDVAR(1, VAR_LOG_IDENTITY) }
 log-time-ascii{COLON}          { YDVAR(1, VAR_LOG_TIME_ASCII) }
+log-time-iso{COLON}            { YDVAR(1, VAR_LOG_TIME_ISO) }
 log-queries{COLON}             { YDVAR(1, VAR_LOG_QUERIES) }
 log-replies{COLON}             { YDVAR(1, VAR_LOG_REPLIES) }
 log-tag-queryreply{COLON}      { YDVAR(1, VAR_LOG_TAG_QUERYREPLY) }

diff --git a/util/configparser.y b/util/configparser.y
index dfc0c58af9751c63956c9f91fa9e5ad39c09fb70..2ca16f81c454d3717972fb3654edb5faae98f8b7 100644 (file)
--- a/util/configparser.y
+++ b/util/configparser.y
@@ -207,7 +207,7 @@ extern struct config_parser_state* cfg_parser;
 %token VAR_HARDEN_UNKNOWN_ADDITIONAL VAR_DISABLE_EDNS_DO VAR_CACHEDB_NO_STORE
 %token VAR_LOG_DESTADDR VAR_CACHEDB_CHECK_WHEN_SERVE_EXPIRED
 %token VAR_COOKIE_SECRET_FILE VAR_ITER_SCRUB_NS VAR_ITER_SCRUB_CNAME
-%token VAR_MAX_GLOBAL_QUOTA VAR_HARDEN_UNVERIFIED_GLUE
+%token VAR_MAX_GLOBAL_QUOTA VAR_HARDEN_UNVERIFIED_GLUE VAR_LOG_TIME_ISO
 
 %%
 toplevelvars: /* empty */ | toplevelvars toplevelvar ;
@@ -347,7 +347,7 @@ content_server: server_num_threads | server_verbosity | server_port |
        server_harden_unknown_additional | server_disable_edns_do |
        server_log_destaddr | server_cookie_secret_file |
        server_iter_scrub_ns | server_iter_scrub_cname | server_max_global_quota |
-       server_harden_unverified_glue
+       server_harden_unverified_glue | server_log_time_iso
        ;
 stub_clause: stubstart contents_stub
        {
@@ -1250,6 +1250,15 @@ server_log_time_ascii: VAR_LOG_TIME_ASCII STRING_ARG
                free($2);
        }
        ;
+server_log_time_iso: VAR_LOG_TIME_ISO STRING_ARG
+       {
+               OUTYY(("P(server_log_time_iso:%s)\n", $2));
+               if(strcmp($2, "yes") != 0 && strcmp($2, "no") != 0)
+                       yyerror("expected yes or no.");
+               else cfg_parser->cfg->log_time_iso = (strcmp($2, "yes")==0);
+               free($2);
+       }
+       ;
 server_log_queries: VAR_LOG_QUERIES STRING_ARG
        {
                OUTYY(("P(server_log_queries:%s)\n", $2));

diff --git a/util/log.c b/util/log.c
index a15ee920c0fb11330d25ae6f368dfb085c51ab25..a44758728b061287eaeb4b4a2ba5b82e373aba38 100644 (file)
--- a/util/log.c
+++ b/util/log.c
@@ -45,6 +45,7 @@
 #ifdef HAVE_TIME_H
 #include <time.h>
 #endif
+#include <sys/time.h>
 #ifdef HAVE_SYSLOG_H
 #  include <syslog.h>
 #else
@@ -81,6 +82,8 @@ static int logging_to_syslog = 0;
 #endif /* HAVE_SYSLOG_H */
 /** print time in UTC or in secondsfrom1970 */
 static int log_time_asc = 0;
+/** print time in iso format */
+static int log_time_iso = 0;
 
 void
 log_init(const char* filename, int use_syslog, const char* chrootdir)
@@ -205,6 +208,11 @@ void log_set_time_asc(int use_asc)
        log_time_asc = use_asc;
 }
 
+void log_set_time_iso(int use_iso)
+{
+       log_time_iso = use_iso;
+}
+
 void* log_get_lock(void)
 {
        if(!key_created)
@@ -269,6 +277,34 @@ log_vmsg(int pri, const char* type,
                lock_basic_unlock(&log_lock);
                return;
        }
+#if defined(HAVE_STRFTIME) && defined(HAVE_LOCALTIME_R)
+       if(log_time_iso && log_time_asc) {
+               char tzbuf[16];
+               struct timeval tv;
+               struct tm tm, *tm_p;
+               if(gettimeofday(&tv, NULL) < 0)
+                       memset(&tv, 0, sizeof(tv));
+               now = (time_t)tv.tv_sec;
+               tm_p = localtime_r(&now, &tm);
+               strftime(tmbuf, sizeof(tmbuf), "%Y-%m-%dT%H:%M:%S", tm_p);
+               if(strftime(tzbuf, sizeof(tzbuf), "%z", tm_p) == 5) {
+                       /* put ':' in "+hh:mm" */
+                       tzbuf[5] = tzbuf[4];
+                       tzbuf[4] = tzbuf[3];
+                       tzbuf[3] = ':';
+                       tzbuf[6] = 0;
+               }
+               fprintf(logfile, "%s.%3.3d%s %s[%d:%x] %s: %s\n",
+                       tmbuf, (int)tv.tv_usec/1000, tzbuf,
+                       ident, (int)getpid(), tid?*tid:0, type, message);
+#ifdef UB_ON_WINDOWS
+               /* line buffering does not work on windows */
+               fflush(logfile);
+#endif
+               lock_basic_unlock(&log_lock);
+               return;
+       }
+#endif /* HAVE_STRFTIME && HAVE_LOCALTIME_R */
        now = (time_t)time(NULL);
 #if defined(HAVE_STRFTIME) && defined(HAVE_LOCALTIME_R) 
        if(log_time_asc && strftime(tmbuf, sizeof(tmbuf), "%b %d %H:%M:%S",

diff --git a/util/log.h b/util/log.h
index 29a1ba38009fc34ccbebba1bf76a22e56e301683..e8b03c45ad503f9847ae57a0bd3a241063b0c750 100644 (file)
--- a/util/log.h
+++ b/util/log.h
@@ -138,6 +138,12 @@ void log_ident_set_or_default(const char* identity);
  */
 void log_set_time_asc(int use_asc);
 
+/**
+ * Set if the time value is printed in ISO8601 format.
+ * @param use_iso: if true, ascii timestamps are formatted in iso format.
+ */
+void log_set_time_iso(int use_iso);
+
 /** get log lock */
 void* log_get_lock(void);