[PATCH] printk: debug: Allow to print backtraces of console_lock API callers.

[Petr Mladek]

This patch allows to print backtraces of console_lock API callers.
The logging must be explicitely enabled by:

   echo 1 >/sys/module/printk/parameters/debug_console_lock

I suggest to increase the internal log buffer size, for example,
use on the command line:

   log_buf_len=1M

The logging might easily go wild because the console API is
called by printk() and tty code. I have explicitely disabled
the logging in:

   + vprintk_emit()
   + fb_flashcursor()

, see no_debug_console_lock_enter()/exit() calls. Otherwise,
there was an endless loop of printed entries.

Note that I run the tests in a virtualized test system (QEMU)
via ssh. Some more tty API might need to get disabled when
doing the tests using the tty console. But it might hide
the code called during suspend. So, doing the tests via
ssh sounds better to me.

Also the number of printed backtraces is limited to "100".
It helps to keep the system running when printing the report
triggers more callers of the API and causes an infinite loop.

Signed-off-by: Petr Mladek <pmladek@xxxxxxxx>
---
 drivers/video/fbdev/core/fbcon.c |  9 +++-
 include/linux/printk.h           |  2 +
 kernel/printk/printk.c           | 91 ++++++++++++++++++++++++++++++--
 3 files changed, 98 insertions(+), 4 deletions(-)

diff --git a/drivers/video/fbdev/core/fbcon.c b/drivers/video/fbdev/core/fbcon.c
index 7be9e865325d..1d5d7af516ed 100644
--- a/drivers/video/fbdev/core/fbcon.c
+++ b/drivers/video/fbdev/core/fbcon.c
@@ -397,14 +397,19 @@ static void fb_flashcursor(struct work_struct *work)
 	struct vc_data *vc = NULL;
 	int c;
 	bool enable;
+	int debug;
 	int ret;
 
+	debug = no_debug_console_lock_enter();
+
 	/* FIXME: we should sort out the unbind locking instead */
 	/* instead we just fail to flash the cursor if we can't get
 	 * the lock instead of blocking fbcon deinit */
 	ret = console_trylock();
-	if (ret == 0)
+	if (ret == 0) {
+		no_debug_console_lock_exit(debug);
 		return;
+	}
 
 	/* protected by console_lock */
 	info = par->info;
@@ -416,6 +421,7 @@ static void fb_flashcursor(struct work_struct *work)
 	    fbcon_info_from_console(vc->vc_num) != info ||
 	    vc->vc_deccm != 1) {
 		console_unlock();
+		no_debug_console_lock_exit(debug);
 		return;
 	}
 
@@ -425,6 +431,7 @@ static void fb_flashcursor(struct work_struct *work)
 			    get_fg_color(vc, info, c),
 			    get_bg_color(vc, info, c));
 	console_unlock();
+	no_debug_console_lock_exit(debug);
 
 	queue_delayed_work(system_power_efficient_wq, &par->cursor_work,
 			   par->cur_blink_jiffies);
diff --git a/include/linux/printk.h b/include/linux/printk.h
index 45c663124c9b..f266b20b7584 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -201,6 +201,8 @@ void __init setup_log_buf(int early);
 __printf(1, 2) void dump_stack_set_arch_desc(const char *fmt, ...);
 void dump_stack_print_info(const char *log_lvl);
 void show_regs_print_info(const char *log_lvl);
+int no_debug_console_lock_enter(void);
+void no_debug_console_lock_exit(int debug);
 extern asmlinkage void dump_stack_lvl(const char *log_lvl) __cold;
 extern asmlinkage void dump_stack(void) __cold;
 void printk_trigger_flush(void);
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 6e0ad926f409..c54c70d7a074 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2383,11 +2383,52 @@ MODULE_PARM_DESC(debug_non_panic_cpus,
 		 "allow messages from non-panic CPUs in panic()");
 #endif
 
+int debug_console_lock;
+module_param(debug_console_lock, int, S_IRUGO | S_IWUSR);
+MODULE_PARM_DESC(debug_console_lock,
+		 "Print some caller info when console_lock() API is called.");
+
+static DEFINE_PER_CPU(int, no_debug_console_lock_nesting);
+
+int no_debug_console_lock_enter(void)
+{
+	int debug;
+
+	debug = READ_ONCE(debug_console_lock);
+	if (debug) {
+		if (this_cpu_read(no_debug_console_lock_nesting) > 256) {
+			debug_console_lock = 0;
+			pr_err("Overflow of no_debug_console_lock_nesting! Disabled console_lock debuginng.\n");
+			return 0;
+		}
+
+		migrate_disable();
+		this_cpu_inc(no_debug_console_lock_nesting);
+	}
+
+	return debug;
+}
+
+void no_debug_console_lock_exit(int debug)
+{
+	if (debug) {
+		if (this_cpu_read(no_debug_console_lock_nesting) <= 0) {
+			debug_console_lock = 0;
+			pr_err("Underflow of no_debug_console_lock_nesting! Disabled console lock debuginng.\n");
+			migrate_enable();
+			return;
+		}
+		this_cpu_dec(no_debug_console_lock_nesting);
+		migrate_enable();
+	}
+}
+
 asmlinkage int vprintk_emit(int facility, int level,
 			    const struct dev_printk_info *dev_info,
 			    const char *fmt, va_list args)
 {
 	struct console_flush_type ft;
+	int debug_caller;
 	int printed_len;
 
 	/* Suppress unimportant messages after panic happens */
@@ -2404,6 +2445,8 @@ asmlinkage int vprintk_emit(int facility, int level,
 	    !panic_triggering_all_cpu_backtrace)
 		return 0;
 
+	debug_caller = no_debug_console_lock_enter();
+
 	printk_get_console_flush_type(&ft);
 
 	/* If called from the scheduler, we can not call up(). */
@@ -2448,6 +2491,8 @@ asmlinkage int vprintk_emit(int facility, int level,
 	else if (!console_irqwork_blocked)
 		wake_up_klogd();
 
+	no_debug_console_lock_exit(debug_caller);
+
 	return printed_len;
 }
 EXPORT_SYMBOL(vprintk_emit);
@@ -2856,6 +2901,41 @@ static int console_cpu_notify(unsigned int cpu)
 	return 0;
 }
 
+static void print_console_lock_caller(const char *func_name)
+{
+	static int reports = 0;
+	char tcomm[64];
+	u8 nested;
+
+	if (!debug_console_lock)
+		return;
+
+	nested = raw_cpu_read(no_debug_console_lock_nesting);
+	if (nested)
+		return;
+
+	if (!func_name) {
+		pr_err_once("%s: called without func_name\n", __func__);
+		return;
+	}
+
+	if (reports++ > 100) {
+		debug_console_lock = 0;
+		pr_warn("Too many printed console lock callers. Disabled the debugging.\n");
+	}
+
+	if (current->flags & PF_WQ_WORKER)
+		wq_worker_comm(tcomm, sizeof(tcomm), current);
+	else if (current->flags & PF_KTHREAD)
+		get_kthread_comm(tcomm, sizeof(tcomm), current);
+	else
+		get_task_comm(tcomm, current);
+
+	pr_info("console lock API call [%d]: %s() by pid=%d, comm=%s\n",
+		reports, func_name, current->pid, tcomm);
+	show_stack(current, NULL, KERN_INFO);
+}
+
 /**
  * console_lock - block the console subsystem from printing
  *
@@ -2868,13 +2948,14 @@ void console_lock(void)
 {
 	might_sleep();
 
+	print_console_lock_caller(__func__);
+
 	/* On panic, the console_lock must be left to the panic cpu. */
 	while (panic_on_other_cpu())
 		msleep(1000);
 
 	down_console_sem();
 	if (console_suspended) {
-		printk_store(KERN_INFO "printk: %s\n", __func__);
 		/*
 		 * Keep console locked, but do not touch
 		 * @console_locked or @console_may_schedule.
@@ -2897,13 +2978,14 @@ EXPORT_SYMBOL(console_lock);
  */
 int console_trylock(void)
 {
+	print_console_lock_caller(__func__);
+
 	/* On panic, the console_lock must be left to the panic cpu. */
 	if (panic_on_other_cpu())
 		return 0;
 	if (down_trylock_console_sem())
 		return 0;
 	if (console_suspended) {
-		printk_store(KERN_INFO "printk: %s\n", __func__);
 		/*
 		 * The lock was acquired, but unlock directly and report
 		 * failure. Here console_locked=1 and console_may_schedule=1.
@@ -2919,6 +3001,8 @@ EXPORT_SYMBOL(console_trylock);
 
 int is_console_locked(void)
 {
+//	/* This might produce too many entries. */
+//	print_console_lock_caller(__func__);
 	return console_locked;
 }
 EXPORT_SYMBOL(is_console_locked);
@@ -3404,8 +3488,9 @@ void console_unlock(void)
 {
 	struct console_flush_type ft;
 
+	print_console_lock_caller(__func__);
+
 	if (console_suspended) {
-		printk_store(KERN_INFO "printk: %s\n", __func__);
 		/*
 		 * Simply unlock directly.
 		 * Here console_locked=1 and console_may_schedule=1.
-- 
2.52.0