mir/bind
2
0
Fork 0
mirror of https://gitlab.isc.org/isc-projects/bind9 synced 2025-08-29 13:38:26 +00:00
Code Issues Releases Wiki Activity

new: usr: Support ISO timestamps with timezone information

Browse Source 
The configuration option `print-time` can now be set to `iso8601-tzinfo` in order to use the ISO 8601 timestamp with timezone information when logging. This is used as a default for `named -g`.

Closes #4963

Merge branch '4963-provide-timezone-information-in-log-timestamps' into 'main'

See merge request isc-projects/bind9!9563
This commit is contained in:
Alessio Podda 2024-10-02 08:16:17 +00:00
commit e618cdddf8
19 changed files with 98 additions and 112 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
bin/named/include/named/globals.h
View File

@ -111,6 +111,7 @@ EXTERN const char *named_g_chrootdir INIT(NULL);
EXTERN bool named_g_foreground INIT(false);
EXTERN bool named_g_logstderr INIT(false);
EXTERN bool named_g_nosyslog INIT(false);
EXTERN unsigned int named_g_logflags INIT(0);
EXTERN const char *named_g_logfile INIT(NULL);
EXTERN const char *named_g_defaultsessionkeyfile INIT(NAMED_LOCALSTATEDIR

20
bin/named/log.c
View File

@ -79,6 +79,16 @@ named_log_setdefaultchannels(isc_logconfig_t *lcfg) {
isc_log_createchannel(lcfg, "default_debug", ISC_LOG_TOFILE,
ISC_LOG_DYNAMIC, &destination,
ISC_LOG_PRINTTIME | ISC_LOG_DEBUGONLY);
} else if (named_g_logstderr && (named_g_logflags != 0)) {
/*
* If the option -g is given, but we also requested iso
* timestamps, we'll still need to override the "default_debug"
* logger with a new one.
*/
isc_log_createchannel(lcfg, "default_debug", ISC_LOG_TOFILEDESC,
ISC_LOG_DYNAMIC,
ISC_LOGDESTINATION_STDERR,
ISC_LOG_PRINTTIME | named_g_logflags);
}
if (named_g_logfile != NULL) {
@ -118,6 +128,16 @@ named_log_setsafechannels(isc_logconfig_t *lcfg) {
* discarded a bit faster.
*/
isc_log_setdebuglevel(0);
} else if (named_g_logstderr && (named_g_logflags != 0)) {
/*
* If the option -g is given, but we also requested iso
* timestamps, we'll still need to override the "default_debug"
* logger with a new one.
*/
isc_log_createchannel(lcfg, "default_debug", ISC_LOG_TOFILEDESC,
ISC_LOG_DYNAMIC,
ISC_LOGDESTINATION_STDERR,
ISC_LOG_PRINTTIME | named_g_logflags);
} else {
isc_log_setdebuglevel(named_g_debuglevel);
}

2
bin/named/logconf.c
View File

@ -239,6 +239,8 @@ channel_fromconf(const cfg_obj_t *channel, isc_logconfig_t *logconfig) {
flags |= ISC_LOG_ISO8601;
} else if (strcasecmp(s, "iso8601-utc") == 0) {
flags |= ISC_LOG_ISO8601 | ISC_LOG_UTC;
} else if (strcasecmp(s, "iso8601-tzinfo") == 0) {
flags |= ISC_LOG_ISO8601 | ISC_LOG_TZINFO;
}
}
}

2
bin/named/main.c
View File

@ -889,6 +889,8 @@ parse_command_line(int argc, char *argv[]) {
case 'g':
named_g_foreground = true;
named_g_logstderr = true;
named_g_logflags = ISC_LOG_PRINTTIME | ISC_LOG_ISO8601 |
ISC_LOG_TZINFO;
break;
case 'L':
named_g_logfile = isc_commandline_argument;

2
bin/tests/system/cacheclean/tests.sh
View File

@ -101,7 +101,7 @@ digcomp --lc dig.out.ns2 knowngood.dig.out || status=1
n=$((n + 1))
echo_i "only one tcp socket was used ($n)"
tcpclients=$(awk '$3 == "client" && $5 ~ /10.53.0.7#[0-9]*:/ {print $5}' ns2/named.run | sort | uniq -c | wc -l)
tcpclients=$(awk '$2 == "client" && $4 ~ /10.53.0.7#[0-9]*:/ {print $4}' ns2/named.run | sort | uniq -c | wc -l)
test $tcpclients -eq 1 || {
status=1

4
bin/tests/system/checkconf/good-printtime.conf
View File

@ -32,4 +32,8 @@ logging {
file "five.out";
print-time iso8601-utc;
};
channel six {
file "six.out";
print-time iso8601-tzinfo;
};
};

4
bin/tests/system/kasp/tests.sh
View File

@ -2412,10 +2412,10 @@ _check_next_key_event() {
# Get the latest next key event.
if [ "${DYNAMIC}" = "yes" ]; then
_time=$(awk '{print $9}' <"keyevent.out.$ZONE.test$n" | tail -1)
_time=$(awk '{print $8}' <"keyevent.out.$ZONE.test$n" | tail -1)
else
# inline-signing zone adds "(signed)"
_time=$(awk '{print $10}' <"keyevent.out.$ZONE.test$n" | tail -1)
_time=$(awk '{print $9}' <"keyevent.out.$ZONE.test$n" | tail -1)
fi
# The next key event time must within threshold of the

2
bin/tests/system/mkeys/tests.sh
View File

@ -733,7 +733,7 @@ echo_i "check that trust-anchor-telemetry queries contain the correct key ($n)"
ret=0
# convert the hexadecimal key from the TAT query into decimal and
# compare against the known key.
tathex=$(grep "query '_ta-[0-9a-f][0-9a-f]*/NULL/IN' approved" ns1/named.run | awk '{print $6; exit 0}' | sed -e 's/(_ta-\([0-9a-f][0-9a-f]*\)):/\1/') || true
tathex=$(grep "query '_ta-[0-9a-f][0-9a-f]*/NULL/IN' approved" ns1/named.run | awk '{print $5; exit 0}' | sed -e 's/(_ta-\([0-9a-f][0-9a-f]*\)):/\1/') || true
tatkey=$($PERL -e 'printf("%d\n", hex(@ARGV[0]));' "$tathex")
realkey=$(rndccmd 10.53.0.2 secroots - | sed -n "s#.*${DEFAULT_ALGORITHM}/\([0-9][0-9]*\) ; .*managed.*#\1#p")
[ "$tatkey" -eq "$realkey" ] || ret=1

3
bin/tests/system/notify/tests.sh
View File

@ -65,7 +65,8 @@ test_end
test_start "checking startup notify rate limit"
awk '/x[0-9].*sending notify to/ {
split($2, a, ":");
split($1, ts, "T");
split(ts[2], a, ":");
this = a[1] * 3600 + a[2] * 60 + a[3];
if (lasta1 && lasta1 > a[1]) {
fix = 3600 * 24;

4
bin/tests/system/start.pl
View File

@ -373,9 +373,9 @@ sub count_running_lines {
# the shell *ought* to have created the file immediately, but this
# logic allows the creation to be delayed without issues
if (open(my $fh, "<", $runfile)) {
# the two non-whitespace blobs should be the date and time
# the whitespace blob should be an ISO timestamp
# but we don't care about them really, only that they are there
return scalar(grep /^\S+ \S+ running\R/, <$fh>);
return scalar(grep /^\S+[ T]\S+ running\R/, <$fh>);
} else {
return 0;
}

2
bin/tests/system/xfer/tests.sh
View File

@ -528,7 +528,7 @@ $RNDCCMD 10.53.0.7 refresh edns-expire 2>&1 | sed 's/^/ns7 /' | cat_i
sleep 10
# there may be multiple log entries so get the last one.
expire=$(awk '/edns-expire\/IN: got EDNS EXPIRE of/ { x=$9 } END { print x }' ns7/named.run)
expire=$(awk '/edns-expire\/IN: got EDNS EXPIRE of/ { x=$8 } END { print x }' ns7/named.run)
test ${expire:-0} -gt 0 -a ${expire:-0} -lt 1814400 || {
echo_i "failed (expire=${expire:-0})"
status=$((status + 1))

15
doc/arm/reference.rst
View File

@ -812,13 +812,16 @@ what messages to print.
:short: Specifies the time format for log messages.
:any:`print-time` can be set to ``yes``, ``no``, or a time format
specifier, which may be one of ``local``, ``iso8601``, or
``iso8601-utc``. If set to ``no``, the date and time are not
logged. If set to ``yes`` or ``local``, the date and time are logged in
a human-readable format, using the local time zone. If set to
``iso8601``, the local time is logged in ISO 8601 format. If set to
specifier, which may be one of ``local``, ``iso8601``, ``iso8601-utc``
or ``iso8601-tzinfo``. If set to ``no``, the date and time are
not logged. If set to ``yes`` or ``local``, the date and time are
logged in a human-readable format, using the local time zone. If
set to ``iso8601``, the local time is logged in ISO 8601 format,
but no timezone information is included in the timestamp. If set to
``iso8601-utc``, the date and time are logged in ISO 8601 format,
with time zone set to UTC. The default is ``no``.
with time zone set to UTC. If set to ``iso8601-tzinfo``, the local
time is logged in ISO 8601 format, with timezone information included
at the end of the timestamp. The default is ``no``.
:any:`print-time` may be specified for a :any:`syslog` channel, but it is
usually pointless since :any:`syslog` also logs the date and time.

2
doc/misc/options
View File

@ -57,7 +57,7 @@ logging {
null;
print-category <boolean>;
print-severity <boolean>;
print-time ( iso8601 | iso8601-utc | local | <boolean> );
print-time ( iso8601 | iso8601-utc | iso8601-tzinfo | local | <boolean> );
severity <log_severity>;
stderr;
syslog [ <syslog_facility> ];

1
lib/isc/include/isc/log.h
View File

@ -72,6 +72,7 @@ typedef struct isc_logconfig isc_logconfig_t; /*%< Log Configuration */
#define ISC_LOG_OPENERR 0x08000 /* internal */
#define ISC_LOG_ISO8601 0x10000 /* if PRINTTIME, use ISO8601 */
#define ISC_LOG_UTC 0x20000 /* if PRINTTIME, use UTC */
#define ISC_LOG_TZINFO 0x40000 /* if PRINTTIME, output TZ info */
/*@}*/
/*@{*/

18
lib/isc/include/isc/time.h
View File

@ -395,20 +395,6 @@ isc_time_parsehttptimestamp(char *input, isc_time_t *t);
*\li 'buf' and 't' are not NULL.
*/
void
isc_time_formatISO8601L(const isc_time_t *t, char *buf, unsigned int len);
/*%<
* Format the time 't' into the buffer 'buf' of length 'len',
* using the ISO8601 format: "yyyy-mm-ddThh:mm:ss"
* If the text does not fit in the buffer, the result is indeterminate,
* but is always guaranteed to be null terminated.
*
* Requires:
*\li 'len' > 0
*\li 'buf' points to an array of at least len chars
*
*/
void
isc_time_formatISO8601Lms(const isc_time_t *t, char *buf, unsigned int len);
/*%<
@ -424,10 +410,10 @@ isc_time_formatISO8601Lms(const isc_time_t *t, char *buf, unsigned int len);
*/
void
isc_time_formatISO8601Lus(const isc_time_t *t, char *buf, unsigned int len);
isc_time_formatISO8601TZms(const isc_time_t *t, char *buf, unsigned int len);
/*%<
* Format the time 't' into the buffer 'buf' of length 'len',
* using the ISO8601 format: "yyyy-mm-ddThh:mm:ss.ssssss"
* using the ISO8601 format: "yyyy-mm-ddThh:mm:ss.sss+hhmm"
* If the text does not fit in the buffer, the result is indeterminate,
* but is always guaranteed to be null terminated.
*

21
lib/isc/log.c
View File

@ -477,7 +477,7 @@ isc_log_createchannel(isc_logconfig_t *lcfg, const char *name,
isc_mem_t *mctx;
unsigned int permitted = ISC_LOG_PRINTALL | ISC_LOG_DEBUGONLY |
ISC_LOG_BUFFERED | ISC_LOG_ISO8601 |
ISC_LOG_UTC;
ISC_LOG_UTC | ISC_LOG_TZINFO;
REQUIRE(VALID_CONFIG(lcfg));
REQUIRE(name != NULL);
@ -486,6 +486,7 @@ isc_log_createchannel(isc_logconfig_t *lcfg, const char *name,
REQUIRE(destination != NULL || type == ISC_LOG_TONULL);
REQUIRE(level >= ISC_LOG_CRITICAL);
REQUIRE((flags & ~permitted) == 0);
REQUIRE(!(flags & ISC_LOG_UTC) || !(flags & ISC_LOG_TZINFO));
/* FIXME: find duplicate names? */
@ -1256,13 +1257,14 @@ isc_log_doit(isc_logcategory_t category, isc_logmodule_t module, int level,
const char *format, va_list args) {
int syslog_level;
const char *time_string;
char local_time[64];
char iso8601z_string[64];
char iso8601l_string[64];
char local_time[64] = { 0 };
char iso8601z_string[64] = { 0 };
char iso8601l_string[64] = { 0 };
char iso8601tz_string[64] = { 0 };
char level_string[24] = { 0 };
struct stat statbuf;
bool matched = false;
bool printtime, iso8601, utc, printtag, printcolon;
bool printtime, iso8601, utc, tzinfo, printtag, printcolon;
bool printcategory, printmodule, printlevel, buffered;
isc_logchannel_t *channel;
isc_logchannellist_t *category_channels;
@ -1280,10 +1282,6 @@ isc_log_doit(isc_logcategory_t category, isc_logmodule_t module, int level,
return;
}
local_time[0] = '\0';
iso8601l_string[0] = '\0';
iso8601z_string[0] = '\0';
rcu_read_lock();
LOCK(&isc__lctx->lock);
@ -1368,6 +1366,8 @@ isc_log_doit(isc_logcategory_t category, isc_logmodule_t module, int level,
sizeof(iso8601z_string));
isc_time_formatISO8601Lms(&isctime, iso8601l_string,
sizeof(iso8601l_string));
isc_time_formatISO8601TZms(&isctime, iso8601tz_string,
sizeof(iso8601tz_string));
}
if ((channel->flags & ISC_LOG_PRINTLEVEL) != 0 &&
@ -1396,6 +1396,7 @@ isc_log_doit(isc_logcategory_t category, isc_logmodule_t module, int level,
}
utc = ((channel->flags & ISC_LOG_UTC) != 0);
tzinfo = ((channel->flags & ISC_LOG_TZINFO) != 0);
iso8601 = ((channel->flags & ISC_LOG_ISO8601) != 0);
printtime = ((channel->flags & ISC_LOG_PRINTTIME) != 0);
printtag = ((channel->flags &
@ -1412,6 +1413,8 @@ isc_log_doit(isc_logcategory_t category, isc_logmodule_t module, int level,
if (iso8601) {
if (utc) {
time_string = iso8601z_string;
} else if (tzinfo) {
time_string = iso8601tz_string;
} else {
time_string = iso8601l_string;
}

40
lib/isc/time.c
View File

@ -382,22 +382,6 @@ isc_time_parsehttptimestamp(char *buf, isc_time_t *t) {
return (ISC_R_SUCCESS);
}
void
isc_time_formatISO8601L(const isc_time_t *t, char *buf, unsigned int len) {
time_t now;
unsigned int flen;
struct tm tm;
REQUIRE(t != NULL);
INSIST(t->nanoseconds < NS_PER_SEC);
REQUIRE(buf != NULL);
REQUIRE(len > 0);
now = (time_t)t->seconds;
flen = strftime(buf, len, "%Y-%m-%dT%H:%M:%S", localtime_r(&now, &tm));
INSIST(flen < len);
}
void
isc_time_formatISO8601Lms(const isc_time_t *t, char *buf, unsigned int len) {
time_t now;
@ -419,7 +403,9 @@ isc_time_formatISO8601Lms(const isc_time_t *t, char *buf, unsigned int len) {
}
void
isc_time_formatISO8601Lus(const isc_time_t *t, char *buf, unsigned int len) {
isc_time_formatISO8601TZms(const isc_time_t *t, char *buf, unsigned int len) {
char strftime_buf[64] = { 0 };
char ms_buf[8] = { 0 };
time_t now;
unsigned int flen;
struct tm tm;
@ -430,14 +416,20 @@ isc_time_formatISO8601Lus(const isc_time_t *t, char *buf, unsigned int len) {
REQUIRE(len > 0);
now = (time_t)t->seconds;
flen = strftime(buf, len, "%Y-%m-%dT%H:%M:%S", localtime_r(&now, &tm));
INSIST(flen < len);
if (flen > 0U && len - flen >= 6) {
snprintf(buf + flen, len - flen, ".%06u",
t->nanoseconds / NS_PER_US);
}
}
flen = strftime(strftime_buf, len, "%Y-%m-%dT%H:%M:%S.xxx%z",
localtime_r(&now, &tm));
snprintf(ms_buf, sizeof(ms_buf), ".%03u", t->nanoseconds / NS_PER_MS);
INSIST(flen < len);
size_t local_date_len = sizeof("yyyy-mm-ddThh:mm:ss") - 1ul;
size_t ms_date_len = local_date_len + 4;
memmove(buf, strftime_buf, local_date_len);
memmove(buf + local_date_len, ms_buf, 4);
memmove(buf + ms_date_len, strftime_buf + ms_date_len, 3);
buf[ms_date_len + 3] = ':';
memmove(buf + ms_date_len + 4, strftime_buf + ms_date_len + 3, 3);
}
void
isc_time_formatISO8601(const isc_time_t *t, char *buf, unsigned int len) {
time_t now;

4
lib/isccfg/namedconf.c
View File

@ -2631,8 +2631,8 @@ static cfg_type_t cfg_type_server = { "server", cfg_parse_netprefix_map,
* - There must exactly one of file/syslog/null/stderr
*/
static const char *printtime_enums[] = { "iso8601", "iso8601-utc", "local",
NULL };
static const char *printtime_enums[] = { "iso8601", "iso8601-utc",
"iso8601-tzinfo", "local", NULL };
static isc_result_t
parse_printtime(cfg_parser_t *pctx, const cfg_type_t *type, cfg_obj_t **ret) {
return (cfg_parse_enum_or_other(pctx, type, &cfg_type_boolean, ret));

63
tests/isc/time_test.c
View File

@ -256,9 +256,9 @@ ISC_RUN_TEST_IMPL(isc_time_formatISO8601us_test) {
assert_string_equal(buf, "2015-12-13T09:46:40.123456Z");
}
/* print local time in ISO8601 */
/* print local time in ISO8601 with milliseconds and timezone */
ISC_RUN_TEST_IMPL(isc_time_formatISO8601L_test) {
ISC_RUN_TEST_IMPL(isc_time_formatISO8601TZms_test) {
isc_time_t t;
char buf[64];
@ -267,28 +267,34 @@ ISC_RUN_TEST_IMPL(isc_time_formatISO8601L_test) {
setenv("TZ", "America/Los_Angeles", 1);
t = isc_time_now();
/* check formatting: yyyy-mm-ddThh:mm:ss */
/* check formatting: yyyy-mm-ddThh:mm:ss.sss */
memset(buf, 'X', sizeof(buf));
isc_time_formatISO8601L(&t, buf, sizeof(buf));
assert_int_equal(strlen(buf), 19);
buf[63] = '\0';
isc_time_formatISO8601TZms(&t, buf, sizeof(buf));
assert_int_equal(strlen(buf), strlen("yyyy-mm-ddThh:mm:ss.sss+hh:mm"));
assert_int_equal(buf[4], '-');
assert_int_equal(buf[7], '-');
assert_int_equal(buf[10], 'T');
assert_int_equal(buf[13], ':');
assert_int_equal(buf[16], ':');
assert_int_equal(buf[19], '.');
size_t plus_minus[2] = { '+', '-' };
assert_in_set(buf[23], plus_minus, sizeof(plus_minus));
assert_int_equal(buf[26], ':');
/* check time conversion correctness */
memset(buf, 'X', sizeof(buf));
isc_time_settoepoch(&t);
isc_time_formatISO8601L(&t, buf, sizeof(buf));
assert_string_equal(buf, "1969-12-31T16:00:00");
isc_time_formatISO8601Lms(&t, buf, sizeof(buf));
assert_string_equal(buf, "1969-12-31T16:00:00.000");
memset(buf, 'X', sizeof(buf));
isc_time_set(&t, 1450000000, 123000000);
isc_time_formatISO8601L(&t, buf, sizeof(buf));
assert_string_equal(buf, "2015-12-13T01:46:40");
isc_time_formatISO8601Lms(&t, buf, sizeof(buf));
assert_string_equal(buf, "2015-12-13T01:46:40.123");
}
/* print local time in ISO8601 with milliseconds */
ISC_RUN_TEST_IMPL(isc_time_formatISO8601Lms_test) {
@ -323,40 +329,6 @@ ISC_RUN_TEST_IMPL(isc_time_formatISO8601Lms_test) {
assert_string_equal(buf, "2015-12-13T01:46:40.123");
}
/* print local time in ISO8601 with microseconds */
ISC_RUN_TEST_IMPL(isc_time_formatISO8601Lus_test) {
isc_time_t t;
char buf[64];
UNUSED(state);
setenv("TZ", "America/Los_Angeles", 1);
t = isc_time_now_hires();
/* check formatting: yyyy-mm-ddThh:mm:ss.ssssss */
memset(buf, 'X', sizeof(buf));
isc_time_formatISO8601Lus(&t, buf, sizeof(buf));
assert_int_equal(strlen(buf), 26);
assert_int_equal(buf[4], '-');
assert_int_equal(buf[7], '-');
assert_int_equal(buf[10], 'T');
assert_int_equal(buf[13], ':');
assert_int_equal(buf[16], ':');
assert_int_equal(buf[19], '.');
/* check time conversion correctness */
memset(buf, 'X', sizeof(buf));
isc_time_settoepoch(&t);
isc_time_formatISO8601Lus(&t, buf, sizeof(buf));
assert_string_equal(buf, "1969-12-31T16:00:00.000000");
memset(buf, 'X', sizeof(buf));
isc_time_set(&t, 1450000000, 123456000);
isc_time_formatISO8601Lus(&t, buf, sizeof(buf));
assert_string_equal(buf, "2015-12-13T01:46:40.123456");
}
/* print UTC time as yyyymmddhhmmsssss */
ISC_RUN_TEST_IMPL(isc_time_formatshorttimestamp_test) {
@ -393,9 +365,8 @@ ISC_TEST_ENTRY(isc_time_parsehttptimestamp_test)
ISC_TEST_ENTRY(isc_time_formatISO8601_test)
ISC_TEST_ENTRY(isc_time_formatISO8601ms_test)
ISC_TEST_ENTRY(isc_time_formatISO8601us_test)
ISC_TEST_ENTRY(isc_time_formatISO8601L_test)
ISC_TEST_ENTRY(isc_time_formatISO8601Lms_test)
ISC_TEST_ENTRY(isc_time_formatISO8601Lus_test)
ISC_TEST_ENTRY(isc_time_formatISO8601TZms_test)
ISC_TEST_ENTRY(isc_time_formatshorttimestamp_test)
ISC_TEST_LIST_END