From affde1d7e79a634ee6053dbd4a57b3b51b74c170 Mon Sep 17 00:00:00 2001 From: Yu Watanabe Date: Wed, 1 May 2024 05:12:12 +0900 Subject: [PATCH] logs-show: adjust source timestamp with header timestamp Previously, _SOURCE_REALTIME_TIMESTAMP was only used for realtime timestamp, and _SOURCE_MONOTONIC_TIMESTAMP was for monotonic. This make these journal field used more aggressively. If we need realtime timestamp, but an entry has only _SOURCE_MONOTONIC_TIMESTAMP, then now realtime timestamp is calculated based on _SOURCE_MONOTONIC_TIMESTAMP and the header dual timestamp. Similary, monotonic timestamp is obtained from _SOURCE_REALTIME_TIMESTAMP and the header dual timestamp. This should change shown timestamps not so much in most cases, but may be improve the situation such as #32492. --- src/basic/time-util.h | 1 + src/shared/logs-show.c | 118 +++++++++++++++++++++++++++-------------- 2 files changed, 78 insertions(+), 41 deletions(-) diff --git a/src/basic/time-util.h b/src/basic/time-util.h index ebcdc41118..b28ab8242f 100644 --- a/src/basic/time-util.h +++ b/src/basic/time-util.h @@ -72,6 +72,7 @@ typedef enum TimestampStyle { #define TIME_T_MAX (time_t)((UINTMAX_C(1) << ((sizeof(time_t) << 3) - 1)) - 1) #define DUAL_TIMESTAMP_NULL ((dual_timestamp) {}) +#define DUAL_TIMESTAMP_INFINITY ((dual_timestamp) { USEC_INFINITY, USEC_INFINITY }) #define TRIPLE_TIMESTAMP_NULL ((triple_timestamp) {}) usec_t now(clockid_t clock); diff --git a/src/shared/logs-show.c b/src/shared/logs-show.c index 1d9466f7a1..d5b131a187 100644 --- a/src/shared/logs-show.c +++ b/src/shared/logs-show.c @@ -439,37 +439,75 @@ static int output_timestamp_realtime( return (int) strlen(buf); } +static void parse_display_realtime( + sd_journal *j, + const char *source_realtime, + const char *source_monotonic, + usec_t *ret) { + + usec_t t, s, u; + + assert(j); + assert(ret); + + /* First, try _SOURCE_REALTIME_TIMESTAMP. */ + if (source_realtime && safe_atou64(source_realtime, &t) >= 0 && VALID_REALTIME(t)) { + *ret = t; + return; + } + + /* Read realtime timestamp in the entry header. */ + if (sd_journal_get_realtime_usec(j, &t) < 0) { + *ret = USEC_INFINITY; + return; + } + + /* If _SOURCE_MONOTONIC_TIMESTAMP is provided, adjust the header timestamp. */ + if (source_monotonic && safe_atou64(source_monotonic, &s) >= 0 && VALID_MONOTONIC(s) && + sd_journal_get_monotonic_usec(j, &u, &(sd_id128_t) {}) >= 0) { + *ret = map_clock_usec_raw(t, u, s); + return; + } + + /* Otherwise, use the header timestamp as is. */ + *ret = t; +} + static void parse_display_timestamp( sd_journal *j, - const char *realtime, - const char *monotonic, + const char *source_realtime, + const char *source_monotonic, dual_timestamp *ret_display_ts, sd_id128_t *ret_boot_id) { - bool realtime_good = false, monotonic_good = false, boot_id_good = false; + dual_timestamp header_ts = DUAL_TIMESTAMP_INFINITY, source_ts = DUAL_TIMESTAMP_INFINITY; + sd_id128_t boot_id = SD_ID128_NULL; + usec_t t; assert(j); assert(ret_display_ts); assert(ret_boot_id); - if (realtime) - realtime_good = safe_atou64(realtime, &ret_display_ts->realtime) >= 0; - if (!realtime_good || !VALID_REALTIME(ret_display_ts->realtime)) - realtime_good = sd_journal_get_realtime_usec(j, &ret_display_ts->realtime) >= 0; - if (!realtime_good) - ret_display_ts->realtime = USEC_INFINITY; + if (source_realtime && safe_atou64(source_realtime, &t) >= 0 && VALID_REALTIME(t)) + source_ts.realtime = t; - if (monotonic) - monotonic_good = safe_atou64(monotonic, &ret_display_ts->monotonic) >= 0; - if (!monotonic_good || !VALID_MONOTONIC(ret_display_ts->monotonic)) - monotonic_good = boot_id_good = sd_journal_get_monotonic_usec(j, &ret_display_ts->monotonic, ret_boot_id) >= 0; - if (!monotonic_good) - ret_display_ts->monotonic = USEC_INFINITY; + if (source_monotonic && safe_atou64(source_monotonic, &t) >= 0 && VALID_MONOTONIC(t)) + source_ts.monotonic = t; - if (!boot_id_good) - boot_id_good = sd_journal_get_monotonic_usec(j, NULL, ret_boot_id) >= 0; - if (!boot_id_good) - *ret_boot_id = SD_ID128_NULL; + (void) sd_journal_get_realtime_usec(j, &header_ts.realtime); + (void) sd_journal_get_monotonic_usec(j, &header_ts.monotonic, &boot_id); + + /* Adjust timestamp if possible. */ + if (header_ts.realtime != USEC_INFINITY && header_ts.monotonic != USEC_INFINITY) { + if (source_ts.realtime == USEC_INFINITY && source_ts.monotonic != USEC_INFINITY) + source_ts.realtime = map_clock_usec_raw(header_ts.realtime, header_ts.monotonic, source_ts.monotonic); + else if (source_ts.realtime != USEC_INFINITY && source_ts.monotonic == USEC_INFINITY) + source_ts.monotonic = map_clock_usec_raw(header_ts.monotonic, header_ts.realtime, source_ts.realtime); + } + + ret_display_ts->realtime = source_ts.realtime != USEC_INFINITY ? source_ts.realtime : header_ts.realtime; + ret_display_ts->monotonic = source_ts.monotonic != USEC_INFINITY ? source_ts.monotonic : header_ts.monotonic; + *ret_boot_id = boot_id; } static int output_short( @@ -480,8 +518,8 @@ static int output_short( OutputFlags flags, const Set *output_fields, const size_t highlight[2], - dual_timestamp *previous_display_ts, /* in and out */ - sd_id128_t *previous_boot_id) { /* in and out */ + dual_timestamp *previous_display_ts, /* in and out, used only when mode is OUTPUT_SHORT_MONOTONIC, OUTPUT_SHORT_DELTA. */ + sd_id128_t *previous_boot_id) { /* in and out, used only when mode is OUTPUT_SHORT_MONOTONIC, OUTPUT_SHORT_DELTA. */ int r; const void *data; @@ -546,8 +584,6 @@ static int output_short( if (identifier && set_contains(j->exclude_syslog_identifiers, identifier)) return 0; - parse_display_timestamp(j, realtime, monotonic, &display_ts, &boot_id); - if (!(flags & OUTPUT_SHOW_ALL)) strip_tab_ansi(&message, &message_len, highlight_shifted); @@ -559,10 +595,14 @@ static int output_short( audit = streq_ptr(transport, "audit"); - if (IN_SET(mode, OUTPUT_SHORT_MONOTONIC, OUTPUT_SHORT_DELTA)) + if (IN_SET(mode, OUTPUT_SHORT_MONOTONIC, OUTPUT_SHORT_DELTA)) { + parse_display_timestamp(j, realtime, monotonic, &display_ts, &boot_id); r = output_timestamp_monotonic(f, mode, &display_ts, &boot_id, previous_display_ts, previous_boot_id); - else - r = output_timestamp_realtime(f, j, mode, flags, display_ts.realtime); + } else { + usec_t usec; + parse_display_realtime(j, realtime, monotonic, &usec); + r = output_timestamp_realtime(f, j, mode, flags, usec); + } if (r < 0) return r; n += r; @@ -683,17 +723,15 @@ static int output_short( if (flags & OUTPUT_CATALOG) (void) print_catalog(f, j); - *previous_display_ts = display_ts; - *previous_boot_id = boot_id; + if (IN_SET(mode, OUTPUT_SHORT_MONOTONIC, OUTPUT_SHORT_DELTA)) { + *previous_display_ts = display_ts; + *previous_boot_id = boot_id; + } return ellipsized; } -static int get_display_timestamp( - sd_journal *j, - dual_timestamp *ret_display_ts, - sd_id128_t *ret_boot_id) { - +static int get_display_realtime(sd_journal *j, usec_t *ret) { const void *data; _cleanup_free_ char *realtime = NULL, *monotonic = NULL; size_t length; @@ -704,8 +742,7 @@ static int get_display_timestamp( int r; assert(j); - assert(ret_display_ts); - assert(ret_boot_id); + assert(ret); JOURNAL_FOREACH_DATA_RETVAL(j, data, length, r) { r = parse_fieldv(data, length, message_fields, ELEMENTSOF(message_fields)); @@ -718,7 +755,7 @@ static int get_display_timestamp( if (r < 0) return r; - (void) parse_display_timestamp(j, realtime, monotonic, ret_display_ts, ret_boot_id); + (void) parse_display_realtime(j, realtime, monotonic, ret); /* Restart all data before */ sd_journal_restart_data(j); @@ -743,9 +780,8 @@ static int output_verbose( size_t length; _cleanup_free_ char *cursor = NULL; char buf[FORMAT_TIMESTAMP_MAX + 7]; - dual_timestamp display_ts; - sd_id128_t boot_id; const char *timestamp; + usec_t usec; int r; assert(f); @@ -753,7 +789,7 @@ static int output_verbose( (void) sd_journal_set_data_threshold(j, 0); - r = get_display_timestamp(j, &display_ts, &boot_id); + r = get_display_realtime(j, &usec); if (IN_SET(r, -EBADMSG, -EADDRNOTAVAIL)) { log_debug_errno(r, "Skipping message we can't read: %m"); return 0; @@ -761,14 +797,14 @@ static int output_verbose( if (r < 0) return log_error_errno(r, "Failed to get journal fields: %m"); - if (!VALID_REALTIME(display_ts.realtime)) + if (!VALID_REALTIME(usec)) return log_error_errno(SYNTHETIC_ERRNO(EINVAL), "No valid realtime timestamp available"); r = sd_journal_get_cursor(j, &cursor); if (r < 0) return log_error_errno(r, "Failed to get cursor: %m"); - timestamp = format_timestamp_style(buf, sizeof buf, display_ts.realtime, + timestamp = format_timestamp_style(buf, sizeof buf, usec, flags & OUTPUT_UTC ? TIMESTAMP_US_UTC : TIMESTAMP_US); fprintf(f, "%s%s%s %s[%s]%s\n", timestamp && (flags & OUTPUT_COLOR) ? ANSI_UNDERLINE : "",