LKML Archive on lore.kernel.org
 help / Atom feed
* [PATCH 0/3] sysrq: Simple fixes and console visibility
@ 2019-01-11 16:20 Petr Mladek
  2019-01-11 16:20 ` [PATCH 1/3] sysrq: Restore original console_loglevel when sysrq disabled Petr Mladek
                   ` (2 more replies)
  0 siblings, 3 replies; 9+ messages in thread
From: Petr Mladek @ 2019-01-11 16:20 UTC (permalink / raw)
  To: Greg Kroah-Hartman, Jiri Slaby
  Cc: Sergey Senozhatsky, Steven Rostedt, Sergey Senozhatsky,
	linux-kernel, 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


^ permalink raw reply	[flat|nested] 9+ messages in thread

* [PATCH 1/3] sysrq: Restore original console_loglevel when sysrq disabled
  2019-01-11 16:20 [PATCH 0/3] sysrq: Simple fixes and console visibility Petr Mladek
@ 2019-01-11 16:20 ` Petr Mladek
  2019-01-11 16:20 ` [PATCH 2/3] sysrq: Remove duplicated sysrq message Petr Mladek
  2019-01-11 16:20 ` [RFC 3/3] sysrq: Warn about insufficient console_loglevel Petr Mladek
  2 siblings, 0 replies; 9+ messages in thread
From: Petr Mladek @ 2019-01-11 16:20 UTC (permalink / raw)
  To: Greg Kroah-Hartman, Jiri Slaby
  Cc: Sergey Senozhatsky, Steven Rostedt, Sergey Senozhatsky,
	linux-kernel, 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


^ permalink raw reply	[flat|nested] 9+ messages in thread

* [PATCH 2/3] sysrq: Remove duplicated sysrq message
  2019-01-11 16:20 [PATCH 0/3] sysrq: Simple fixes and console visibility Petr Mladek
  2019-01-11 16:20 ` [PATCH 1/3] sysrq: Restore original console_loglevel when sysrq disabled Petr Mladek
@ 2019-01-11 16:20 ` Petr Mladek
  2019-01-14  5:51   ` Sergey Senozhatsky
  2019-01-11 16:20 ` [RFC 3/3] sysrq: Warn about insufficient console_loglevel Petr Mladek
  2 siblings, 1 reply; 9+ messages in thread
From: Petr Mladek @ 2019-01-11 16:20 UTC (permalink / raw)
  To: Greg Kroah-Hartman, Jiri Slaby
  Cc: Sergey Senozhatsky, Steven Rostedt, Sergey Senozhatsky,
	linux-kernel, 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


^ permalink raw reply	[flat|nested] 9+ messages in thread

* [RFC 3/3] sysrq: Warn about insufficient console_loglevel
  2019-01-11 16:20 [PATCH 0/3] sysrq: Simple fixes and console visibility Petr Mladek
  2019-01-11 16:20 ` [PATCH 1/3] sysrq: Restore original console_loglevel when sysrq disabled Petr Mladek
  2019-01-11 16:20 ` [PATCH 2/3] sysrq: Remove duplicated sysrq message Petr Mladek
@ 2019-01-11 16:20 ` Petr Mladek
  2019-01-14  8:05   ` Sergey Senozhatsky
  2 siblings, 1 reply; 9+ messages in thread
From: Petr Mladek @ 2019-01-11 16:20 UTC (permalink / raw)
  To: Greg Kroah-Hartman, Jiri Slaby
  Cc: Sergey Senozhatsky, Steven Rostedt, Sergey Senozhatsky,
	linux-kernel, 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


^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: [PATCH 2/3] sysrq: Remove duplicated sysrq message
  2019-01-11 16:20 ` [PATCH 2/3] sysrq: Remove duplicated sysrq message Petr Mladek
@ 2019-01-14  5:51   ` Sergey Senozhatsky
  2019-01-14 14:45     ` Petr Mladek
  0 siblings, 1 reply; 9+ messages in thread
From: Sergey Senozhatsky @ 2019-01-14  5:51 UTC (permalink / raw)
  To: Petr Mladek
  Cc: Greg Kroah-Hartman, Jiri Slaby, Sergey Senozhatsky,
	Steven Rostedt, Sergey Senozhatsky, linux-kernel

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

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: [RFC 3/3] sysrq: Warn about insufficient console_loglevel
  2019-01-11 16:20 ` [RFC 3/3] sysrq: Warn about insufficient console_loglevel Petr Mladek
@ 2019-01-14  8:05   ` Sergey Senozhatsky
  2019-01-14 14:59     ` Petr Mladek
  0 siblings, 1 reply; 9+ messages in thread
From: Sergey Senozhatsky @ 2019-01-14  8:05 UTC (permalink / raw)
  To: Petr Mladek
  Cc: Greg Kroah-Hartman, Jiri Slaby, Sergey Senozhatsky,
	Steven Rostedt, Sergey Senozhatsky, linux-kernel

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

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: [PATCH 2/3] sysrq: Remove duplicated sysrq message
  2019-01-14  5:51   ` Sergey Senozhatsky
@ 2019-01-14 14:45     ` Petr Mladek
  0 siblings, 0 replies; 9+ messages in thread
From: Petr Mladek @ 2019-01-14 14:45 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Greg Kroah-Hartman, Jiri Slaby, Sergey Senozhatsky,
	Steven Rostedt, linux-kernel

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

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: [RFC 3/3] sysrq: Warn about insufficient console_loglevel
  2019-01-14  8:05   ` Sergey Senozhatsky
@ 2019-01-14 14:59     ` Petr Mladek
  2019-01-15  3:03       ` Sergey Senozhatsky
  0 siblings, 1 reply; 9+ messages in thread
From: Petr Mladek @ 2019-01-14 14:59 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Greg Kroah-Hartman, Jiri Slaby, Sergey Senozhatsky,
	Steven Rostedt, linux-kernel

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

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: [RFC 3/3] sysrq: Warn about insufficient console_loglevel
  2019-01-14 14:59     ` Petr Mladek
@ 2019-01-15  3:03       ` Sergey Senozhatsky
  0 siblings, 0 replies; 9+ messages in thread
From: Sergey Senozhatsky @ 2019-01-15  3:03 UTC (permalink / raw)
  To: Petr Mladek
  Cc: Sergey Senozhatsky, Greg Kroah-Hartman, Jiri Slaby,
	Sergey Senozhatsky, Steven Rostedt, linux-kernel

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

^ permalink raw reply	[flat|nested] 9+ messages in thread

end of thread, back to index

Thread overview: 9+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-01-11 16:20 [PATCH 0/3] sysrq: Simple fixes and console visibility Petr Mladek
2019-01-11 16:20 ` [PATCH 1/3] sysrq: Restore original console_loglevel when sysrq disabled Petr Mladek
2019-01-11 16:20 ` [PATCH 2/3] sysrq: Remove duplicated sysrq message Petr Mladek
2019-01-14  5:51   ` Sergey Senozhatsky
2019-01-14 14:45     ` Petr Mladek
2019-01-11 16:20 ` [RFC 3/3] sysrq: Warn about insufficient console_loglevel Petr Mladek
2019-01-14  8:05   ` Sergey Senozhatsky
2019-01-14 14:59     ` Petr Mladek
2019-01-15  3:03       ` Sergey Senozhatsky

LKML Archive on lore.kernel.org

Archives are clonable:
	git clone --mirror https://lore.kernel.org/lkml/0 lkml/git/0.git
	git clone --mirror https://lore.kernel.org/lkml/1 lkml/git/1.git
	git clone --mirror https://lore.kernel.org/lkml/2 lkml/git/2.git
	git clone --mirror https://lore.kernel.org/lkml/3 lkml/git/3.git
	git clone --mirror https://lore.kernel.org/lkml/4 lkml/git/4.git
	git clone --mirror https://lore.kernel.org/lkml/5 lkml/git/5.git
	git clone --mirror https://lore.kernel.org/lkml/6 lkml/git/6.git

	# If you have public-inbox 1.1+ installed, you may
	# initialize and index your mirror using the following commands:
	public-inbox-init -V2 lkml lkml/ https://lore.kernel.org/lkml \
		linux-kernel@vger.kernel.org linux-kernel@archiver.kernel.org
	public-inbox-index lkml


Newsgroup available over NNTP:
	nntp://nntp.lore.kernel.org/org.kernel.vger.linux-kernel


AGPL code for this site: git clone https://public-inbox.org/ public-inbox