Re: [RFC] printk/sysrq: Don't play with console_loglevel

From: Tetsuo Handa
Date: Fri May 31 2019 - 10:14:57 EST

On 2019/05/28 22:42, Petr Mladek wrote:
> On Tue 2019-05-28 13:46:19, Sergey Senozhatsky wrote:
>> On (05/28/19 13:15), Sergey Senozhatsky wrote:
>>> On (05/28/19 01:24), Dmitry Safonov wrote:
>>> [..]
>>>> While handling sysrq the console_loglevel is bumped to default to print
>>>> sysrq headers. It's done to print sysrq messages with WARNING level for
>>>> consumers of /proc/kmsg, though it sucks by the following reasons:
>>>> - changing console_loglevel may produce tons of messages (especially on
>>>> bloated with debug/info prints systems)
>>>> - it doesn't guarantee that the message will be printed as printk may
>>>> deffer the actual console output from buffer (see the comment near
>>>> printk() in kernel/printk/printk.c)
>>>>
>>>> Provide KERN_UNSUPPRESSED printk() annotation for such legacy places.
>>>> Make sysrq print the headers unsuppressed instead of changing
>>>> console_loglevel.
>
> I like this idea. console_loglevel is temporary manipulated only
> when some messages should or should never appear on the console.
> Storing this information in the message flags would help
> to solve all the related races.

Something like this?

---
arch/ia64/kernel/mca.c | 37 +++++++++++++++------------
arch/x86/platform/uv/uv_nmi.c | 6 ++---
drivers/tty/sysrq.c | 9 +++----
include/linux/printk.h | 24 +++++++++---------
include/linux/sched.h | 3 +++
kernel/debug/kdb/kdb_bt.c | 5 ++--
kernel/debug/kdb/kdb_io.c | 5 ++--
kernel/debug/kdb/kdb_main.c | 5 ++--
kernel/printk/printk.c | 59 +++++++++++++++++++++++++++++++++++++++----
kernel/printk/printk_safe.c | 2 ++
10 files changed, 105 insertions(+), 50 deletions(-)

diff --git a/arch/ia64/kernel/mca.c b/arch/ia64/kernel/mca.c
index 6a52d76..5f3968c 100644
--- a/arch/ia64/kernel/mca.c
+++ b/arch/ia64/kernel/mca.c
@@ -189,19 +189,24 @@
static unsigned long mlogbuf_timestamp = 0;

static int loglevel_save = -1;
-#define BREAK_LOGLEVEL(__console_loglevel) \
- oops_in_progress = 1; \
- if (loglevel_save < 0) \
- loglevel_save = __console_loglevel; \
- __console_loglevel = 15;
-
-#define RESTORE_LOGLEVEL(__console_loglevel) \
- if (loglevel_save >= 0) { \
- __console_loglevel = loglevel_save; \
- loglevel_save = -1; \
- } \
- mlogbuf_finished = 0; \
- oops_in_progress = 0;
+#define BREAK_LOGLEVEL() \
+ do { \
+ int ret; \
+ oops_in_progress = 1; \
+ ret = set_local_loglevel(CONSOLE_LOGLEVEL_MOTORMOUTH); \
+ if (loglevel_save < 0) \
+ loglevel_save = ret; \
+ } while (0)
+
+#define RESTORE_LOGLEVEL() \
+ do { \
+ if (loglevel_save >= 0) { \
+ set_local_loglevel(loglevel_save); \
+ loglevel_save = -1; \
+ } \
+ mlogbuf_finished = 0; \
+ oops_in_progress = 0; \
+ } while (0)

/*
* Push messages into buffer, print them later if not urgent.
@@ -288,7 +293,7 @@ void ia64_mlogbuf_dump(void)
*/
static void ia64_mlogbuf_finish(int wait)
{
- BREAK_LOGLEVEL(console_loglevel);
+ BREAK_LOGLEVEL();

spin_lock_init(&mlogbuf_rlock);
ia64_mlogbuf_dump();
@@ -1623,7 +1628,7 @@ static void mca_insert_tr(u64 iord)
* To enable show_stack from INIT, we use oops_in_progress which should
* be used in real oops. This would cause something wrong after INIT.
*/
- BREAK_LOGLEVEL(console_loglevel);
+ BREAK_LOGLEVEL();
ia64_mlogbuf_dump_from_init();

printk(KERN_ERR "Processes interrupted by INIT -");
@@ -1648,7 +1653,7 @@ static void mca_insert_tr(u64 iord)
read_unlock(&tasklist_lock);
}
/* FIXME: This will not restore zapped printk locks. */
- RESTORE_LOGLEVEL(console_loglevel);
+ RESTORE_LOGLEVEL();
return NOTIFY_DONE;
}

diff --git a/arch/x86/platform/uv/uv_nmi.c b/arch/x86/platform/uv/uv_nmi.c
index b21a932..48592d1 100644
--- a/arch/x86/platform/uv/uv_nmi.c
+++ b/arch/x86/platform/uv/uv_nmi.c
@@ -766,13 +766,13 @@ static void uv_nmi_dump_state(int cpu, struct pt_regs *regs, int master)
if (master) {
int tcpu;
int ignored = 0;
- int saved_console_loglevel = console_loglevel;
+ int saved_loglevel;

pr_alert("UV: tracing %s for %d CPUs from CPU %d\n",
uv_nmi_action_is("ips") ? "IPs" : "processes",
atomic_read(&uv_nmi_cpus_in_nmi), cpu);

- console_loglevel = uv_nmi_loglevel;
+ saved_loglevel = set_local_loglevel(uv_nmi_loglevel);
atomic_set(&uv_nmi_slave_continue, SLAVE_EXIT);
for_each_online_cpu(tcpu) {
if (cpumask_test_cpu(tcpu, uv_nmi_cpu_mask))
@@ -785,7 +785,7 @@ static void uv_nmi_dump_state(int cpu, struct pt_regs *regs, int master)
if (ignored)
pr_alert("UV: %d CPUs ignored NMI\n", ignored);

- console_loglevel = saved_console_loglevel;
+ set_local_loglevel(saved_loglevel);
pr_alert("UV: process trace complete\n");
} else {
while (!atomic_read(&uv_nmi_slave_continue))
diff --git a/drivers/tty/sysrq.c b/drivers/tty/sysrq.c
index 573b205..5675977 100644
--- a/drivers/tty/sysrq.c
+++ b/drivers/tty/sysrq.c
@@ -541,8 +541,7 @@ void __handle_sysrq(int key, bool check_mask)
* simply emit this at KERN_EMERG as that would change message
* routing in the consumers of /proc/kmsg.
*/
- orig_log_level = console_loglevel;
- console_loglevel = CONSOLE_LOGLEVEL_DEFAULT;
+ orig_log_level = set_local_loglevel(CONSOLE_LOGLEVEL_DEFAULT);

op_p = __sysrq_get_key_op(key);
if (op_p) {
@@ -552,11 +551,11 @@ void __handle_sysrq(int key, bool check_mask)
*/
if (!check_mask || sysrq_on_mask(op_p->enable_mask)) {
pr_info("%s\n", op_p->action_msg);
- console_loglevel = orig_log_level;
+ set_local_loglevel(orig_log_level);
op_p->handler(key);
} else {
pr_info("This sysrq operation is disabled.\n");
- console_loglevel = orig_log_level;
+ set_local_loglevel(orig_log_level);
}
} else {
pr_info("HELP : ");
@@ -574,7 +573,7 @@ void __handle_sysrq(int key, bool check_mask)
}
}
pr_cont("\n");
- console_loglevel = orig_log_level;
+ set_local_loglevel(orig_log_level);
}
rcu_read_unlock();
rcu_sysrq_end();
diff --git a/include/linux/printk.h b/include/linux/printk.h
index cefd374..b2dd248 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -47,7 +47,7 @@ static inline const char *printk_skip_headers(const char *buffer)
#define MESSAGE_LOGLEVEL_DEFAULT CONFIG_MESSAGE_LOGLEVEL_DEFAULT

/* We show everything that is MORE important than this.. */
-#define CONSOLE_LOGLEVEL_SILENT 0 /* Mum's the word */
+#define CONSOLE_LOGLEVEL_SILENT -1 /* Mum's the word */
#define CONSOLE_LOGLEVEL_MIN 1 /* Minimum loglevel we let people use */
#define CONSOLE_LOGLEVEL_DEBUG 10 /* issue debug messages */
#define CONSOLE_LOGLEVEL_MOTORMOUTH 15 /* You can't shut this one up */
@@ -66,17 +66,6 @@ static inline const char *printk_skip_headers(const char *buffer)
#define minimum_console_loglevel (console_printk[2])
#define default_console_loglevel (console_printk[3])

-static inline void console_silent(void)
-{
- console_loglevel = CONSOLE_LOGLEVEL_SILENT;
-}
-
-static inline void console_verbose(void)
-{
- if (console_loglevel)
- console_loglevel = CONSOLE_LOGLEVEL_MOTORMOUTH;
-}
-
/* strlen("ratelimit") + 1 */
#define DEVKMSG_STR_MAX_SIZE 10
extern char devkmsg_log_str[];
@@ -205,6 +194,7 @@ extern bool printk_timed_ratelimit(unsigned long *caller_jiffies,
extern void printk_safe_init(void);
extern void printk_safe_flush(void);
extern void printk_safe_flush_on_panic(void);
+char set_local_loglevel(char level);
#else
static inline __printf(1, 0)
int vprintk(const char *s, va_list args)
@@ -280,8 +270,18 @@ static inline void printk_safe_flush(void)
static inline void printk_safe_flush_on_panic(void)
{
}
+
+static inline char set_local_loglevel(char level)
+{
+ return 0;
+}
#endif

+static inline void console_verbose(void)
+{
+ set_local_loglevel(CONSOLE_LOGLEVEL_MOTORMOUTH);
+}
+
extern int kptr_restrict;

#ifndef pr_fmt
diff --git a/include/linux/sched.h b/include/linux/sched.h
index 1183741..283d0d2 100644
--- a/include/linux/sched.h
+++ b/include/linux/sched.h
@@ -732,6 +732,9 @@ struct task_struct {
/* to be used once the psi infrastructure lands upstream. */
unsigned use_memdelay:1;
#endif
+#ifdef CONFIG_PRINTK
+ unsigned printk_loglevel:8;
+#endif

unsigned long atomic_flags; /* Flags requiring atomic access. */

diff --git a/kernel/debug/kdb/kdb_bt.c b/kernel/debug/kdb/kdb_bt.c
index 7e2379a..b385a7e 100644
--- a/kernel/debug/kdb/kdb_bt.c
+++ b/kernel/debug/kdb/kdb_bt.c
@@ -21,8 +21,7 @@

static void kdb_show_stack(struct task_struct *p, void *addr)
{
- int old_lvl = console_loglevel;
- console_loglevel = CONSOLE_LOGLEVEL_MOTORMOUTH;
+ int old_lvl = set_local_loglevel(CONSOLE_LOGLEVEL_MOTORMOUTH);
kdb_trap_printk++;
kdb_set_current_task(p);
if (addr) {
@@ -36,7 +35,7 @@ static void kdb_show_stack(struct task_struct *p, void *addr)
} else {
show_stack(p, NULL);
}
- console_loglevel = old_lvl;
+ set_local_loglevel(old_lvl);
kdb_trap_printk--;
}

diff --git a/kernel/debug/kdb/kdb_io.c b/kernel/debug/kdb/kdb_io.c
index 3a5184e..8b76103 100644
--- a/kernel/debug/kdb/kdb_io.c
+++ b/kernel/debug/kdb/kdb_io.c
@@ -715,8 +715,7 @@ int vkdb_printf(enum kdb_msgsrc src, const char *fmt, va_list ap)
}
}
if (logging) {
- saved_loglevel = console_loglevel;
- console_loglevel = CONSOLE_LOGLEVEL_SILENT;
+ saved_loglevel = set_local_loglevel(CONSOLE_LOGLEVEL_SILENT);
if (printk_get_level(kdb_buffer) || src == KDB_MSGSRC_PRINTK)
printk("%s", kdb_buffer);
else
@@ -845,7 +844,7 @@ int vkdb_printf(enum kdb_msgsrc src, const char *fmt, va_list ap)
kdb_print_out:
suspend_grep = 0; /* end of what may have been a recursive call */
if (logging)
- console_loglevel = saved_loglevel;
+ set_local_loglevel(saved_loglevel);
/* kdb_printf_cpu locked the code above. */
smp_store_release(&kdb_printf_cpu, old_cpu);
local_irq_restore(flags);
diff --git a/kernel/debug/kdb/kdb_main.c b/kernel/debug/kdb/kdb_main.c
index 9ecfa37..395eb98 100644
--- a/kernel/debug/kdb/kdb_main.c
+++ b/kernel/debug/kdb/kdb_main.c
@@ -1130,13 +1130,12 @@ static int kdb_reboot(int argc, const char **argv)

static void kdb_dumpregs(struct pt_regs *regs)
{
- int old_lvl = console_loglevel;
- console_loglevel = CONSOLE_LOGLEVEL_MOTORMOUTH;
+ int old_lvl = set_local_loglevel(CONSOLE_LOGLEVEL_MOTORMOUTH);
kdb_trap_printk++;
show_regs(regs);
kdb_trap_printk--;
kdb_printf("\n");
- console_loglevel = old_lvl;
+ set_local_loglevel(old_lvl);
}

void kdb_set_current_task(struct task_struct *p)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 1888f6a..dfdefe9 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -351,7 +351,9 @@ enum con_msg_format_flags {
*/

enum log_flags {
- LOG_NEWLINE = 2, /* text ended with a newline */
+ LOG_ALWAYS_CON = 1, /* Force suppress_message_printing() = false */
+ LOG_NEVER_CON = 2, /* Force suppress_message_printing() = true */
+ LOG_NEWLINE = 4, /* text ended with a newline */
LOG_CONT = 8, /* text is a fragment of a continuation line */
};

@@ -1172,6 +1174,9 @@ void __init setup_log_buf(int early)
}

static bool __read_mostly ignore_loglevel;
+static DEFINE_PER_CPU(char, printk_loglevel_nmi);
+static DEFINE_PER_CPU(char, printk_loglevel_irq);
+static DEFINE_PER_CPU(char, printk_loglevel_softirq);

static int __init ignore_loglevel_setup(char *str)
{
@@ -1186,11 +1191,36 @@ static int __init ignore_loglevel_setup(char *str)
MODULE_PARM_DESC(ignore_loglevel,
"ignore loglevel setting (prints all kernel messages to the console)");

-static bool suppress_message_printing(int level)
+static bool suppress_message_printing(int flags, int level)
{
+ if (flags & LOG_ALWAYS_CON)
+ return false;
+ if (flags & LOG_NEVER_CON)
+ return true;
return (level >= console_loglevel && !ignore_loglevel);
}

+char set_local_loglevel(char level)
+{
+ char old;
+
+ if (in_nmi()) {
+ old = this_cpu_read(printk_loglevel_nmi);
+ this_cpu_write(printk_loglevel_nmi, level);
+ } else if (in_irq()) {
+ old = this_cpu_read(printk_loglevel_irq);
+ this_cpu_write(printk_loglevel_irq, level);
+ } else if (in_serving_softirq()) {
+ old = this_cpu_read(printk_loglevel_softirq);
+ this_cpu_write(printk_loglevel_softirq, level);
+ } else {
+ old = current->printk_loglevel;
+ current->printk_loglevel = level;
+ }
+ return old;
+}
+EXPORT_SYMBOL(set_local_loglevel);
+
#ifdef CONFIG_BOOT_PRINTK_DELAY

static int boot_delay; /* msecs delay after each printk during bootup */
@@ -1220,7 +1250,7 @@ static void boot_delay_msec(int level)
unsigned long timeout;

if ((boot_delay == 0 || system_state >= SYSTEM_RUNNING)
- || suppress_message_printing(level)) {
+ || suppress_message_printing(0, level)) {
return;
}

@@ -1934,6 +1964,25 @@ int vprintk_store(int facility, int level,
if (level == LOGLEVEL_DEFAULT)
level = default_message_loglevel;

+ {
+ char loglevel;
+
+ if (in_nmi())
+ loglevel = this_cpu_read(printk_loglevel_nmi);
+ else if (in_irq())
+ loglevel = this_cpu_read(printk_loglevel_irq);
+ else if (in_serving_softirq())
+ loglevel = this_cpu_read(printk_loglevel_softirq);
+ else
+ loglevel = current->printk_loglevel;
+ if (loglevel) {
+ if (level >= (int) loglevel && !ignore_loglevel)
+ lflags |= LOG_NEVER_CON;
+ else
+ lflags |= LOG_ALWAYS_CON;
+ }
+ }
+
if (dict)
lflags |= LOG_NEWLINE;

@@ -2080,7 +2129,7 @@ static void call_console_drivers(const char *ext_text, size_t ext_len,
const char *text, size_t len) {}
static size_t msg_print_text(const struct printk_log *msg, bool syslog,
bool time, char *buf, size_t size) { return 0; }
-static bool suppress_message_printing(int level) { return false; }
+static bool suppress_message_printing(int flags, int level) { return false; }

#endif /* CONFIG_PRINTK */

@@ -2418,7 +2467,7 @@ void console_unlock(void)
break;

msg = log_from_idx(console_idx);
- if (suppress_message_printing(msg->level)) {
+ if (suppress_message_printing(msg->flags, msg->level)) {
/*
* Skip record we have buffered and already printed
* directly to the console when we received it, and
diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
index b4045e7..d33bea5 100644
--- a/kernel/printk/printk_safe.c
+++ b/kernel/printk/printk_safe.c
@@ -186,6 +186,7 @@ static void __printk_safe_flush(struct irq_work *work)
unsigned long flags;
size_t len;
int i;
+ char level = set_local_loglevel(CONSOLE_LOGLEVEL_MOTORMOUTH);

/*
* The lock has two functions. First, one reader has to flush all
@@ -232,6 +233,7 @@ static void __printk_safe_flush(struct irq_work *work)
out:
report_message_lost(s);
raw_spin_unlock_irqrestore(&read_lock, flags);
+ set_local_loglevel(level);
}

/**
--
1.8.3.1