The dmesg logs have timestamps in seconds since boot format which can be converted to other formats. However, there is no option to include both the original timestamp as present in the buffer along with the converted timestamp in the specified format. This change updates the --time-format option in dmesg to enable the user to specify it multiple times with different formats with each input providing a timestamp format among the currently supported choices. This enables seeing the dmesg logs in both seconds since boot and human readable format simultaneously in each row of the log output. The sequence of timestamp format is fixed and independent of the order in which the user provides the desired formats. Signed-off-by: Rishabh Thukral <rthukral@xxxxxxxxxx> --- sys-utils/dmesg.1.adoc | 4 +- sys-utils/dmesg.c | 228 ++++++++++++++++++++++++----------------- 2 files changed, 138 insertions(+), 94 deletions(-) diff --git a/sys-utils/dmesg.1.adoc b/sys-utils/dmesg.1.adoc index 6f4941ede..a968fe9f9 100644 --- a/sys-utils/dmesg.1.adoc +++ b/sys-utils/dmesg.1.adoc @@ -133,9 +133,11 @@ Display record until the specified time. Supported is the subsecond granularity. Do not print kernel's timestamps. *--time-format* _format_:: -Print timestamps using the given _format_, which can be *ctime*, *reltime*, *delta* or *iso*. The first three formats are aliases of the time-format-specific options. The *iso* format is a *dmesg* implementation of the ISO-8601 timestamp format. The purpose of this format is to make the comparing of timestamps between two systems, and any other parsing, easy. The definition of the *iso* timestamp is: YYYY-MM-DD<T>HH:MM:SS,<microseconds><-+><timezone offset from UTC>. +Print timestamps using the given _format_, which can be *ctime*, *reltime*, *delta*, *iso* or *raw*. The first three formats are aliases of the time-format-specific options. The *raw* format uses the default timestamp format showing seconds since boot. The *iso* format is a *dmesg* implementation of the ISO-8601 timestamp format. The purpose of this format is to make the comparing of timestamps between two systems, and any other parsing, easy. The definition of the *iso* timestamp is: YYYY-MM-DD<T>HH:MM:SS,<microseconds><-+><timezone offset from UTC>. + The *iso* format has the same issue as *ctime*: the time may be inaccurate when a system is suspended and resumed. ++ +*--time-format* may be used multiple times with different values for _format_ to output each specified format in the following sequence *ctime, delta, reltime, raw, iso* *-u*, *--userspace*:: Print userspace messages. diff --git a/sys-utils/dmesg.c b/sys-utils/dmesg.c index 79e1c1690..9c8fea6c2 100644 --- a/sys-utils/dmesg.c +++ b/sys-utils/dmesg.c @@ -161,7 +161,13 @@ enum { DMESG_TIMEFTM_TIME_DELTA, /* [time <delta>] */ DMESG_TIMEFTM_ISO8601 /* 2013-06-13T22:11:00,123456+0100 */ }; -#define is_timefmt(c, f) ((c)->time_fmt == (DMESG_TIMEFTM_ ##f)) +#define TOTAL_DMESG_TIMESTAMP_FORMATS_SUPPORTED 8 + +enum { + TIMESTAMP_FMT_UNSET = 0, + TIMESTAMP_FMT_SET = 1, + TIMESTAMP_FMT_INIT_SET = 2 +}; struct dmesg_control { /* bit arrays -- see include/bitops.h */ @@ -199,7 +205,7 @@ struct dmesg_control { char *filename; char *mmap_buff; size_t pagesize; - unsigned int time_fmt; /* time format */ + unsigned int time_fmts[TOTAL_DMESG_TIMESTAMP_FORMATS_SUPPORTED]; /* time format */ struct ul_jsonwrt jfmt; /* -J formatting */ @@ -316,7 +322,7 @@ static void __attribute__((__noreturn__)) usage(void) fputs(_(" -T, --ctime show human-readable timestamp (may be inaccurate!)\n"), out); fputs(_(" -t, --notime don't show any timestamp with messages\n"), out); fputs(_(" --time-format <format> show timestamp using the given format:\n" - " [delta|reltime|ctime|notime|iso]\n" + " [delta|reltime|ctime|notime|iso|raw]\n" "Suspending/resume will make ctime and iso timestamps inaccurate.\n"), out); fputs(_(" --since <time> display the lines since the specified time\n"), out); fputs(_(" --until <time> display the lines until the specified time\n"), out); @@ -764,7 +770,7 @@ static int get_next_syslog_record(struct dmesg_control *ctl, if (*begin == '[' && (*(begin + 1) == ' ' || isdigit(*(begin + 1)))) { - if (!is_timefmt(ctl, NONE)) + if (ctl->time_fmts[DMESG_TIMEFTM_NONE] == TIMESTAMP_FMT_UNSET) begin = parse_syslog_timestamp(begin + 1, &rec->tv); else begin = skip_item(begin, end, "]"); @@ -939,10 +945,21 @@ static void print_record(struct dmesg_control *ctl, char buf[128]; char fpbuf[32] = "\0"; char tsbuf[64] = "\0"; + char full_tsbuf[64*TOTAL_DMESG_TIMESTAMP_FORMATS_SUPPORTED] = "\0"; size_t mesg_size = rec->mesg_size; int timebreak = 0; char *mesg_copy = NULL; const char *line = NULL; + unsigned int ts_format_sequence[TOTAL_DMESG_TIMESTAMP_FORMATS_SUPPORTED] = { + DMESG_TIMEFTM_NONE, + DMESG_TIMEFTM_CTIME, DMESG_TIMEFTM_CTIME_DELTA, + DMESG_TIMEFTM_DELTA, + DMESG_TIMEFTM_RELTIME, + DMESG_TIMEFTM_TIME, DMESG_TIMEFTM_TIME_DELTA, + DMESG_TIMEFTM_ISO8601 + }; + int format_iterator = 0; + double delta = record_count_delta(ctl, rec); if (!accept_record(ctl, rec)) return; @@ -967,7 +984,7 @@ static void print_record(struct dmesg_control *ctl, * backward compatibility with syslog(2) buffers only */ if (ctl->raw) { - ctl->indent = snprintf(tsbuf, sizeof(tsbuf), + ctl->indent = snprintf(full_tsbuf, sizeof(full_tsbuf), "<%d>[%5ld.%06ld] ", LOG_RAW_FAC_PRI(rec->facility, rec->level), (long) rec->tv.tv_sec, @@ -982,64 +999,73 @@ static void print_record(struct dmesg_control *ctl, level_names[rec->level].name); /* Store the timestamp in a buffer */ - switch (ctl->time_fmt) { - double delta; - struct tm cur; - case DMESG_TIMEFTM_NONE: - ctl->indent = 0; - break; - case DMESG_TIMEFTM_CTIME: - ctl->indent = snprintf(tsbuf, sizeof(tsbuf), "[%s] ", - record_ctime(ctl, rec, buf, sizeof(buf))); - break; - case DMESG_TIMEFTM_CTIME_DELTA: - ctl->indent = snprintf(tsbuf, sizeof(tsbuf), "[%s <%12.06f>] ", - record_ctime(ctl, rec, buf, sizeof(buf)), - record_count_delta(ctl, rec)); - break; - case DMESG_TIMEFTM_DELTA: - ctl->indent = snprintf(tsbuf, sizeof(tsbuf), "[<%12.06f>] ", - record_count_delta(ctl, rec)); - break; - case DMESG_TIMEFTM_RELTIME: - record_localtime(ctl, rec, &cur); - delta = record_count_delta(ctl, rec); - if (cur.tm_min != ctl->lasttm.tm_min || - cur.tm_hour != ctl->lasttm.tm_hour || - cur.tm_yday != ctl->lasttm.tm_yday) { - timebreak = 1; + for (format_iterator = 0; format_iterator < TOTAL_DMESG_TIMESTAMP_FORMATS_SUPPORTED; + format_iterator++) { + if (ctl->time_fmts[ts_format_sequence[format_iterator]] == TIMESTAMP_FMT_UNSET) + continue; + + switch (ts_format_sequence[format_iterator]) { + struct tm cur; + case DMESG_TIMEFTM_NONE: + ctl->indent = 0; + break; + case DMESG_TIMEFTM_CTIME: ctl->indent = snprintf(tsbuf, sizeof(tsbuf), "[%s] ", - short_ctime(&cur, buf, - sizeof(buf))); - } else { - if (delta < 10) - ctl->indent = snprintf(tsbuf, sizeof(tsbuf), - "[ %+8.06f] ", delta); - else - ctl->indent = snprintf(tsbuf, sizeof(tsbuf), - "[ %+9.06f] ", delta); + record_ctime(ctl, rec, buf, sizeof(buf))); + break; + case DMESG_TIMEFTM_CTIME_DELTA: + ctl->indent = snprintf(tsbuf, sizeof(tsbuf), "[%s <%12.06f>] ", + record_ctime(ctl, rec, buf, sizeof(buf)), + delta); + break; + case DMESG_TIMEFTM_DELTA: + ctl->indent = snprintf(tsbuf, sizeof(tsbuf), "[<%12.06f>] ", + delta); + break; + case DMESG_TIMEFTM_RELTIME: + record_localtime(ctl, rec, &cur); + if (cur.tm_min != ctl->lasttm.tm_min || + cur.tm_hour != ctl->lasttm.tm_hour || + cur.tm_yday != ctl->lasttm.tm_yday) { + timebreak = 1; + ctl->indent = snprintf(tsbuf, sizeof(tsbuf), "[%s] ", + short_ctime(&cur, buf, + sizeof(buf))); + } else { + if (delta < 10) + ctl->indent = snprintf(tsbuf, sizeof(tsbuf), + "[ %+8.06f] ", delta); + else + ctl->indent = snprintf(tsbuf, sizeof(tsbuf), + "[ %+9.06f] ", delta); + } + ctl->lasttm = cur; + break; + case DMESG_TIMEFTM_TIME: + ctl->indent = snprintf(tsbuf, sizeof(tsbuf), + ctl->json ? "%5ld.%06ld" : "[%5ld.%06ld] ", + (long)rec->tv.tv_sec, + (long)rec->tv.tv_usec); + break; + case DMESG_TIMEFTM_TIME_DELTA: + ctl->indent = snprintf(tsbuf, sizeof(tsbuf), "[%5ld.%06ld <%12.06f>] ", + (long)rec->tv.tv_sec, + (long)rec->tv.tv_usec, + delta); + break; + case DMESG_TIMEFTM_ISO8601: + ctl->indent = snprintf(tsbuf, sizeof(tsbuf), "%s ", + iso_8601_time(ctl, rec, buf, + sizeof(buf))); + break; + default: + abort(); } - ctl->lasttm = cur; - break; - case DMESG_TIMEFTM_TIME: - ctl->indent = snprintf(tsbuf, sizeof(tsbuf), - ctl->json ? "%5ld.%06ld" : "[%5ld.%06ld] ", - (long)rec->tv.tv_sec, - (long)rec->tv.tv_usec); - break; - case DMESG_TIMEFTM_TIME_DELTA: - ctl->indent = snprintf(tsbuf, sizeof(tsbuf), "[%5ld.%06ld <%12.06f>] ", - (long)rec->tv.tv_sec, - (long)rec->tv.tv_usec, - record_count_delta(ctl, rec)); - break; - case DMESG_TIMEFTM_ISO8601: - ctl->indent = snprintf(tsbuf, sizeof(tsbuf), "%s ", - iso_8601_time(ctl, rec, buf, - sizeof(buf))); - break; - default: - abort(); + + if (*tsbuf) + strcat(full_tsbuf, tsbuf); + else if (ts_format_sequence[format_iterator] == DMESG_TIMEFTM_NONE) + break; } ctl->indent += strlen(fpbuf); @@ -1057,23 +1083,23 @@ full_output: } /* Output the timestamp buffer */ - if (*tsbuf) { + if (*full_tsbuf) { /* Colorize the timestamp */ if (ctl->color) dmesg_enable_color(timebreak ? DMESG_COLOR_TIMEBREAK : DMESG_COLOR_TIME); - if (ctl->time_fmt != DMESG_TIMEFTM_RELTIME) { + if (ctl->time_fmts[DMESG_TIMEFTM_RELTIME] == TIMESTAMP_FMT_UNSET) { if (ctl->json) - ul_jsonwrt_value_raw(&ctl->jfmt, "time", tsbuf); + ul_jsonwrt_value_raw(&ctl->jfmt, "time", full_tsbuf); else - fputs(tsbuf, stdout); + fputs(full_tsbuf, stdout); } else { /* * For relative timestamping, the first line's * timestamp is the offset and all other lines will * report an offset of 0.000000. */ - fputs(!line ? tsbuf : "[ +0.000000] ", stdout); + fputs(!line ? full_tsbuf : "[ +0.000000] ", stdout); } if (ctl->color) color_disable(); @@ -1254,7 +1280,7 @@ static int parse_kmsg_record(struct dmesg_control *ctl, goto mesg; /* C) timestamp */ - if (is_timefmt(ctl, NONE)) + if (ctl->time_fmts[DMESG_TIMEFTM_NONE] == TIMESTAMP_FMT_SET) p = skip_item(p, end, ",;"); else p = parse_kmsg_timestamp(p, &rec->tv); @@ -1346,6 +1372,8 @@ static int which_time_format(const char *s) return DMESG_TIMEFTM_RELTIME; if (!strcmp(s, "iso")) return DMESG_TIMEFTM_ISO8601; + if (!strcmp(s, "raw")) + return DMESG_TIMEFTM_TIME; errx(EXIT_FAILURE, _("unknown time format: %s"), s); } @@ -1388,9 +1416,11 @@ int main(int argc, char *argv[]) .action = SYSLOG_ACTION_READ_ALL, .method = DMESG_METHOD_KMSG, .kmsg = -1, - .time_fmt = DMESG_TIMEFTM_TIME, .indent = 0, }; + memset(ctl.time_fmts, 0, + TOTAL_DMESG_TIMESTAMP_FORMATS_SUPPORTED * sizeof(*(ctl.time_fmts))); + ctl.time_fmts[DMESG_TIMEFTM_TIME] = TIMESTAMP_FMT_INIT_SET; int colormode = UL_COLORMODE_UNDEF; enum { OPT_TIME_FORMAT = CHAR_MAX + 1, @@ -1475,7 +1505,9 @@ int main(int argc, char *argv[]) ctl.action = SYSLOG_ACTION_CONSOLE_ON; break; case 'e': - ctl.time_fmt = DMESG_TIMEFTM_RELTIME; + if (ctl.time_fmts[DMESG_TIMEFTM_TIME] == TIMESTAMP_FMT_INIT_SET) + ctl.time_fmts[DMESG_TIMEFTM_TIME] = TIMESTAMP_FMT_UNSET; + ctl.time_fmts[DMESG_TIMEFTM_RELTIME] = TIMESTAMP_FMT_SET; break; case 'F': ctl.filename = optarg; @@ -1488,7 +1520,9 @@ int main(int argc, char *argv[]) return EXIT_FAILURE; break; case 'H': - ctl.time_fmt = DMESG_TIMEFTM_RELTIME; + if (ctl.time_fmts[DMESG_TIMEFTM_TIME] == TIMESTAMP_FMT_INIT_SET) + ctl.time_fmts[DMESG_TIMEFTM_TIME] = TIMESTAMP_FMT_UNSET; + ctl.time_fmts[DMESG_TIMEFTM_RELTIME] = TIMESTAMP_FMT_SET; colormode = UL_COLORMODE_AUTO; ctl.pager = 1; break; @@ -1535,10 +1569,14 @@ int main(int argc, char *argv[]) ctl.bufsize = 4096; break; case 'T': - ctl.time_fmt = DMESG_TIMEFTM_CTIME; + if (ctl.time_fmts[DMESG_TIMEFTM_TIME] == TIMESTAMP_FMT_INIT_SET) + ctl.time_fmts[DMESG_TIMEFTM_TIME] = TIMESTAMP_FMT_UNSET; + ctl.time_fmts[DMESG_TIMEFTM_CTIME] = TIMESTAMP_FMT_SET; break; case 't': - ctl.time_fmt = DMESG_TIMEFTM_NONE; + memset(ctl.time_fmts, 0, + TOTAL_DMESG_TIMESTAMP_FORMATS_SUPPORTED * sizeof(*(ctl.time_fmts))); + ctl.time_fmts[DMESG_TIMEFTM_NONE] = TIMESTAMP_FMT_SET; break; case 'u': ctl.fltr_fac = 1; @@ -1556,7 +1594,9 @@ int main(int argc, char *argv[]) ctl.decode = 1; break; case OPT_TIME_FORMAT: - ctl.time_fmt = which_time_format(optarg); + if (ctl.time_fmts[DMESG_TIMEFTM_TIME] == TIMESTAMP_FMT_INIT_SET) + ctl.time_fmts[DMESG_TIMEFTM_TIME] = TIMESTAMP_FMT_UNSET; + ctl.time_fmts[which_time_format(optarg)] = TIMESTAMP_FMT_SET; break; case OPT_NOESC: ctl.noesc = 1; @@ -1588,7 +1628,9 @@ int main(int argc, char *argv[]) } if (ctl.json) { - ctl.time_fmt = DMESG_TIMEFTM_TIME; + memset(ctl.time_fmts, 0, + TOTAL_DMESG_TIMESTAMP_FORMATS_SUPPORTED * sizeof(*(ctl.time_fmts))); + ctl.time_fmts[DMESG_TIMEFTM_TIME] = TIMESTAMP_FMT_SET; delta = 0; ctl.force_prefix = 0; ctl.raw = 0; @@ -1596,30 +1638,30 @@ int main(int argc, char *argv[]) nopager = 1; } - if ((is_timefmt(&ctl, RELTIME) || - is_timefmt(&ctl, CTIME) || - is_timefmt(&ctl, ISO8601)) || + if ((ctl.time_fmts[DMESG_TIMEFTM_RELTIME] > 0 || + ctl.time_fmts[DMESG_TIMEFTM_CTIME] > 0 || + ctl.time_fmts[DMESG_TIMEFTM_ISO8601] > 0) || ctl.since || ctl.until) { - if (dmesg_get_boot_time(&ctl.boot_time) != 0) - ctl.time_fmt = DMESG_TIMEFTM_NONE; - else + if (dmesg_get_boot_time(&ctl.boot_time) != 0) { + memset(ctl.time_fmts, 0, + TOTAL_DMESG_TIMESTAMP_FORMATS_SUPPORTED * sizeof(*(ctl.time_fmts))); + ctl.time_fmts[DMESG_TIMEFTM_NONE] = TIMESTAMP_FMT_SET; + } else ctl.suspended_time = dmesg_get_suspended_time(); } - if (delta) { - switch (ctl.time_fmt) { - case DMESG_TIMEFTM_CTIME: - ctl.time_fmt = DMESG_TIMEFTM_CTIME_DELTA; - break; - case DMESG_TIMEFTM_TIME: - ctl.time_fmt = DMESG_TIMEFTM_TIME_DELTA; - break; - case DMESG_TIMEFTM_ISO8601: - warnx(_("--show-delta is ignored when used together with iso8601 time format")); - break; - default: - ctl.time_fmt = DMESG_TIMEFTM_DELTA; + if (delta || ctl.time_fmts[DMESG_TIMEFTM_DELTA]) { + if (ctl.time_fmts[DMESG_TIMEFTM_TIME] > 0) { + ctl.time_fmts[DMESG_TIMEFTM_DELTA] = TIMESTAMP_FMT_UNSET; + ctl.time_fmts[DMESG_TIMEFTM_TIME] = TIMESTAMP_FMT_UNSET; + ctl.time_fmts[DMESG_TIMEFTM_TIME_DELTA] = TIMESTAMP_FMT_SET; + } else if (ctl.time_fmts[DMESG_TIMEFTM_CTIME] > 0) { + ctl.time_fmts[DMESG_TIMEFTM_DELTA] = TIMESTAMP_FMT_UNSET; + ctl.time_fmts[DMESG_TIMEFTM_CTIME] = TIMESTAMP_FMT_UNSET; + ctl.time_fmts[DMESG_TIMEFTM_CTIME_DELTA] = TIMESTAMP_FMT_SET; + } else { + ctl.time_fmts[DMESG_TIMEFTM_DELTA] = TIMESTAMP_FMT_SET; } } -- 2.41.0