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

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

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

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
 

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

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;

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

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) }

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));

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",

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);