[PATCH v2] printk: make sure to print log on console.

[PATCH v2] printk: make sure to print log on console.

[Maninder Singh]

This patch make sure printing of log on console if loglevel
at time of storing log is less than current console loglevel.

@why
In SMP printk can work asynchronously, logs can be missed on console
because it checks current log level at time of console_unlock,
not at time of storing logs.

func()
{
....
....
        console_verbose();  // user wants to have all the logs on console.
        pr_alert();
	dump_backtrace(); //prints with default loglevel.
        ...
        console_silent(); // stop all logs from printing on console.
}

Now if console_lock was owned by another process, the messages might
be handled after the consoles were silenced.

reused flag LOG_NOCONS as its usage is gone long back.
(5c2992ee7fd8a29d04125dc0aa3522784c5fa5eb)

Signed-off-by: Vaneet Narang <v.narang@samsung.com>
Signed-off-by: Maninder Singh <maninder1.s@samsung.com>
---
v1 -> v2: make changes simpler as suggested by Petr Mladek.
	  use flag rather than changing structure of printk.

 kernel/printk/printk.c | 12 +++++++-----
 1 file changed, 7 insertions(+), 5 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 2f4af21..4b059fe 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -349,7 +349,7 @@ enum con_msg_format_flags {
  */
 
 enum log_flags {
-	LOG_NOCONS	= 1,	/* already flushed, do not print to console */
+	LOG_NOCONS	= 1,	/* suppress print, do not print to console */
 	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 */
@@ -1886,6 +1886,9 @@ asmlinkage int vprintk_emit(int facility, int level,
 	if (dict)
 		lflags |= LOG_PREFIX|LOG_NEWLINE;
 
+	if (suppress_message_printing(level))
+		lflags |= LOG_NOCONS;
+
 	printed_len = log_output(facility, level, lflags, dict, dictlen, text, text_len);
 
 	logbuf_unlock_irqrestore(flags);
@@ -2355,11 +2358,10 @@ void console_unlock(void)
 			break;
 
 		msg = log_from_idx(console_idx);
-		if (suppress_message_printing(msg->level)) {
+		if (msg->flags & LOG_NOCONS) {
 			/*
-			 * Skip record we have buffered and already printed
-			 * directly to the console when we received it, and
-			 * record that has level above the console loglevel.
+			 * Skip record if !ignore_loglevel, and
+			 * record has level above the console loglevel.
 			 */
 			console_idx = log_next(console_idx);
 			console_seq++;
-- 
1.9.1

Re: [PATCH v2] printk: make sure to print log on console.

[Petr Mladek]

On Fri 2018-06-01 14:26:42, Maninder Singh wrote:
> This patch make sure printing of log on console if loglevel
> at time of storing log is less than current console loglevel.
> 
> @why
> In SMP printk can work asynchronously, logs can be missed on console
> because it checks current log level at time of console_unlock,
> not at time of storing logs.
> 
> func()
> {
> ....
> ....
>         console_verbose();  // user wants to have all the logs on console.
>         pr_alert();
> 	dump_backtrace(); //prints with default loglevel.
>         ...
>         console_silent(); // stop all logs from printing on console.
> }
> 
> Now if console_lock was owned by another process, the messages might
> be handled after the consoles were silenced.

It might make sense to document the limitations reported by
Sergey. I mean to add something like:

"There are still some corner cases where this patch is not enough,
for example, when the messages are flushed later from printk_safe
buffers or when there are races between console_verbose() and
console_silent() callers."


> reused flag LOG_NOCONS as its usage is gone long back.
> (5c2992ee7fd8a29d04125dc0aa3522784c5fa5eb)
> 
> Signed-off-by: Vaneet Narang <v.narang@samsung.com>
> Signed-off-by: Maninder Singh <maninder1.s@samsung.com>

Anyway. the patch helps in many situations and it is a step in the right
direction:

Reviewed-by: Petr Mladek <pmladek@suse.com>

Best Regards,
Petr

PS: There is no need to resend the patch. I could update the commit
message when pushing the patch. I am just going to wait a bit for
other potential reviewers.

Re: [PATCH v2] printk: make sure to print log on console.

[Sergey Senozhatsky]

On (06/08/18 10:39), Petr Mladek wrote:
[..]
> It might make sense to document the limitations reported by
> Sergey. I mean to add something like:
> 
> "There are still some corner cases where this patch is not enough,
> for example, when the messages are flushed later from printk_safe
> buffers or when there are races between console_verbose() and
> console_silent() callers."

Agree. Probably a link to the email would also be helpful.

> > reused flag LOG_NOCONS as its usage is gone long back.
> > (5c2992ee7fd8a29d04125dc0aa3522784c5fa5eb)
> > 
> > Signed-off-by: Vaneet Narang <v.narang@samsung.com>
> > Signed-off-by: Maninder Singh <maninder1.s@samsung.com>
> 
> Anyway. the patch helps in many situations and it is a step in the right
> direction:

So I'm not objecting the patch and will review it shortly.

For educational purposes only:
Would be appreciated if you guys could point out what those "many
situations" are (in the mainline kernel). Could you do that for me?
This is a real question.

Otherwise it feels like I'm missing the real [mainline kernel] importance
and significance of this patch.

	-ss

Re: [PATCH v2] printk: make sure to print log on console.

[Sergey Senozhatsky]

On (06/01/18 14:26), Maninder Singh wrote:
>
> Signed-off-by: Vaneet Narang <v.narang@samsung.com>
> Signed-off-by: Maninder Singh <maninder1.s@samsung.com>

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

	-ss

Re: [PATCH v2] printk: make sure to print log on console.

[Sergey Senozhatsky]

On (06/18/18 15:15), Sergey Senozhatsky wrote:
> 
> On (06/01/18 14:26), Maninder Singh wrote:
> >
> > Signed-off-by: Vaneet Narang <v.narang@samsung.com>
> > Signed-off-by: Maninder Singh <maninder1.s@samsung.com>
> 
> Reviewed-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

OK, we probably need v3 after all.

I think this

-               if (suppress_message_printing(msg->level)) {
+               if (msg->flags & LOG_NOCONS) {

must be changed to

-               if (suppress_message_printing(msg->level)) {
+               if (!ignore_loglevel && (msg->flags & LOG_NOCONS)) {


`ignore_loglevel' is a module param and can change any time via
	/sys/module/printk/parameters/ignore_loglevel
we need to respect its value.

	-ss

Re: [PATCH v2] printk: make sure to print log on console.

[Petr Mladek]

On Mon 2018-06-18 15:23:06, Sergey Senozhatsky wrote:
> On (06/18/18 15:15), Sergey Senozhatsky wrote:
> > 
> > On (06/01/18 14:26), Maninder Singh wrote:
> > >
> > > Signed-off-by: Vaneet Narang <v.narang@samsung.com>
> > > Signed-off-by: Maninder Singh <maninder1.s@samsung.com>
> > 
> > Reviewed-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> 
> OK, we probably need v3 after all.
> 
> I think this
> 
> -               if (suppress_message_printing(msg->level)) {
> +               if (msg->flags & LOG_NOCONS) {
> 
> must be changed to
> 
> -               if (suppress_message_printing(msg->level)) {
> +               if (!ignore_loglevel && (msg->flags & LOG_NOCONS)) {
> 
> 
> `ignore_loglevel' is a module param and can change any time via
> 	/sys/module/printk/parameters/ignore_loglevel
> we need to respect its value.

I would prefer to keep the patch as is. I see it the following way.

Also console_loglevel can be changed anytime by /proc/sys/kernel/printk.
The patch basically moves the decision about the message visibility from
console_unlock() to vprintk_emit(). The logic is easier when all
aspects are handled in a single location and only once.

Best Regards,
Petr

Re: [PATCH v2] printk: make sure to print log on console.

[Sergey Senozhatsky]

On (06/19/18 11:32), Petr Mladek wrote:
> > -               if (suppress_message_printing(msg->level)) {
> > +               if (!ignore_loglevel && (msg->flags & LOG_NOCONS)) {
> > 
> > 
> > `ignore_loglevel' is a module param and can change any time via
> > 	/sys/module/printk/parameters/ignore_loglevel
> > we need to respect its value.
> 
> I would prefer to keep the patch as is. I see it the following way.
> 
> Also console_loglevel can be changed anytime by /proc/sys/kernel/printk.
> The patch basically moves the decision about the message visibility from
> console_unlock() to vprintk_emit(). The logic is easier when all
> aspects are handled in a single location and only once.

But when I set /sys/module/printk/parameters/ignore_loglevel I naturally
expect it to take an immediate action. Without waiting for the consoles
to catch up and to discard N messages [if the consoles were behind the
logbuf head].

	-ss

Re: [PATCH v2] printk: make sure to print log on console.

[Petr Mladek]

On Tue 2018-06-19 18:49:53, Sergey Senozhatsky wrote:
> On (06/19/18 11:32), Petr Mladek wrote:
> > > -               if (suppress_message_printing(msg->level)) {
> > > +               if (!ignore_loglevel && (msg->flags & LOG_NOCONS)) {
> > > 
> > > 
> > > `ignore_loglevel' is a module param and can change any time via
> > > 	/sys/module/printk/parameters/ignore_loglevel
> > > we need to respect its value.
> > 
> > I would prefer to keep the patch as is. I see it the following way.
> > 
> > Also console_loglevel can be changed anytime by /proc/sys/kernel/printk.
> > The patch basically moves the decision about the message visibility from
> > console_unlock() to vprintk_emit(). The logic is easier when all
> > aspects are handled in a single location and only once.
> 
> But when I set /sys/module/printk/parameters/ignore_loglevel I naturally
> expect it to take an immediate action. Without waiting for the consoles
> to catch up and to discard N messages [if the consoles were behind the
> logbuf head].

Yeah, I understand this view. I thought about it as well. But did you
ever needed this behavior in the real life?

I personally changed ignore_loglevel only before I wanted to reproduce a
bug. Then it would be perfectly fine to handle it only in
vprintk_emit(). In fact, it would be even better because it would
affect only messages that happened after I triggered the bug.

Anyway, changing ignore_loglevel during a printk flood has undefined
behavior by definition. If you do this manually, it would depend on
the speed of the console, your typing capabilities, possibility to
login as administrator, load of the system, ... If you do this
by a script, you would probably do it in advance. I do not see
this a reason for a more complicated and even schizophrenic logic.

Best Regards,
Petr

Re: [PATCH v2] printk: make sure to print log on console.

[Sergey Senozhatsky]

On (06/19/18 12:52), Petr Mladek wrote:
> > But when I set /sys/module/printk/parameters/ignore_loglevel I naturally
> > expect it to take an immediate action. Without waiting for the consoles
> > to catch up and to discard N messages [if the consoles were behind the
> > logbuf head].
> 
> Yeah, I understand this view. I thought about it as well. But did you
> ever needed this behavior in the real life?
>
> I personally changed ignore_loglevel only before I wanted to reproduce a
> bug. Then it would be perfectly fine to handle it only in
> vprintk_emit(). In fact, it would be even better because it would
> affect only messages that happened after I triggered the bug.

I thought that additionally to sysfs knob we had a console_foo() function
that simply set ignore_loglevel. But it appears to be sysfs or boot-time
configurable only. I confused CONSOLE_LOGLEVEL_MOTORMOUTH and ignore_loglevel
and thought that a console_verbose() call would basically set ignore_loglevel
to true. It's a bit misleading that we have multiple and independent ways of
achieving the same result.

So maybe the patch can stand the way it is, after all. JFI, still haven't
seen those "helps in real life a lot" examples, tho.


> schizophrenic logic.

OUCH! Seriously, what the... Knock it off!

	-ss

Re: [PATCH v2] printk: make sure to print log on console.

[Petr Mladek]

On Wed 2018-06-20 10:55:25, Sergey Senozhatsky wrote:
> On (06/19/18 12:52), Petr Mladek wrote:
> > > But when I set /sys/module/printk/parameters/ignore_loglevel I naturally
> > > expect it to take an immediate action. Without waiting for the consoles
> > > to catch up and to discard N messages [if the consoles were behind the
> > > logbuf head].
> > 
> > Yeah, I understand this view. I thought about it as well. But did you
> > ever needed this behavior in the real life?
> >
> > I personally changed ignore_loglevel only before I wanted to reproduce a
> > bug. Then it would be perfectly fine to handle it only in
> > vprintk_emit(). In fact, it would be even better because it would
> > affect only messages that happened after I triggered the bug.
> 
> So maybe the patch can stand the way it is, after all. JFI, still haven't
> seen those "helps in real life a lot" examples, tho.

I have personally seen these races when testing printk in NMI. I
combined iptables logging, ping -f and sysrq-l. I am not sure
how often they happen in the real life but I could understand
that it might be annoying.

This patch goes in the right direction and nobody really blocks
it. Therefore I pushed it into printk.git, branch for-4.19.

Best Regards,
Petr

Re: [PATCH v2] printk: make sure to print log on console.

[Steven Rostedt]

On Tue, 19 Jun 2018 18:49:53 +0900
Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:

> On (06/19/18 11:32), Petr Mladek wrote:
> > > -               if (suppress_message_printing(msg->level)) {
> > > +               if (!ignore_loglevel && (msg->flags & LOG_NOCONS)) {
> > > 
> > > 
> > > `ignore_loglevel' is a module param and can change any time via
> > > 	/sys/module/printk/parameters/ignore_loglevel
> > > we need to respect its value.  
> > 
> > I would prefer to keep the patch as is. I see it the following way.
> > 
> > Also console_loglevel can be changed anytime by /proc/sys/kernel/printk.
> > The patch basically moves the decision about the message visibility from
> > console_unlock() to vprintk_emit(). The logic is easier when all
> > aspects are handled in a single location and only once.  
> 
> But when I set /sys/module/printk/parameters/ignore_loglevel I naturally
> expect it to take an immediate action. Without waiting for the consoles
> to catch up and to discard N messages [if the consoles were behind the
> logbuf head].
>

It's not that critical to have that change take immediate effect. It's
not a common operation, and I doubt anyone (but perhaps you ;-) will
even notice any difference.

-- Steve

Re: [PATCH v2] printk: make sure to print log on console.

[Sergey Senozhatsky]

On (06/19/18 09:26), Steven Rostedt wrote:
> > 
> > But when I set /sys/module/printk/parameters/ignore_loglevel I naturally
> > expect it to take an immediate action. Without waiting for the consoles
> > to catch up and to discard N messages [if the consoles were behind the
> > logbuf head].
> >
> It's not that critical to have that change take immediate effect. It's
> not a common operation, and I doubt anyone (but perhaps you ;-) will
> even notice any difference.

Quite possibly.

	In the background (what I didn't post) I thought that
console_verbose() sets ignore_loglevel. So we could have a race
condition - when console drags behind, something sets ignore_loglevel
but it takes a while before "all" messages actually start to appear
on the console.

	In the foreground (what I posted) I thought that the whole
reason the patch exists was "In SMP printk can work asynchronously,
logs can be missed on console because it checks current log level at
time of console_unlock, not at time of storing logs" So console_sem may
be scheduled out, or simply slow. Once again, it may take some time for
ignore_loglevel to take any effect.

But probably it's fine to have this new behaviour.

	-ss