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

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

[Maninder Singh]

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

@why
In case of async printk, printk thread can miss logs because it checks
current log level at time of console_unlock.

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

Now if printk thread is scheduled after setting console loglevel
to silent, then user's requirement will be in waste, because it will not
print logs on console at time of printk thread scheduling.

@how
use one bit of flags field to store whether its console print
or not(console_print) by checking current console loglevel with 
message's level at time of log.
At time of print check this flag for printing message on console.

Signed-off-by: Vaneet Narang <v.narang@samsung.com>
Signed-off-by: Maninder Singh <maninder1.s@samsung.com>
---
 kernel/printk/printk.c | 33 +++++++++++++++++++++++----------
 1 file changed, 23 insertions(+), 10 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index ab15903..4e0be66e 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -360,8 +360,16 @@ struct printk_log {
 	u16 text_len;		/* length of text buffer */
 	u16 dict_len;		/* length of dictionary buffer */
 	u8 facility;		/* syslog facility */
-	u8 flags:5;		/* internal record flags */
+	u8 flags:4;		/* internal record flags */
 	u8 level:3;		/* syslog level */
+	/*
+	 * whether to print this msg on console or not?
+	 * due to async printk, printk thread can miss
+	 * prints at the time of console_flush because of
+	 * change in print level afterwards.
+	 */
+	u8 console_print:1;
+
 }
 #ifdef CONFIG_HAVE_EFFICIENT_UNALIGNED_ACCESS
 __packed __aligned(4)
@@ -623,7 +631,12 @@ static int log_store(int facility, int level,
 	msg->dict_len = dict_len;
 	msg->facility = facility;
 	msg->level = level & 7;
-	msg->flags = flags & 0x1f;
+	if (msg->level >= console_loglevel)
+		msg->console_print = 0;
+	else
+		msg->console_print = 1;
+
+	msg->flags = flags & 0xf;
 	if (ts_nsec > 0)
 		msg->ts_nsec = ts_nsec;
 	else
@@ -1144,9 +1157,9 @@ 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 console_print)
 {
-	return (level >= console_loglevel && !ignore_loglevel);
+	return (!console_print && !ignore_loglevel);
 }
 
 #ifdef CONFIG_BOOT_PRINTK_DELAY
@@ -1172,13 +1185,13 @@ static int __init boot_delay_setup(char *str)
 }
 early_param("boot_delay", boot_delay_setup);
 
-static void boot_delay_msec(int level)
+static void boot_delay_msec(int console_print)
 {
 	unsigned long long k;
 	unsigned long timeout;
 
 	if ((boot_delay == 0 || system_state >= SYSTEM_RUNNING)
-		|| suppress_message_printing(level)) {
+		|| suppress_message_printing(console_print)) {
 		return;
 	}
 
@@ -1199,7 +1212,7 @@ static void boot_delay_msec(int level)
 	}
 }
 #else
-static inline void boot_delay_msec(int level)
+static inline void boot_delay_msec(int console_print)
 {
 }
 #endif
@@ -1840,7 +1853,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 		in_sched = true;
 	}
 
-	boot_delay_msec(level);
+	boot_delay_msec(level < console_loglevel);
 	printk_delay();
 
 	/* This stops the holder of console_sem just where we want him */
@@ -2011,7 +2024,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, char *buf, size_t size) { return 0; }
-static bool suppress_message_printing(int level) { return false; }
+static bool suppress_message_printing(int console_print) { return false; }
 
 #endif /* CONFIG_PRINTK */
 
@@ -2354,7 +2367,7 @@ void console_unlock(void)
 			break;
 
 		msg = log_from_idx(console_idx);
-		if (suppress_message_printing(msg->level)) {
+		if (suppress_message_printing(msg->console_print)) {
 			/*
 			 * Skip record we have buffered and already printed
 			 * directly to the console when we received it, and
-- 
1.9.1

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

[Sergey Senozhatsky]

On (05/31/18 15:49), Maninder Singh wrote:
> 
> This patch make sure printing of log if loglevel at time of storing
> log is greater than current console loglevel.
> 
> @why
> In case of async printk, printk thread can miss logs because it checks
> current log level at time of console_unlock.

Upstream printk has no printing kthread. And we also run
printk()->console_unlock() with disabled preemption.

	-ss

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

[Petr Mladek]

On Thu 2018-05-31 19:52:15, Sergey Senozhatsky wrote:
> On (05/31/18 15:49), Maninder Singh wrote:
> > 
> > This patch make sure printing of log if loglevel at time of storing
> > log is greater than current console loglevel.
> > 
> > @why
> > In case of async printk, printk thread can miss logs because it checks
> > current log level at time of console_unlock.
> 
> Upstream printk has no printing kthread. And we also run
> printk()->console_unlock() with disabled preemption.

Yes, the comment was wrong but the problem is real. The console
handling is asynchronous even without the kthread. The current
console_lock owner is responsible for handling messages also
from other CPUs.

Best Regards,
Petr

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

[Petr Mladek]

On Thu 2018-05-31 15:49:11, Maninder Singh wrote:
> This patch make sure printing of log if loglevel at time of storing
> log is greater than current console loglevel.
> 
> @why
> In case of async printk, printk thread can miss logs because it checks
> current log level at time of console_unlock.
> 
> func()
> {
> ....
> ....
> 	console_verbose();  // user wants to have all the logs on console.
> 	pr_alert();
> 	pr_info();
> 	dump_backtrace(); // prints with default loglevel.
> 	pr_info();
> 	pr_emerg();
> 	pr_info();
> 	...
> 	...
> 	...
> 	pr_info();
> 	console_silent(); // stop all logs from printing on console.
> }
> 
> Now if printk thread is scheduled after setting console loglevel
> to silent, then user's requirement will be in waste, because it will not
> print logs on console at time of printk thread scheduling.

A better text would be something like:

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

> @how
> use one bit of flags field to store whether its console print
> or not(console_print) by checking current console loglevel with 
> message's level at time of log.
> At time of print check this flag for printing message on console.
> 
> Signed-off-by: Vaneet Narang <v.narang@samsung.com>
> Signed-off-by: Maninder Singh <maninder1.s@samsung.com>
> ---
>  kernel/printk/printk.c | 33 +++++++++++++++++++++++----------
>  1 file changed, 23 insertions(+), 10 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index ab15903..4e0be66e 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -360,8 +360,16 @@ struct printk_log {
>  	u16 text_len;		/* length of text buffer */
>  	u16 dict_len;		/* length of dictionary buffer */
>  	u8 facility;		/* syslog facility */
> -	u8 flags:5;		/* internal record flags */
> +	u8 flags:4;		/* internal record flags */
>  	u8 level:3;		/* syslog level */
> +	/*
> +	 * whether to print this msg on console or not?
> +	 * due to async printk, printk thread can miss
> +	 * prints at the time of console_flush because of
> +	 * change in print level afterwards.
> +	 */
> +	u8 console_print:1;

We should be careful with changing the structure. It is accessed
by external tools, like "crash".

IMHO, it is perfectly fine to handle this by a flag, e.g.
add LOG_CON_SUPPRESS.

> +
>  }
>  #ifdef CONFIG_HAVE_EFFICIENT_UNALIGNED_ACCESS
>  __packed __aligned(4)
> @@ -623,7 +631,12 @@ static int log_store(int facility, int level,
>  	msg->dict_len = dict_len;
>  	msg->facility = facility;
>  	msg->level = level & 7;
> -	msg->flags = flags & 0x1f;
> +	if (msg->level >= console_loglevel)
> +		msg->console_print = 0;
> +	else
> +		msg->console_print = 1;

We are going to decide about the visibility when the message is
stored. Let's handle it completely and make it easier later.

We could keep suppress_message_printing() as is and do the following
in vprintk_emit():

	if (suppress_message_printing(level)
		lflags |= LOG_CON_SUPPRESS;

> @@ -2354,7 +2367,7 @@ void console_unlock(void)
>  			break;
>  
>  		msg = log_from_idx(console_idx);
> -		if (suppress_message_printing(msg->level)) {
> +		if (suppress_message_printing(msg->console_print)) {

Then it is enough to do

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

Best Regards,
Petr

  			/*
>  			 * Skip record we have buffered and already printed
>  			 * directly to the console when we received it, and
> -- 
> 1.9.1
> 

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

[Sergey Senozhatsky]

On (05/31/18 14:21), Petr Mladek wrote:
> > 
> > Upstream printk has no printing kthread. And we also run
> > printk()->console_unlock() with disabled preemption.
> 
> Yes, the comment was wrong

Yes, that was the only thing I meant.
I really didn't have any time to look at the patch yesterday, just
commented on the most obvious thing.

> but the problem is real.

Yep, could be. But not exactly the way it is described in the commit
messages and the patch does not fully address the problem.

The patch assumes that all those events happen sequentially. While
in reality they can happen in parallel on different CPUs.

Example:

	CPU0					CPU1

	set console verbose

	dump_backtrace()
	{
		// for (;;)  print frames
		printk("%pS\n", frame0);
		printk("%pS\n", frame1);
		printk("%pS\n", frame2);
		printk("%pS\n", frame3);
		...				console_loglevel = CONSOLE_LOGLEVEL_SILENT;
		printk("%pS\n", frame12);
		printk("%pS\n", frame13);
	}

Part of backtrace or the entire backtrace will be missed, because
we read the global console_loglevel. The problem is still there.

> The console handling is asynchronous even without the kthread.
> The current console_lock owner is responsible for handling messages
> also from other CPUs.

A nitpick: that's another thing to improve in the commit message, because
   I don't see that console_silent() race in the upstream kernel. We even
   don't have any users of console_silent() function. The only thing that
   ever sets console_loglevel to CONSOLE_LOGLEVEL_SILENT is
   kernel/debug/kdb/kdb_io.c


Now, there is a bunch of places that manually set console_loglevel.
At a glance, __handle_sysrq() *seems* to be interesting:

---

void __handle_sysrq(int key, bool check_mask)
{
	struct sysrq_key_op *op_p;
	int orig_log_level;
	int i;

	rcu_sysrq_start();
	rcu_read_lock();
	/*
~	 * Raise the apparent loglevel to maximum so that the sysrq header
~	 * is shown to provide the user with positive feedback.  We do not
~	 * 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;
	pr_info("SysRq : ");

        op_p = __sysrq_get_key_op(key);
        if (op_p) {
		/*
		 * Should we check for enabled operations (/proc/sysrq-trigger
		 * 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);
			console_loglevel = orig_log_level;
			op_p->handler(key);
		} else {
			pr_cont("This sysrq operation is disabled.\n");
		}
	} else {
		pr_cont("HELP : ");
		/* Only print the help msg once per handler */
		for (i = 0; i < ARRAY_SIZE(sysrq_key_table); i++) {
			if (sysrq_key_table[i]) {
				int j;

				for (j = 0; sysrq_key_table[i] !=
						sysrq_key_table[j]; j++)
					;
				if (j != i)
					continue;
				pr_cont("%s ", sysrq_key_table[i]->help_msg);
			}
		}
		pr_cont("\n");
~		console_loglevel = orig_log_level;
	}
	rcu_read_unlock();
	rcu_sysrq_end();
}

---

But only at a glance... In fact, it raises the loglevel to maximum only
to printk() "This sysrq operation is disabled" or "HELP: " and help_msg
messages. The sysrq handler itself is executed under orig_log_level
loglevel. So it doesn't look like we are loosing anything super-critical,
after all.


This case is very interesting:

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;

		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;
		atomic_set(&uv_nmi_slave_continue, SLAVE_EXIT);
		for_each_online_cpu(tcpu) {
			if (cpumask_test_cpu(tcpu, uv_nmi_cpu_mask))
				ignored++;
			else if (tcpu == cpu)
				uv_nmi_dump_state_cpu(tcpu, regs);
			else
				uv_nmi_trigger_dump(tcpu);
		}
		if (ignored)
			pr_alert("UV: %d CPUs ignored NMI\n", ignored);

		console_loglevel = saved_console_loglevel;
		pr_alert("UV: process trace complete\n");
	} else {
		while (!atomic_read(&uv_nmi_slave_continue))
			cpu_relax();
		while (this_cpu_read(uv_cpu_nmi.state) != UV_NMI_STATE_DUMP)
			cpu_relax();
		uv_nmi_dump_state_cpu(cpu, regs);
	}
	uv_nmi_sync_exit(master);
}

And it seems to be broken anyway... uv_nmi_dump_state() relies on printk()
to do a direct console_unlock() call from NMI. We don't do it. Apart from
that, printk() is in printk_nmi() context when we call this function, which
sometimes can use printk_deferred() directly [loglevel messages bit will be
useful here], but sometimes it stores the messages in per-CPU buffers and
flushes them to the logbuf later - we don't carry the must-be-printed bit
with every printk_safe/printk_nmi message and as of now there is no way for
to forcibly set it [because it's set automatically in log_store() after
msg->level >= console_loglevel check].

So I'd say that most likely the following scenarios can suffer:

- NMI comes in, sets loglevel to X, printk-s some data, restores the
  loglevel back to Y
- IRQ comes in [like sysrq, etc] comes in and does the same thing
- software exception comes in and does the same thing [e.g. bust_spinlocks()
  at arch/s390/mm/fault.c]

IOW, the following scenario

	CPUA

	something happens
	set console loglevel
	printk			0. writes to the logbuf, e.g. printk_deferred()
				1. writes to the logbuf AND calls console_unlock()
				2. writes to printk_safe per-CPU buffer
				3. writes to printk_nmi per-CPU buffer
	...
	restore loglevel

This is how I see the problem at the moment. May be I'm missing something.

Would be great to see more real cases when it actually hits us and more
analysis, please.

	-ss

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

[Vaneet Narang]

Hi Sergey,

>> but the problem is real.
>
>Yep, could be. But not exactly the way it is described in the commit
>messages and the patch does not fully address the problem.
>
>The patch assumes that all those events happen sequentially. While
>in reality they can happen in parallel on different CPUs.
>
>Example:
>
> CPU0     CPU1
>
> set console verbose
>
> dump_backtrace()
> {
>  // for (;;)  print frames
>  printk("%pS\n", frame0);
>  printk("%pS\n", frame1);
>  printk("%pS\n", frame2);
>  printk("%pS\n", frame3);
>  ...    console_loglevel = CONSOLE_LOGLEVEL_SILENT;
>  printk("%pS\n", frame12);
>  printk("%pS\n", frame13);
> }
>

This is not printk issue, its printk usage issue. User need to handle this part using some protection.

What we highlighted is issue related to printk, Where usage is correct 
but still printk can miss some logs due to printk design of asynchronous printing.


>Part of backtrace or the entire backtrace will be missed, because
>we read the global console_loglevel. The problem is still there.
>
>> The console handling is asynchronous even without the kthread.
>> The current console_lock owner is responsible for handling messages
>> also from other CPUs.
>
>A nitpick: that's another thing to improve in the commit message, because
>   I don't see that console_silent() race in the upstream kernel. We even
>   don't have any users of console_silent() function. The only thing that
>   ever sets console_loglevel to CONSOLE_LOGLEVEL_SILENT is
>   kernel/debug/kdb/kdb_io.c
>

Issue is not related to console_silent() user, Issue is with dynamic console log level handling.
Which can be done using dmesg as well.
For example:
dmesg -n 7 
"Run some scenario to capture all the kernel logs"
dmesg -n 1

I may end up not getting all the logs if my console flush is slow & 
dmesg -n 1 got excuted before flush .


Thanks & Regards,
Vaneet Narang

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

[Petr Mladek]

On Fri 2018-06-01 13:40:50, Sergey Senozhatsky wrote:
> On (05/31/18 14:21), Petr Mladek wrote:
> > > 
> > > Upstream printk has no printing kthread. And we also run
> > > printk()->console_unlock() with disabled preemption.
> > 
> > Yes, the comment was wrong
> 
> Yes, that was the only thing I meant.
> I really didn't have any time to look at the patch yesterday, just
> commented on the most obvious thing.

Fair enough.

> > but the problem is real.
> 
> Yep, could be. But not exactly the way it is described in the commit
> messages and the patch does not fully address the problem.
> 
> The patch assumes that all those events happen sequentially. While
> in reality they can happen in parallel on different CPUs.
> 
> Example:
> 
> 	CPU0					CPU1
> 
> 	set console verbose
> 
> 	dump_backtrace()
> 	{
> 		// for (;;)  print frames
> 		printk("%pS\n", frame0);
> 		printk("%pS\n", frame1);
> 		printk("%pS\n", frame2);
> 		printk("%pS\n", frame3);
> 		...				console_loglevel = CONSOLE_LOGLEVEL_SILENT;
> 		printk("%pS\n", frame12);
> 		printk("%pS\n", frame13);
> 	}
> 
> Part of backtrace or the entire backtrace will be missed, because
> we read the global console_loglevel. The problem is still there.

[...]

> So I'd say that most likely the following scenarios can suffer:
> 
> - NMI comes in, sets loglevel to X, printk-s some data, restores the
>   loglevel back to Y
> - IRQ comes in [like sysrq, etc] comes in and does the same thing
> - software exception comes in and does the same thing [e.g. bust_spinlocks()
>   at arch/s390/mm/fault.c]


My view is:

The race with another printk() (console_lock owner) is much more
likely than a race between two CPUs manipulating console_loglevel.

The proposed patch seems to be in the right direction. It is supposed
to fix the most likely scenario. We could block it and request full
solution but I wonder if it is worth it.

I am personally fine with this partial solution for now. We could
always make it better if people meet the other scenarios.

Best Regards,
Petr

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

[Petr Mladek]

On Fri 2018-06-01 10:53:56, Petr Mladek wrote:
> On Fri 2018-06-01 13:40:50, Sergey Senozhatsky wrote:
> > On (05/31/18 14:21), Petr Mladek wrote:
> > > > 
> > > > Upstream printk has no printing kthread. And we also run
> > > > printk()->console_unlock() with disabled preemption.
> > > 
> > > Yes, the comment was wrong
> > 
> > Yes, that was the only thing I meant.
> > I really didn't have any time to look at the patch yesterday, just
> > commented on the most obvious thing.
> 
> Fair enough.
> 
> > > but the problem is real.
> > 
> > Yep, could be. But not exactly the way it is described in the commit
> > messages and the patch does not fully address the problem.
> > 
> > The patch assumes that all those events happen sequentially. While
> > in reality they can happen in parallel on different CPUs.
> > 
> > Example:
> > 
> > 	CPU0					CPU1
> > 
> > 	set console verbose
> > 
> > 	dump_backtrace()
> > 	{
> > 		// for (;;)  print frames
> > 		printk("%pS\n", frame0);
> > 		printk("%pS\n", frame1);
> > 		printk("%pS\n", frame2);
> > 		printk("%pS\n", frame3);
> > 		...				console_loglevel = CONSOLE_LOGLEVEL_SILENT;
> > 		printk("%pS\n", frame12);
> > 		printk("%pS\n", frame13);
> > 	}
> > 
> > Part of backtrace or the entire backtrace will be missed, because
> > we read the global console_loglevel. The problem is still there.
> 
> [...]
> 
> > So I'd say that most likely the following scenarios can suffer:
> > 
> > - NMI comes in, sets loglevel to X, printk-s some data, restores the
> >   loglevel back to Y
> > - IRQ comes in [like sysrq, etc] comes in and does the same thing
> > - software exception comes in and does the same thing [e.g. bust_spinlocks()
> >   at arch/s390/mm/fault.c]

I forgot to say that it was a great point and analyze.

> My view is:
> 
> The race with another printk() (console_lock owner) is much more
> likely than a race between two CPUs manipulating console_loglevel.
> 
> The proposed patch seems to be in the right direction. It is supposed
> to fix the most likely scenario. We could block it and request full
> solution but I wonder if it is worth it.
> 
> I am personally fine with this partial solution for now. We could
> always make it better if people meet the other scenarios.

I am still fine with the partial solution. Well, I will think
more about it before approving any patch.

Best Regards,
Petr

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

[Sergey Senozhatsky]

On (06/01/18 10:53), Petr Mladek wrote:
> [...]
> 
> > So I'd say that most likely the following scenarios can suffer:
> > 
> > - NMI comes in, sets loglevel to X, printk-s some data, restores the
> >   loglevel back to Y
> > - IRQ comes in [like sysrq, etc] comes in and does the same thing
> > - software exception comes in and does the same thing [e.g. bust_spinlocks()
> >   at arch/s390/mm/fault.c]
> 
> 
> My view is:
> 
> The race with another printk() (console_lock owner) is much more
> likely than a race between two CPUs manipulating console_loglevel.

The race with console_loglevel manipulation from another CPU was not
the main point [it is unlikely, like I said in my "nitpick"].
The point was

	NMI / printk_safe section

	saved_console_loglevel = console_loglevel
	console_loglevel = A

	printk
	printk
	printk

	console_loglevel = saved_console_loglevel
	iret

Is not handled.

> The proposed patch seems to be in the right direction. It is supposed
> to fix the most likely scenario.

Could be.

> I am personally fine with this partial solution for now. We could
> always make it better if people meet the other scenarios.

I don't have objections. But I'd prefer to see real uses cases and
to know why partial solution is good enough in this case, even though
we know that NMI / printk_safe() messages may be lost due to very same
problem.

	-ss

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

[Sergey Senozhatsky]

Hello,

On (06/01/18 14:12), Vaneet Narang wrote:
> > CPU0                            CPU1
> >
> > set console verbose
> >
> > dump_backtrace()
> > {
> >  // for (;;)  print frames
> >  printk("%pS\n", frame0);
> >  printk("%pS\n", frame1);
> >  printk("%pS\n", frame2);
> >  printk("%pS\n", frame3);
> >  ...                            console_loglevel = CONSOLE_LOGLEVEL_SILENT;
> >  printk("%pS\n", frame12);
> >  printk("%pS\n", frame13);
> > }
> >
> 
> This is not printk issue, its printk usage issue. User need to handle this part using some protection.
> 
> What we highlighted is issue related to printk, Where usage is correct 
> but still printk can miss some logs due to printk design of asynchronous printing.

Yeah, I understand your example from the commit message. What I said was
"the patch does not fully address the problem". One way or another we still
can miss logs due to the very same problem: either console_loglevel
manipulation on another CPU, or printk_safe(), etc. May be there other
scenarios that are broken.

So if we are going to apply the patch [I don't have real objections, and
Petr seems to be fine], then I'd probably ask for a better commit messages.
Namely, I really want to document cases that are not addressed and are
still known to be broken.

	-ss

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

[Sergey Senozhatsky]

On (06/01/18 11:09), Petr Mladek wrote:
> > [...]
> > 
> > > So I'd say that most likely the following scenarios can suffer:
> > > 
> > > - NMI comes in, sets loglevel to X, printk-s some data, restores the
> > >   loglevel back to Y
> > > - IRQ comes in [like sysrq, etc] comes in and does the same thing
> > > - software exception comes in and does the same thing [e.g. bust_spinlocks()
> > >   at arch/s390/mm/fault.c]
> 
> I forgot to say that it was a great point and analyze.

Thanks :)

> > My view is:
> > 
> > The race with another printk() (console_lock owner) is much more
> > likely than a race between two CPUs manipulating console_loglevel.
> > 
> > The proposed patch seems to be in the right direction. It is supposed
> > to fix the most likely scenario. We could block it and request full
> > solution but I wonder if it is worth it.
> > 
> > I am personally fine with this partial solution for now. We could
> > always make it better if people meet the other scenarios.
> 
> I am still fine with the partial solution. Well, I will think
> more about it before approving any patch.

Same here. I don't mind the patch and can agree with this partial
solution [may be we are missing more cases?]. Probably will need
a little bit more time.

	-ss