diff --git a/doc/Changelog b/doc/Changelog index 9cf000016..9172b2199 100644 --- 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 e5bb5029f..2d16ee75f 100644 --- 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 d9c7f249a..bc48db478 100644 --- 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 +Log time in ISO8601 format, if \fBlog\-time\-ascii:\fR yes is also set. +Default is no. +.TP .B log\-queries: \fI 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 3898a8b0a..2eb81fcee 100644 --- 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 29dd71620..fbb09aa62 100644 --- 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 b4442e913..dbf2910de 100644 --- 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 dfc0c58af..2ca16f81c 100644 --- 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 a15ee920c..a44758728 100644 --- a/util/log.c +++ b/util/log.c @@ -45,6 +45,7 @@ #ifdef HAVE_TIME_H #include #endif +#include #ifdef HAVE_SYSLOG_H # include #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 29a1ba380..e8b03c45a 100644 --- 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);