From 15ff2069cb7f967dae6a8f8c176ba51447c75f00 Mon Sep 17 00:00:00 2001 From: Tetsuo Handa Date: Tue, 18 Dec 2018 06:05:04 +0900 Subject: [PATCH 1/5] printk: Add caller information to printk() output. Sometimes we want to print a series of printk() messages to consoles without being disturbed by concurrent printk() from interrupts and/or other threads. But we can't enforce printk() callers to use their local buffers because we need to ask them to make too much changes. Also, even buffering up to one line inside printk() might cause failing to emit an important clue under critical situation. Therefore, instead of trying to help buffering, let's try to help reconstructing messages by saving caller information as of calling log_store() and adding it as "[T$thread_id]" or "[C$processor_id]" upon printing to consoles. Some examples for console output: [ 1.222773][ T1] x86: Booting SMP configuration: [ 2.779635][ T1] pci 0000:00:01.0: PCI bridge to [bus 01] [ 5.069193][ T268] Fusion MPT base driver 3.04.20 [ 9.316504][ C2] random: fast init done [ 13.413336][ T3355] Initialized host personality Some examples for /dev/kmsg output: 6,496,1222773,-,caller=T1;x86: Booting SMP configuration: 6,968,2779635,-,caller=T1;pci 0000:00:01.0: PCI bridge to [bus 01] SUBSYSTEM=pci DEVICE=+pci:0000:00:01.0 6,1353,5069193,-,caller=T268;Fusion MPT base driver 3.04.20 5,1526,9316504,-,caller=C2;random: fast init done 6,1575,13413336,-,caller=T3355;Initialized host personality Note that this patch changes max length of messages which can be printed by printk() or written to /dev/kmsg interface from 992 bytes to 976 bytes, based on an assumption that userspace won't try to write messages hitting that border line to /dev/kmsg interface. Link: http://lkml.kernel.org/r/93f19e57-5051-c67d-9af4-b17624062d44@i-love.sakura.ne.jp Cc: Dmitry Vyukov Cc: Sergey Senozhatsky Cc: Steven Rostedt Cc: Linus Torvalds Cc: Andrew Morton Cc: LKML Cc: syzkaller Signed-off-by: Tetsuo Handa Acked-by: Sergey Senozhatsky Signed-off-by: Petr Mladek --- kernel/printk/printk.c | 55 +++++++++++++++++++++++++++++++++++++++--- lib/Kconfig.debug | 17 +++++++++++++ 2 files changed, 68 insertions(+), 4 deletions(-) diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 91db332ccf4d..e3d977bbc7ab 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -357,6 +357,9 @@ struct printk_log { u8 facility; /* syslog facility */ u8 flags:5; /* internal record flags */ u8 level:3; /* syslog level */ +#ifdef CONFIG_PRINTK_CALLER + u32 caller_id; /* thread id or processor id */ +#endif } #ifdef CONFIG_HAVE_EFFICIENT_UNALIGNED_ACCESS __packed __aligned(4) @@ -423,7 +426,11 @@ static u64 exclusive_console_stop_seq; static u64 clear_seq; static u32 clear_idx; +#ifdef CONFIG_PRINTK_CALLER +#define PREFIX_MAX 48 +#else #define PREFIX_MAX 32 +#endif #define LOG_LINE_MAX (1024 - PREFIX_MAX) #define LOG_LEVEL(v) ((v) & 0x07) @@ -626,6 +633,12 @@ static int log_store(int facility, int level, msg->ts_nsec = ts_nsec; else msg->ts_nsec = local_clock(); +#ifdef CONFIG_PRINTK_CALLER + if (in_task()) + msg->caller_id = task_pid_nr(current); + else + msg->caller_id = 0x80000000 + raw_smp_processor_id(); +#endif memset(log_dict(msg) + dict_len, 0, pad_len); msg->len = size; @@ -689,12 +702,21 @@ static ssize_t msg_print_ext_header(char *buf, size_t size, struct printk_log *msg, u64 seq) { u64 ts_usec = msg->ts_nsec; + char caller[20]; +#ifdef CONFIG_PRINTK_CALLER + u32 id = msg->caller_id; + + snprintf(caller, sizeof(caller), ",caller=%c%u", + id & 0x80000000 ? 'C' : 'T', id & ~0x80000000); +#else + caller[0] = '\0'; +#endif do_div(ts_usec, 1000); - return scnprintf(buf, size, "%u,%llu,%llu,%c;", - (msg->facility << 3) | msg->level, seq, ts_usec, - msg->flags & LOG_CONT ? 'c' : '-'); + return scnprintf(buf, size, "%u,%llu,%llu,%c%s;", + (msg->facility << 3) | msg->level, seq, ts_usec, + msg->flags & LOG_CONT ? 'c' : '-', caller); } static ssize_t msg_print_ext_body(char *buf, size_t size, @@ -1039,6 +1061,9 @@ void log_buf_vmcoreinfo_setup(void) VMCOREINFO_OFFSET(printk_log, len); VMCOREINFO_OFFSET(printk_log, text_len); VMCOREINFO_OFFSET(printk_log, dict_len); +#ifdef CONFIG_PRINTK_CALLER + VMCOREINFO_OFFSET(printk_log, caller_id); +#endif } #endif @@ -1237,10 +1262,23 @@ static size_t print_time(u64 ts, char *buf) { unsigned long rem_nsec = do_div(ts, 1000000000); - return sprintf(buf, "[%5lu.%06lu] ", + return sprintf(buf, "[%5lu.%06lu]", (unsigned long)ts, rem_nsec / 1000); } +#ifdef CONFIG_PRINTK_CALLER +static size_t print_caller(u32 id, char *buf) +{ + char caller[12]; + + snprintf(caller, sizeof(caller), "%c%u", + id & 0x80000000 ? 'C' : 'T', id & ~0x80000000); + return sprintf(buf, "[%6s]", caller); +} +#else +#define print_caller(id, buf) 0 +#endif + static size_t print_prefix(const struct printk_log *msg, bool syslog, bool time, char *buf) { @@ -1248,8 +1286,17 @@ static size_t print_prefix(const struct printk_log *msg, bool syslog, if (syslog) len = print_syslog((msg->facility << 3) | msg->level, buf); + if (time) len += print_time(msg->ts_nsec, buf + len); + + len += print_caller(msg->caller_id, buf + len); + + if (IS_ENABLED(CONFIG_PRINTK_CALLER) || time) { + buf[len++] = ' '; + buf[len] = '\0'; + } + return len; } diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug index 8d24f4ed66fd..89df6750b365 100644 --- a/lib/Kconfig.debug +++ b/lib/Kconfig.debug @@ -17,6 +17,23 @@ config PRINTK_TIME The behavior is also controlled by the kernel command line parameter printk.time=1. See Documentation/admin-guide/kernel-parameters.rst +config PRINTK_CALLER + bool "Show caller information on printks" + depends on PRINTK + help + Selecting this option causes printk() to add a caller "thread id" (if + in task context) or a caller "processor id" (if not in task context) + to every message. + + This option is intended for environments where multiple threads + concurrently call printk() for many times, for it is difficult to + interpret without knowing where these lines (or sometimes individual + line which was divided into multiple lines due to race) came from. + + Since toggling after boot makes the code racy, currently there is + no option to enable/disable at the kernel command line parameter or + sysfs interface. + config CONSOLE_LOGLEVEL_DEFAULT int "Default console loglevel (1-15)" range 1 15 From cbae05d32ff68233f00cbad9fda0382cc982d821 Mon Sep 17 00:00:00 2001 From: Tetsuo Handa Date: Sat, 16 Feb 2019 19:59:33 +0900 Subject: [PATCH 2/5] printk: Pass caller information to log_store(). When thread1 called printk() which did not end with '\n', and then thread2 called printk() which ends with '\n' before thread1 calls pr_cont(), the partial content saved into "struct cont" is flushed by thread2 despite the partial content was generated by thread1. This leads to confusing output as if the partial content was generated by thread2. Fix this problem by passing correct caller information to log_store(). Before: [ T8533] abcdefghijklm [ T8533] ABCDEFGHIJKLMNOPQRSTUVWXYZ [ T8532] nopqrstuvwxyz [ T8532] abcdefghijklmnopqrstuvwxyz [ T8533] abcdefghijklm [ T8533] ABCDEFGHIJKLMNOPQRSTUVWXYZ [ T8532] nopqrstuvwxyz After: [ T8507] abcdefghijklm [ T8508] ABCDEFGHIJKLMNOPQRSTUVWXYZ [ T8507] nopqrstuvwxyz [ T8507] abcdefghijklmnopqrstuvwxyz [ T8507] abcdefghijklm [ T8508] ABCDEFGHIJKLMNOPQRSTUVWXYZ [ T8507] nopqrstuvwxyz Link: http://lkml.kernel.org/r/1550314773-8607-1-git-send-email-penguin-kernel@I-love.SAKURA.ne.jp To: Dmitry Vyukov To: Sergey Senozhatsky To: Steven Rostedt Cc: linux-kernel@vger.kernel.org Signed-off-by: Tetsuo Handa Reviewed-by: Sergey Senozhatsky [pmladek: broke 80-column rule where it made more harm than good] Signed-off-by: Petr Mladek --- kernel/printk/printk.c | 37 ++++++++++++++++++++++--------------- 1 file changed, 22 insertions(+), 15 deletions(-) diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index e3d977bbc7ab..b4d26388bc62 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -585,7 +585,7 @@ static u32 truncate_msg(u16 *text_len, u16 *trunc_msg_len, } /* insert record into the buffer, discard old ones, update heads */ -static int log_store(int facility, int level, +static int log_store(u32 caller_id, int facility, int level, enum log_flags flags, u64 ts_nsec, const char *dict, u16 dict_len, const char *text, u16 text_len) @@ -634,10 +634,7 @@ static int log_store(int facility, int level, else msg->ts_nsec = local_clock(); #ifdef CONFIG_PRINTK_CALLER - if (in_task()) - msg->caller_id = task_pid_nr(current); - else - msg->caller_id = 0x80000000 + raw_smp_processor_id(); + msg->caller_id = caller_id; #endif memset(log_dict(msg) + dict_len, 0, pad_len); msg->len = size; @@ -1800,6 +1797,12 @@ static inline void printk_delay(void) } } +static inline u32 printk_caller_id(void) +{ + return in_task() ? task_pid_nr(current) : + 0x80000000 + raw_smp_processor_id(); +} + /* * Continuation lines are buffered, and not committed to the record buffer * until the line is complete, or a race forces it. The line fragments @@ -1809,7 +1812,7 @@ static inline void printk_delay(void) static struct cont { char buf[LOG_LINE_MAX]; size_t len; /* length == 0 means unused buffer */ - struct task_struct *owner; /* task of first print*/ + u32 caller_id; /* printk_caller_id() of first print */ u64 ts_nsec; /* time of first print */ u8 level; /* log level of first message */ u8 facility; /* log facility of first message */ @@ -1821,12 +1824,13 @@ static void cont_flush(void) if (cont.len == 0) return; - log_store(cont.facility, cont.level, cont.flags, cont.ts_nsec, - NULL, 0, cont.buf, cont.len); + log_store(cont.caller_id, cont.facility, cont.level, cont.flags, + cont.ts_nsec, NULL, 0, cont.buf, cont.len); cont.len = 0; } -static bool cont_add(int facility, int level, enum log_flags flags, const char *text, size_t len) +static bool cont_add(u32 caller_id, int facility, int level, + enum log_flags flags, const char *text, size_t len) { /* If the line gets too long, split it up in separate records. */ if (cont.len + len > sizeof(cont.buf)) { @@ -1837,7 +1841,7 @@ static bool cont_add(int facility, int level, enum log_flags flags, const char * if (!cont.len) { cont.facility = facility; cont.level = level; - cont.owner = current; + cont.caller_id = caller_id; cont.ts_nsec = local_clock(); cont.flags = flags; } @@ -1857,13 +1861,15 @@ static bool cont_add(int facility, int level, enum log_flags flags, const char * static size_t log_output(int facility, int level, enum log_flags lflags, const char *dict, size_t dictlen, char *text, size_t text_len) { + const u32 caller_id = printk_caller_id(); + /* * If an earlier line was buffered, and we're a continuation - * write from the same process, try to add it to the buffer. + * write from the same context, try to add it to the buffer. */ if (cont.len) { - if (cont.owner == current && (lflags & LOG_CONT)) { - if (cont_add(facility, level, lflags, text, text_len)) + if (cont.caller_id == caller_id && (lflags & LOG_CONT)) { + if (cont_add(caller_id, facility, level, lflags, text, text_len)) return text_len; } /* Otherwise, make sure it's flushed */ @@ -1876,12 +1882,13 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c /* If it doesn't end in a newline, try to buffer the current line */ if (!(lflags & LOG_NEWLINE)) { - if (cont_add(facility, level, lflags, text, text_len)) + if (cont_add(caller_id, facility, level, lflags, text, text_len)) return text_len; } /* Store it in the record log */ - return log_store(facility, level, lflags, 0, dict, dictlen, text, text_len); + return log_store(caller_id, facility, level, lflags, 0, + dict, dictlen, text, text_len); } /* Must be called under logbuf_lock. */ From b60706644282af04e4aa57da5af57470d453cd1f Mon Sep 17 00:00:00 2001 From: Geert Uytterhoeven Date: Thu, 28 Feb 2019 11:53:15 +0100 Subject: [PATCH 3/5] lib/vsprintf: Remove %pCr remnant in comment Support for "%pCr" was removed, but a reference in a comment was forgotten. Fixes: 666902e42fd8344b ("lib/vsprintf: Remove atomic-unsafe support for %pCr") Link: http://lkml.kernel.org/r/20190228105315.744-1-geert+renesas@glider.be To: Andy Shevchenko To: Andrew Morton Cc: linux-kernel@vger.kernel.org Signed-off-by: Geert Uytterhoeven Signed-off-by: Petr Mladek --- lib/vsprintf.c | 1 - 1 file changed, 1 deletion(-) diff --git a/lib/vsprintf.c b/lib/vsprintf.c index ad4fbe5bc730..458600f4fbc5 100644 --- a/lib/vsprintf.c +++ b/lib/vsprintf.c @@ -1827,7 +1827,6 @@ char *device_node_string(char *buf, char *end, struct device_node *dn, * (legacy clock framework) of the clock * - 'Cn' For a clock, it prints the name (Common Clock Framework) or address * (legacy clock framework) of the clock - * - 'Cr' For a clock, it prints the current rate of the clock * - 'G' For flags to be printed as a collection of symbolic strings that would * construct the specific value. Supported flags given by option: * p page flags (see struct page) given as pointer to unsigned long From e36202a844d4eff2ab07bcef998d7b4beda9761f Mon Sep 17 00:00:00 2001 From: Tetsuo Handa Date: Fri, 22 Feb 2019 18:59:40 +0900 Subject: [PATCH 4/5] printk: Remove no longer used LOG_PREFIX. When commit 5becfb1df5ac8e49 ("kmsg: merge continuation records while printing") introduced LOG_PREFIX, we used KERN_DEFAULT etc. as a flag for setting LOG_PREFIX in order to tell whether to call cont_add() (i.e. whether to append the message to "struct cont"). But since commit 4bcc595ccd80decb ("printk: reinstate KERN_CONT for printing continuation lines") inverted the behavior (i.e. don't append the message to "struct cont" unless KERN_CONT is specified) and commit 5aa068ea4082b39e ("printk: remove games with previous record flags") removed the last LOG_PREFIX check, setting LOG_PREFIX via KERN_DEFAULT etc. is no longer meaningful. Therefore, we can remove LOG_PREFIX and make KERN_DEFAULT empty string. Link: http://lkml.kernel.org/r/1550829580-9189-1-git-send-email-penguin-kernel@I-love.SAKURA.ne.jp To: Steven Rostedt To: Linus Torvalds Cc: linux-kernel@vger.kernel.org Cc: Tetsuo Handa Signed-off-by: Tetsuo Handa Reviewed-by: Sergey Senozhatsky Signed-off-by: Petr Mladek --- include/linux/kern_levels.h | 2 +- include/linux/printk.h | 1 - kernel/printk/printk.c | 6 +----- 3 files changed, 2 insertions(+), 7 deletions(-) diff --git a/include/linux/kern_levels.h b/include/linux/kern_levels.h index d237fe854ad9..bf2389c26ae3 100644 --- a/include/linux/kern_levels.h +++ b/include/linux/kern_levels.h @@ -14,7 +14,7 @@ #define KERN_INFO KERN_SOH "6" /* informational */ #define KERN_DEBUG KERN_SOH "7" /* debug-level messages */ -#define KERN_DEFAULT KERN_SOH "d" /* the default kernel loglevel */ +#define KERN_DEFAULT "" /* the default kernel loglevel */ /* * Annotation for a "continued" line of log printout (only done after a diff --git a/include/linux/printk.h b/include/linux/printk.h index 55aa96975fa2..97aa12c928d4 100644 --- a/include/linux/printk.h +++ b/include/linux/printk.h @@ -18,7 +18,6 @@ static inline int printk_get_level(const char *buffer) if (buffer[0] == KERN_SOH_ASCII && buffer[1]) { switch (buffer[1]) { case '0' ... '7': - case 'd': /* KERN_DEFAULT */ case 'c': /* KERN_CONT */ return buffer[1]; } diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index b4d26388bc62..9b6783c158f9 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -345,7 +345,6 @@ static int console_msg_format = MSG_FORMAT_DEFAULT; enum log_flags { LOG_NEWLINE = 2, /* text ended with a newline */ - LOG_PREFIX = 4, /* text started with a prefix */ LOG_CONT = 8, /* text is a fragment of a continuation line */ }; @@ -1922,9 +1921,6 @@ int vprintk_store(int facility, int level, case '0' ... '7': if (level == LOGLEVEL_DEFAULT) level = kern_level - '0'; - /* fallthrough */ - case 'd': /* KERN_DEFAULT */ - lflags |= LOG_PREFIX; break; case 'c': /* KERN_CONT */ lflags |= LOG_CONT; @@ -1939,7 +1935,7 @@ int vprintk_store(int facility, int level, level = default_message_loglevel; if (dict) - lflags |= LOG_PREFIX|LOG_NEWLINE; + lflags |= LOG_NEWLINE; return log_output(facility, level, lflags, dict, dictlen, text, text_len); From 943ca6ad81e5b37bd5d22cbab5ad06dc97fc001c Mon Sep 17 00:00:00 2001 From: Louis Taylor Date: Sun, 3 Mar 2019 12:36:47 +0000 Subject: [PATCH 5/5] printk/docs: Add extra integer types to printk-formats A few commonly used integer types were absent from this table, so add them. Link: https://github.com/ClangBuiltLinux/linux/issues/378 Suggested-by: Nick Desaulniers Link: http://lkml.kernel.org/r/20190303123647.22020-1-louis@kragniz.eu Cc: pmladek@suse.com Cc: geert+renesas@glider.be Cc: andriy.shevchenko@linux.intel.com Cc: linux-doc@vger.kernel.org Cc: linux-kernel@vger.kernel.org Cc: clang-built-linux@googlegroups.com Cc: ndesaulniers@google.com Cc: jflat@chromium.org Cc: Louis Taylor Signed-off-by: Louis Taylor [pmladek@suse.com: sorted both variants the same way by size] Signed-off-by: Petr Mladek --- Documentation/core-api/printk-formats.rst | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/Documentation/core-api/printk-formats.rst b/Documentation/core-api/printk-formats.rst index ff48b55040ef..cd1b0e804b74 100644 --- a/Documentation/core-api/printk-formats.rst +++ b/Documentation/core-api/printk-formats.rst @@ -13,6 +13,10 @@ Integer types If variable is of Type, use printk format specifier: ------------------------------------------------------------ + char %hhd or %hhx + unsigned char %hhu or %hhx + short int %hd or %hx + unsigned short int %hu or %hx int %d or %x unsigned int %u or %x long %ld or %lx @@ -21,6 +25,10 @@ Integer types unsigned long long %llu or %llx size_t %zu or %zx ssize_t %zd or %zx + s8 %hhd or %hhx + u8 %hhu or %hhx + s16 %hd or %hx + u16 %hu or %hx s32 %d or %x u32 %u or %x s64 %lld or %llx