Skip to content

Commit

Permalink
logs-show: adjust source timestamp with header timestamp
Browse files Browse the repository at this point in the history 
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.
  • Loading branch information
@yuwata
yuwata committed May 1, 2024
1 parent 0bdeed6 commit 15cffe8
Show file tree
Hide file tree
Showing 2 changed files with 80 additions and 43 deletions.
1 change: 1 addition & 0 deletions src/basic/time-util.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down
122 changes: 79 additions & 43 deletions src/shared/logs-show.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -445,37 +445,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 (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 (!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;
if (source_realtime && safe_atou64(source_realtime, &t) >= 0 && VALID_REALTIME(t))
source_ts.realtime = t;

if (source_monotonic && safe_atou64(source_monotonic, &t) >= 0 && VALID_MONOTONIC(t))
source_ts.monotonic = t;

(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(
Expand All @@ -486,8 +524,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;
Expand Down Expand Up @@ -552,8 +590,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);

Expand All @@ -565,10 +601,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;
Expand Down Expand Up @@ -689,17 +729,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;
Expand All @@ -710,8 +748,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));
Expand All @@ -724,7 +761,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);
Expand All @@ -749,32 +786,31 @@ 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);
assert(j);

(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;
}
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 : "",
Expand Down

0 comments on commit 15cffe8

Please sign in to comment.