* [PATCH 2/2] printk: make sure to print log on console. [not found] <CGME20180531102246epcas5p2f1cbc6ff217172e12e2f78bb88eb4a7e@epcas5p2.samsung.com> @ 2018-05-31 10:19 ` Maninder Singh 2018-05-31 10:52 ` Sergey Senozhatsky 2018-05-31 13:27 ` Petr Mladek 0 siblings, 2 replies; 11+ messages in thread From: Maninder Singh @ 2018-05-31 10:19 UTC (permalink / raw) To: pmladek, sergey.senozhatsky, rostedt Cc: linux-kernel, a.sahrawat, pankaj.m, v.narang, 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 ^ permalink raw reply related [flat|nested] 11+ messages in thread
* Re: [PATCH 2/2] printk: make sure to print log on console. 2018-05-31 10:19 ` [PATCH 2/2] printk: make sure to print log on console Maninder Singh @ 2018-05-31 10:52 ` Sergey Senozhatsky 2018-05-31 12:21 ` Petr Mladek 2018-05-31 13:27 ` Petr Mladek 1 sibling, 1 reply; 11+ messages in thread From: Sergey Senozhatsky @ 2018-05-31 10:52 UTC (permalink / raw) To: Maninder Singh Cc: pmladek, sergey.senozhatsky, rostedt, linux-kernel, a.sahrawat, pankaj.m, v.narang 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 ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH 2/2] printk: make sure to print log on console. 2018-05-31 10:52 ` Sergey Senozhatsky @ 2018-05-31 12:21 ` Petr Mladek 2018-06-01 4:40 ` Sergey Senozhatsky [not found] ` <CGME20180531102246epcas5p2f1cbc6ff217172e12e2f78bb88eb4a7e@epcms5p5> 0 siblings, 2 replies; 11+ messages in thread From: Petr Mladek @ 2018-05-31 12:21 UTC (permalink / raw) To: Sergey Senozhatsky Cc: Maninder Singh, sergey.senozhatsky, rostedt, linux-kernel, a.sahrawat, pankaj.m, v.narang 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 ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH 2/2] printk: make sure to print log on console. 2018-05-31 12:21 ` Petr Mladek @ 2018-06-01 4:40 ` Sergey Senozhatsky 2018-06-01 8:53 ` Petr Mladek [not found] ` <CGME20180531102246epcas5p2f1cbc6ff217172e12e2f78bb88eb4a7e@epcms5p5> 1 sibling, 1 reply; 11+ messages in thread From: Sergey Senozhatsky @ 2018-06-01 4:40 UTC (permalink / raw) To: Petr Mladek Cc: Sergey Senozhatsky, Maninder Singh, sergey.senozhatsky, rostedt, linux-kernel, a.sahrawat, pankaj.m, v.narang 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 ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH 2/2] printk: make sure to print log on console. 2018-06-01 4:40 ` Sergey Senozhatsky @ 2018-06-01 8:53 ` Petr Mladek 2018-06-01 9:09 ` Petr Mladek 2018-06-01 9:18 ` Sergey Senozhatsky 0 siblings, 2 replies; 11+ messages in thread From: Petr Mladek @ 2018-06-01 8:53 UTC (permalink / raw) To: Sergey Senozhatsky Cc: Maninder Singh, sergey.senozhatsky, rostedt, linux-kernel, a.sahrawat, pankaj.m, v.narang 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 ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH 2/2] printk: make sure to print log on console. 2018-06-01 8:53 ` Petr Mladek @ 2018-06-01 9:09 ` Petr Mladek 2018-06-01 9:37 ` Sergey Senozhatsky 2018-06-01 9:18 ` Sergey Senozhatsky 1 sibling, 1 reply; 11+ messages in thread From: Petr Mladek @ 2018-06-01 9:09 UTC (permalink / raw) To: Sergey Senozhatsky Cc: Maninder Singh, sergey.senozhatsky, rostedt, linux-kernel, a.sahrawat, pankaj.m, v.narang 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 ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH 2/2] printk: make sure to print log on console. 2018-06-01 9:09 ` Petr Mladek @ 2018-06-01 9:37 ` Sergey Senozhatsky 0 siblings, 0 replies; 11+ messages in thread From: Sergey Senozhatsky @ 2018-06-01 9:37 UTC (permalink / raw) To: Petr Mladek Cc: Sergey Senozhatsky, Maninder Singh, sergey.senozhatsky, rostedt, linux-kernel, a.sahrawat, pankaj.m, v.narang 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 ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH 2/2] printk: make sure to print log on console. 2018-06-01 8:53 ` Petr Mladek 2018-06-01 9:09 ` Petr Mladek @ 2018-06-01 9:18 ` Sergey Senozhatsky 1 sibling, 0 replies; 11+ messages in thread From: Sergey Senozhatsky @ 2018-06-01 9:18 UTC (permalink / raw) To: Petr Mladek Cc: Sergey Senozhatsky, Maninder Singh, sergey.senozhatsky, rostedt, linux-kernel, a.sahrawat, pankaj.m, v.narang 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 ^ permalink raw reply [flat|nested] 11+ messages in thread
[parent not found: <CGME20180531102246epcas5p2f1cbc6ff217172e12e2f78bb88eb4a7e@epcms5p5>]
* Re: [PATCH 2/2] printk: make sure to print log on console. [not found] ` <CGME20180531102246epcas5p2f1cbc6ff217172e12e2f78bb88eb4a7e@epcms5p5> @ 2018-06-01 8:42 ` Vaneet Narang 2018-06-01 9:34 ` Sergey Senozhatsky 0 siblings, 1 reply; 11+ messages in thread From: Vaneet Narang @ 2018-06-01 8:42 UTC (permalink / raw) To: Petr Mladek, Sergey Senozhatsky Cc: Maninder Singh, sergey.senozhatsky, rostedt, linux-kernel, AMIT SAHRAWAT, PANKAJ MISHRA 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 ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH 2/2] printk: make sure to print log on console. 2018-06-01 8:42 ` Vaneet Narang @ 2018-06-01 9:34 ` Sergey Senozhatsky 0 siblings, 0 replies; 11+ messages in thread From: Sergey Senozhatsky @ 2018-06-01 9:34 UTC (permalink / raw) To: Vaneet Narang Cc: Petr Mladek, Sergey Senozhatsky, Maninder Singh, sergey.senozhatsky, rostedt, linux-kernel, AMIT SAHRAWAT, PANKAJ MISHRA 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 ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH 2/2] printk: make sure to print log on console. 2018-05-31 10:19 ` [PATCH 2/2] printk: make sure to print log on console Maninder Singh 2018-05-31 10:52 ` Sergey Senozhatsky @ 2018-05-31 13:27 ` Petr Mladek 1 sibling, 0 replies; 11+ messages in thread From: Petr Mladek @ 2018-05-31 13:27 UTC (permalink / raw) To: Maninder Singh Cc: sergey.senozhatsky, rostedt, linux-kernel, a.sahrawat, pankaj.m, v.narang 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 > ^ permalink raw reply [flat|nested] 11+ messages in thread
end of thread, other threads:[~2018-06-01 9:37 UTC | newest] Thread overview: 11+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- [not found] <CGME20180531102246epcas5p2f1cbc6ff217172e12e2f78bb88eb4a7e@epcas5p2.samsung.com> 2018-05-31 10:19 ` [PATCH 2/2] printk: make sure to print log on console Maninder Singh 2018-05-31 10:52 ` Sergey Senozhatsky 2018-05-31 12:21 ` Petr Mladek 2018-06-01 4:40 ` Sergey Senozhatsky 2018-06-01 8:53 ` Petr Mladek 2018-06-01 9:09 ` Petr Mladek 2018-06-01 9:37 ` Sergey Senozhatsky 2018-06-01 9:18 ` Sergey Senozhatsky [not found] ` <CGME20180531102246epcas5p2f1cbc6ff217172e12e2f78bb88eb4a7e@epcms5p5> 2018-06-01 8:42 ` Vaneet Narang 2018-06-01 9:34 ` Sergey Senozhatsky 2018-05-31 13:27 ` Petr Mladek
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).