From c741efdc3139f633b71697e2e4bab921b36e4a23 Mon Sep 17 00:00:00 2001 From: Nikolaus Schulz Date: Wed, 11 Oct 2023 18:31:17 +0200 Subject: [PATCH] dmesg: Parse printk_caller from /dev/kmsg, if available Linux v5.1 has added optional support for recording the printk caller. Extend the parser logic in dmesg to extract this information if it is available. Signed-off-by: Nikolaus Schulz --- sys-utils/dmesg.c | 75 ++++++++++++++++++++++++++++++++++++++--------- 1 file changed, 61 insertions(+), 14 deletions(-) diff --git a/sys-utils/dmesg.c b/sys-utils/dmesg.c index d301951bb..b1193bec5 100644 --- a/sys-utils/dmesg.c +++ b/sys-utils/dmesg.c @@ -70,6 +70,7 @@ struct dmesg_color { enum { DMESG_COLOR_SUBSYS, DMESG_COLOR_TIME, + DMESG_COLOR_CALLER, DMESG_COLOR_TIMEBREAK, DMESG_COLOR_ALERT, DMESG_COLOR_CRIT, @@ -82,6 +83,7 @@ static const struct dmesg_color colors[] = { [DMESG_COLOR_SUBSYS] = { "subsys", UL_COLOR_BROWN }, [DMESG_COLOR_TIME] = { "time", UL_COLOR_GREEN }, + [DMESG_COLOR_CALLER] = { "caller", UL_COLOR_CYAN }, [DMESG_COLOR_TIMEBREAK] = { "timebreak",UL_COLOR_GREEN UL_COLOR_BOLD }, [DMESG_COLOR_ALERT] = { "alert", UL_COLOR_REVERSE UL_COLOR_RED }, [DMESG_COLOR_CRIT] = { "crit", UL_COLOR_BOLD UL_COLOR_RED }, @@ -214,6 +216,7 @@ struct dmesg_record { int level; int facility; struct timeval tv; + char caller[12]; const char *next; /* buffer with next unparsed record */ size_t next_size; /* size of the next buffer */ @@ -226,6 +229,7 @@ struct dmesg_record { (_r)->level = -1; \ (_r)->tv.tv_sec = 0; \ (_r)->tv.tv_usec = 0; \ + (_r)->caller[0] = '\0'; \ } while (0) static int read_kmsg(struct dmesg_control *ctl); @@ -507,6 +511,21 @@ static const char *parse_kmsg_timestamp(const char *str0, struct timeval *tv) return end + 1; /* skip separator */ } +static const char *parse_kmsg_caller(const char *str, char *caller) +{ + const char *end; + + if (sscanf(str, "caller=%11[^,;]", caller) != 1) + return str; + + end = str + strlen("caller=") + strlen(caller); + if (*end != ',' && *end != ';') { + *caller = '\0'; + return str; + } + + return end + 1; /* Skip separator */ +} static double time_diff(struct timeval *a, struct timeval *b) { @@ -912,6 +931,7 @@ static void print_record(struct dmesg_control *ctl, char buf[128]; char fpbuf[32] = "\0"; char tsbuf[64] = "\0"; + char callerbuf[12+2] = "\0"; /* Added room for "[]" */ size_t mesg_size = rec->mesg_size; int timebreak = 0; char *mesg_copy = NULL; @@ -931,7 +951,7 @@ static void print_record(struct dmesg_control *ctl, */ if (ctl->raw) { ctl->indent = snprintf(tsbuf, sizeof(tsbuf), - "<%d>[%5ld.%06ld] ", + "<%d>[%5ld.%06ld]", LOG_MAKEPRI(rec->facility, rec->level), (long) rec->tv.tv_sec, (long) rec->tv.tv_usec); @@ -955,16 +975,16 @@ static void print_record(struct dmesg_control *ctl, ctl->indent = 0; break; case DMESG_TIMEFTM_CTIME: - ctl->indent = snprintf(tsbuf, sizeof(tsbuf), "[%s] ", + 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>] ", + 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>] ", + ctl->indent = snprintf(tsbuf, sizeof(tsbuf), "[<%12.06f>]", record_count_delta(ctl, rec)); break; case DMESG_TIMEFTM_RELTIME: @@ -974,32 +994,32 @@ static void print_record(struct dmesg_control *ctl, cur.tm_hour != ctl->lasttm.tm_hour || cur.tm_yday != ctl->lasttm.tm_yday) { timebreak = 1; - ctl->indent = snprintf(tsbuf, sizeof(tsbuf), "[%s] ", + 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); + "[ %+8.06f]", delta); else ctl->indent = snprintf(tsbuf, sizeof(tsbuf), - "[ %+9.06f] ", delta); + "[ %+9.06f]", delta); } ctl->lasttm = cur; break; case DMESG_TIMEFTM_TIME: - ctl->indent = snprintf(tsbuf, sizeof(tsbuf), "[%5ld.%06ld] ", + ctl->indent = snprintf(tsbuf, sizeof(tsbuf), "[%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>] ", + 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 ", + ctl->indent = snprintf(tsbuf, sizeof(tsbuf), "%s", iso_8601_time(ctl, rec, buf, sizeof(buf))); break; @@ -1007,7 +1027,10 @@ static void print_record(struct dmesg_control *ctl, abort(); } - ctl->indent += strlen(fpbuf); + if (*rec->caller) + snprintf(callerbuf, sizeof(callerbuf), "[%6s]", rec->caller); + + ctl->indent += strlen(fpbuf) + strlen(callerbuf); full_output: /* Output the decode information */ @@ -1031,12 +1054,26 @@ full_output: if (!line) fputs(tsbuf, stdout); else - printf("[ +0.000000] "); + printf("[ +0.000000]"); } if (ctl->color) color_disable(); } + if (*callerbuf) { + /* Colorize the caller */ + if (ctl->color) + dmesg_enable_color(DMESG_COLOR_CALLER); + fputs(callerbuf, stdout); + if (ctl->color) + color_disable(); + } + + if (*tsbuf || *callerbuf) { + fputc(' ', stdout); + ctl->indent++; + } + /* * A kernel message may contain several lines of output, separated * by '\n'. If the timestamp and decode outputs are forced then each @@ -1212,11 +1249,21 @@ static int parse_kmsg_record(struct dmesg_control *ctl, if (LAST_KMSG_FIELD(p)) goto mesg; - /* D) optional fields (ignore) */ + /* D) continuation flag */ + p = skip_item(p, end, ",;"); + if (LAST_KMSG_FIELD(p)) + goto mesg; + + /* E) printk caller */ + p = parse_kmsg_caller(p, rec->caller); + if (LAST_KMSG_FIELD(p)) + goto mesg; + + /* F) optional fields (ignore) */ p = skip_item(p, end, ";"); mesg: - /* E) message text */ + /* G) message text */ rec->mesg = p; p = skip_item(p, end, "\n"); if (!p) -- 2.39.2