[PATCH 0/3] sysrq: Simple fixes and console visibility

[PATCH 0/3] sysrq: Simple fixes and console visibility

[Petr Mladek]

The first two patches are simple bug fixes.

The last one is RFC to fix a bug report. It is not obvious
why sysrq debug operations show only the sysrq header on
the console. The filtering by console_loglevel makes
some sense. The level can actually be set by sysrq.

The solution implemented in the RFC is a warning. It is a simple
idea but the implementation is relatively complicated. Mainly
because all parts sysrq, printk, and consoles are
heavily configurable.

PS: I sent the first patch also separately. It was simple
and it was independent in my first draft of the RFC.
I am sorry for confusion.


Petr Mladek (3):
  sysrq: Restore original console_loglevel when sysrq disabled
  sysrq: Remove duplicated sysrq message
  sysrq: Warn about insufficient console_loglevel

 drivers/tty/sysrq.c    | 34 ++++++++++++++++++++++++++++++----
 include/linux/printk.h |  7 +++++++
 kernel/printk/printk.c |  7 +++----
 3 files changed, 40 insertions(+), 8 deletions(-)

-- 
2.13.7

[PATCH 1/3] sysrq: Restore original console_loglevel when sysrq disabled

[Petr Mladek]

The sysrq header line is printed with an increased loglevel
to provide users some positive feedback.

The original loglevel is not restored when the sysrq operation
is disabled. This bug was introduced in 2.6.12 (pre-git-history)
by the commit ("Allow admin to enable only some of the Magic-Sysrq
functions").

Signed-off-by: Petr Mladek <pmladek@suse.com>
Reviewed-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 drivers/tty/sysrq.c | 1 +
 1 file changed, 1 insertion(+)

diff --git a/drivers/tty/sysrq.c b/drivers/tty/sysrq.c
index 1f03078ec352..2e4e184cfaa6 100644
--- a/drivers/tty/sysrq.c
+++ b/drivers/tty/sysrq.c
@@ -553,6 +553,7 @@ void __handle_sysrq(int key, bool check_mask)
 			op_p->handler(key);
 		} else {
 			pr_cont("This sysrq operation is disabled.\n");
+			console_loglevel = orig_log_level;
 		}
 	} else {
 		pr_cont("HELP : ");
-- 
2.13.7

[PATCH 2/3] sysrq: Remove duplicated sysrq message

[Petr Mladek]

The commit 97f5f0cd8cd0a0544 ("Input: implement SysRq as a separate input
handler") added pr_fmt() definition. It caused a duplicated message
prefix in the sysrq header messages, for example:

[  177.053931] sysrq: SysRq : Show backtrace of all active CPUs
[  742.864776] sysrq: SysRq : HELP : loglevel(0-9) reboot(b) crash(c)

Fixes: 97f5f0cd8cd0a05 ("Input: implement SysRq as a separate input handler")
Signed-off-by: Petr Mladek <pmladek@suse.com>
---
 drivers/tty/sysrq.c | 7 +++----
 1 file changed, 3 insertions(+), 4 deletions(-)

diff --git a/drivers/tty/sysrq.c b/drivers/tty/sysrq.c
index 2e4e184cfaa6..fa0ce7dd9e24 100644
--- a/drivers/tty/sysrq.c
+++ b/drivers/tty/sysrq.c
@@ -539,7 +539,6 @@ void __handle_sysrq(int key, bool check_mask)
 	 */
 	orig_log_level = console_loglevel;
 	console_loglevel = CONSOLE_LOGLEVEL_DEFAULT;
-	pr_info("SysRq : ");
 
         op_p = __sysrq_get_key_op(key);
         if (op_p) {
@@ -548,15 +547,15 @@ void __handle_sysrq(int key, bool check_mask)
 		 * should not) and is the invoked operation enabled?
 		 */
 		if (!check_mask || sysrq_on_mask(op_p->enable_mask)) {
-			pr_cont("%s\n", op_p->action_msg);
+			pr_info("%s\n", op_p->action_msg);
 			console_loglevel = orig_log_level;
 			op_p->handler(key);
 		} else {
-			pr_cont("This sysrq operation is disabled.\n");
+			pr_info("This sysrq operation is disabled.\n");
 			console_loglevel = orig_log_level;
 		}
 	} else {
-		pr_cont("HELP : ");
+		pr_info("HELP : ");
 		/* Only print the help msg once per handler */
 		for (i = 0; i < ARRAY_SIZE(sysrq_key_table); i++) {
 			if (sysrq_key_table[i]) {
-- 
2.13.7

[RFC 3/3] sysrq: Warn about insufficient console_loglevel

[Petr Mladek]

People are sometimes confused that they do not see any output
on the console when trying to get some debugging information
using SysRq.

The messages are filtered by the current console_loglevel.
It makes some sense because a very long output might cause
troubles with a slow console.

Fortunately, the console_loglevel can be increased by SysRq
as well. The only problem is that people do not know that
they should do so and how to do so.

This patch adds a message to help users. It is printed only
once and only when the loglevel is not sufficient.

There is also a need to export suppress_message_printing()
function.

Signed-off-by: Petr Mladek <pmladek@suse.com>
---
 drivers/tty/sysrq.c    | 26 ++++++++++++++++++++++++++
 include/linux/printk.h |  7 +++++++
 kernel/printk/printk.c |  7 +++----
 3 files changed, 36 insertions(+), 4 deletions(-)

diff --git a/drivers/tty/sysrq.c b/drivers/tty/sysrq.c
index fa0ce7dd9e24..e517113cecec 100644
--- a/drivers/tty/sysrq.c
+++ b/drivers/tty/sysrq.c
@@ -523,9 +523,33 @@ static void __sysrq_put_key_op(int key, struct sysrq_key_op *op_p)
                 sysrq_key_table[i] = op_p;
 }
 
+static void warn_console(bool console_suppressed,
+			 int orig_log_level,
+			 struct sysrq_key_op *op_p)
+{
+	static int warned;
+
+	if (warned)
+		return;
+
+	/* Do not warn when people are already setting loglevel via sysrq */
+	if (op_p->enable_mask & SYSRQ_ENABLE_LOG) {
+		warned = 1;
+		return;
+	}
+
+	if (console_suppressed) {
+		pr_info("Messages filtered by console_loglevel (%d)%s\n",
+			orig_log_level,
+			sysrq_on_mask(SYSRQ_ENABLE_LOG) ? ", try SysRq+7" : "");
+		warned = 1;
+	}
+}
+
 void __handle_sysrq(int key, bool check_mask)
 {
 	struct sysrq_key_op *op_p;
+	bool console_suppressed;
 	int orig_log_level;
 	int i;
 
@@ -537,6 +561,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.
 	 */
+	console_suppressed = console_suppress_message(LOGLEVEL_INFO);
 	orig_log_level = console_loglevel;
 	console_loglevel = CONSOLE_LOGLEVEL_DEFAULT;
 
@@ -548,6 +573,7 @@ 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);
+			warn_console(console_suppressed, orig_log_level, op_p);
 			console_loglevel = orig_log_level;
 			op_p->handler(key);
 		} else {
diff --git a/include/linux/printk.h b/include/linux/printk.h
index 77740a506ebb..917bd6ca784c 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -193,6 +193,8 @@ devkmsg_sysctl_set_loglvl(struct ctl_table *table, int write, void __user *buf,
 
 extern void wake_up_klogd(void);
 
+extern bool console_suppress_message(int level);
+
 char *log_buf_addr_get(void);
 u32 log_buf_len_get(void);
 void log_buf_vmcoreinfo_setup(void);
@@ -234,6 +236,11 @@ static inline void wake_up_klogd(void)
 {
 }
 
+static bool console_suppress_message(int)
+{
+	return false;
+}
+
 static inline char *log_buf_addr_get(void)
 {
 	return NULL;
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index d3d170374ceb..b37c3513d7d8 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1164,7 +1164,7 @@ module_param(ignore_loglevel, bool, S_IRUGO | S_IWUSR);
 MODULE_PARM_DESC(ignore_loglevel,
 		 "ignore loglevel setting (prints all kernel messages to the console)");
 
-static bool suppress_message_printing(int level)
+bool console_suppress_message(int level)
 {
 	return (level >= console_loglevel && !ignore_loglevel);
 }
@@ -1198,7 +1198,7 @@ static void boot_delay_msec(int level)
 	unsigned long timeout;
 
 	if ((boot_delay == 0 || system_state >= SYSTEM_RUNNING)
-		|| suppress_message_printing(level)) {
+		|| console_suppress_message(level)) {
 		return;
 	}
 
@@ -2025,7 +2025,6 @@ 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; }
 
 #endif /* CONFIG_PRINTK */
 
@@ -2363,7 +2362,7 @@ void console_unlock(void)
 			break;
 
 		msg = log_from_idx(console_idx);
-		if (suppress_message_printing(msg->level)) {
+		if (console_suppress_message(msg->level)) {
 			/*
 			 * Skip record we have buffered and already printed
 			 * directly to the console when we received it, and
-- 
2.13.7

Re: [PATCH 2/3] sysrq: Remove duplicated sysrq message

[Sergey Senozhatsky]

On (01/11/19 17:20), Petr Mladek wrote:
> The commit 97f5f0cd8cd0a0544 ("Input: implement SysRq as a separate input
> handler") added pr_fmt() definition. It caused a duplicated message
> prefix in the sysrq header messages, for example:
> 
> [  177.053931] sysrq: SysRq : Show backtrace of all active CPUs
> [  742.864776] sysrq: SysRq : HELP : loglevel(0-9) reboot(b) crash(c)
> 
> Fixes: 97f5f0cd8cd0a05 ("Input: implement SysRq as a separate input handler")
> Signed-off-by: Petr Mladek <pmladek@suse.com>

Reviewed-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>



A side note:

> -			pr_cont("This sysrq operation is disabled.\n");
> +			pr_info("This sysrq operation is disabled.\n");

I wouldn't mind this messages to become more informative.

+	pr_info("sysrq 0x%x operation is disabled.\n", key);

?

A bunch of "This sysrq operation is disabled" in serial0 log file
(post mortem) is not very helpful.

	-ss

Re: [RFC 3/3] sysrq: Warn about insufficient console_loglevel

[Sergey Senozhatsky]

On (01/11/19 17:20), Petr Mladek wrote:
> +static void warn_console(bool console_suppressed,
> +			 int orig_log_level,
> +			 struct sysrq_key_op *op_p)
> +{
> +	static int warned;
> +
> +	if (warned)
> +		return;
> +
> +	/* Do not warn when people are already setting loglevel via sysrq */
> +	if (op_p->enable_mask & SYSRQ_ENABLE_LOG) {
> +		warned = 1;
> +		return;
> +	}
> +
> +	if (console_suppressed) {
> +		pr_info("Messages filtered by console_loglevel (%d)%s\n",
> +			orig_log_level,
> +			sysrq_on_mask(SYSRQ_ENABLE_LOG) ? ", try SysRq+7" : "");
> +		warned = 1;
> +	}
> +}

I understand the intent.

Some comments:

- Not all of sysrq handlers printk() data. There are some quiet
  handlers. E.g. sysrq_handle_unraw(). Having "Messages filtered by
  console_loglevel" can be confusing.

- Not all sysrq handlers use INFO level.
  E.g. sync_inodes_sb()->WARN_ON()->pr_warn(). So once again there can
  be a "false positive" "Messages filtered" error, while in fact
  no messages would be filtered out.

What do you think?

	-ss

Re: [PATCH 2/3] sysrq: Remove duplicated sysrq message

[Petr Mladek]

On Mon 2019-01-14 14:51:27, Sergey Senozhatsky wrote:
> On (01/11/19 17:20), Petr Mladek wrote:
> > The commit 97f5f0cd8cd0a0544 ("Input: implement SysRq as a separate input
> > handler") added pr_fmt() definition. It caused a duplicated message
> > prefix in the sysrq header messages, for example:
> > 
> > [  177.053931] sysrq: SysRq : Show backtrace of all active CPUs
> > [  742.864776] sysrq: SysRq : HELP : loglevel(0-9) reboot(b) crash(c)
> > 
> > Fixes: 97f5f0cd8cd0a05 ("Input: implement SysRq as a separate input handler")
> > Signed-off-by: Petr Mladek <pmladek@suse.com>
> 
> Reviewed-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

Thanks.


> A side note:
> 
> > -			pr_cont("This sysrq operation is disabled.\n");
> > +			pr_info("This sysrq operation is disabled.\n");
> 
> I wouldn't mind this messages to become more informative.
> 
> +	pr_info("sysrq 0x%x operation is disabled.\n", key);
> ?

It might be better to use the op_p->action_msg or op_p->help_msg
strings instead of the key number.


> A bunch of "This sysrq operation is disabled" in serial0 log file
> (post mortem) is not very helpful.

The line is printed with the increased loglevel. It is primary
an immediate feedback on the console for the user pressing
the sysrq key.

Well, a more descriptive message would not hurt. Anyway, it
should be a separate patch.

Best Regards,
Petr

Re: [RFC 3/3] sysrq: Warn about insufficient console_loglevel

[Petr Mladek]

On Mon 2019-01-14 17:05:22, Sergey Senozhatsky wrote:
> On (01/11/19 17:20), Petr Mladek wrote:
> > +static void warn_console(bool console_suppressed,
> > +			 int orig_log_level,
> > +			 struct sysrq_key_op *op_p)
> > +{
> > +	static int warned;
> > +
> > +	if (warned)
> > +		return;
> > +
> > +	/* Do not warn when people are already setting loglevel via sysrq */
> > +	if (op_p->enable_mask & SYSRQ_ENABLE_LOG) {
> > +		warned = 1;
> > +		return;
> > +	}
> > +
> > +	if (console_suppressed) {
> > +		pr_info("Messages filtered by console_loglevel (%d)%s\n",
> > +			orig_log_level,
> > +			sysrq_on_mask(SYSRQ_ENABLE_LOG) ? ", try SysRq+7" : "");
> > +		warned = 1;
> > +	}
> > +}
> 
> I understand the intent.
> 
> Some comments:
> 
> - Not all of sysrq handlers printk() data. There are some quiet
>   handlers. E.g. sysrq_handle_unraw(). Having "Messages filtered by
>   console_loglevel" can be confusing.
> 
> - Not all sysrq handlers use INFO level.
>   E.g. sync_inodes_sb()->WARN_ON()->pr_warn(). So once again there can
>   be a "false positive" "Messages filtered" error, while in fact
>   no messages would be filtered out.
> 
> What do you think?

Yes, it has false positives. On the other hand, I do not think
that a better message is worth even more complicated code.

Either we find a better text, for example, use warning style:

    pr_warn("warning: messages are filtered by console loglevel (%d)%s\n"

or hint style:

    pr_info("hint: make sure to see all messages by increasing the
    console logvel, ...

or ???

Otherwise, I would just throw away this idea.

Best Regards,
Petr

Re: [RFC 3/3] sysrq: Warn about insufficient console_loglevel

[Sergey Senozhatsky]

On (01/14/19 15:59), Petr Mladek wrote:
> Yes, it has false positives. On the other hand, I do not think
> that a better message is worth even more complicated code.
> 
> Either we find a better text, for example, use warning style:
> 
>     pr_warn("warning: messages are filtered by console loglevel (%d)%s\n"
> 
> or hint style:
> 
>     pr_info("hint: make sure to see all messages by increasing the
>     console logvel, ...

A box (laptop or desktop) can run X server and read logbuf via
/dev/kmsg or /proc/kmsg, IOW no suppress_message() filtering at
all yet we still will show "you lost some messages" warning. So
we are, sort of, never certain if any messages were filtered out,
in fact. Thus a hint style pr_info() is, probably, the best we
can do, but then I'm not totally sure if we want all that complexity
(exporting another printk() symbol, which somebody someday can
start (ab)using).

I'm not against this patch, so up to you guys.

	-ss