LKML Archive on lore.kernel.org
help / color / mirror / Atom feed
* [PATCH] printk: Monitor change of console loglevel.
@ 2019-05-10 15:19 Tetsuo Handa
  2019-05-14  9:19 ` Sergey Senozhatsky
  2019-05-24 17:17 ` Linus Torvalds
  0 siblings, 2 replies; 11+ messages in thread
From: Tetsuo Handa @ 2019-05-10 15:19 UTC (permalink / raw)
  To: Andrew Morton
  Cc: linux-kernel, Tetsuo Handa, Dmitry Vyukov, Petr Mladek,
	Sergey Senozhatsky

We are seeing syzbot reports [1] where printk() messages prior to panic()
are missing for unknown reason. To test whether it is due to some testcase
changing console loglevel, let's panic() as soon as console loglevel has
changed. This patch is intended for testing on linux-next.git only, and
will be removed after we found what is wrong.

[1] https://lkml.kernel.org/r/127c9c3b-f878-174f-7065-66dc50fcabcf@i-love.sakura.ne.jp

Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
Cc: Dmitry Vyukov <dvyukov@google.com>
Cc: Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
Cc: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk.c | 20 ++++++++++++++++++++
 1 file changed, 20 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index e1e8250..f0b9463 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -3338,3 +3338,23 @@ void kmsg_dump_rewind(struct kmsg_dumper *dumper)
 EXPORT_SYMBOL_GPL(kmsg_dump_rewind);
 
 #endif
+
+#ifdef CONFIG_DEBUG_AID_FOR_SYZBOT
+static int initial_loglevel;
+static void check_loglevel(struct timer_list *timer)
+{
+	if (console_loglevel < initial_loglevel)
+		panic("Console loglevel changed (%d->%d)!", initial_loglevel,
+		      console_loglevel);
+	mod_timer(timer, jiffies + HZ);
+}
+static int __init loglevelcheck_init(void)
+{
+	static DEFINE_TIMER(timer, check_loglevel);
+
+	initial_loglevel = console_loglevel;
+	mod_timer(&timer, jiffies + HZ);
+	return 0;
+}
+late_initcall(loglevelcheck_init);
+#endif
-- 
1.8.3.1

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

* Re: [PATCH] printk: Monitor change of console loglevel.
  2019-05-10 15:19 [PATCH] printk: Monitor change of console loglevel Tetsuo Handa
@ 2019-05-14  9:19 ` Sergey Senozhatsky
  2019-05-15 14:32   ` Tetsuo Handa
  2019-05-24 17:17 ` Linus Torvalds
  1 sibling, 1 reply; 11+ messages in thread
From: Sergey Senozhatsky @ 2019-05-14  9:19 UTC (permalink / raw)
  To: Tetsuo Handa
  Cc: Andrew Morton, linux-kernel, Dmitry Vyukov, Petr Mladek,
	Sergey Senozhatsky, Steven Rostedt

On (05/11/19 00:19), Tetsuo Handa wrote:
> We are seeing syzbot reports [1] where printk() messages prior to panic()
> are missing for unknown reason. To test whether it is due to some testcase
> changing console loglevel, let's panic() as soon as console loglevel has
> changed. This patch is intended for testing on linux-next.git only, and
> will be removed after we found what is wrong.

Clone linux-next, apply the patch, push to a github/gitlab repo,
configure syzbot to pull from github/gitlab? Adding temp patches
to linux-next is hard and apparently not exactly what linux-next
is used for these days.

	-ss

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

* Re: [PATCH] printk: Monitor change of console loglevel.
  2019-05-14  9:19 ` Sergey Senozhatsky
@ 2019-05-15 14:32   ` Tetsuo Handa
  2019-05-23  9:56     ` Tetsuo Handa
  0 siblings, 1 reply; 11+ messages in thread
From: Tetsuo Handa @ 2019-05-15 14:32 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Andrew Morton, linux-kernel, Dmitry Vyukov, Petr Mladek, Steven Rostedt

On 2019/05/14 18:19, Sergey Senozhatsky wrote:
> On (05/11/19 00:19), Tetsuo Handa wrote:
>> We are seeing syzbot reports [1] where printk() messages prior to panic()
>> are missing for unknown reason. To test whether it is due to some testcase
>> changing console loglevel, let's panic() as soon as console loglevel has
>> changed. This patch is intended for testing on linux-next.git only, and
>> will be removed after we found what is wrong.
> 
> Clone linux-next, apply the patch, push to a github/gitlab repo,
> configure syzbot to pull from github/gitlab?

I think that it is practically impossible to do so from the point of
view of automation.

>                                              Adding temp patches
> to linux-next is hard and apparently not exactly what linux-next
> is used for these days.

Currently Andrew Morton is carrying "linux-next.git only" patches
(a.k.a. CONFIG_DEBUG_AID_FOR_SYZBOT patches) via mmotm tree.

It would be nice if linux-next.git can directly import temp patches
using "quilt push -a" on patches from a subversion repository. Then,
we can casually add/remove/update temp patches like this.


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

* Re: [PATCH] printk: Monitor change of console loglevel.
  2019-05-15 14:32   ` Tetsuo Handa
@ 2019-05-23  9:56     ` Tetsuo Handa
  2019-05-24  7:55       ` Dmitry Vyukov
  0 siblings, 1 reply; 11+ messages in thread
From: Tetsuo Handa @ 2019-05-23  9:56 UTC (permalink / raw)
  To: Andrew Morton
  Cc: Sergey Senozhatsky, linux-kernel, Dmitry Vyukov, Petr Mladek,
	Steven Rostedt

Well, the culprit of this problem might be syz_execute_func().

  https://twitter.com/ed_maste/status/1131165065485398016

Then, blacklisting specific syscalls/arguments might not work.
We will need to guard specific paths on the kernel side using
some kernel config option...

Anyway, Andrew, will you send this patch to linux-next.git ?
syzbot would identify which syz_execute_func() call is triggering
this problem.

From 96e0741839f56c461f85d83e20bf5ae6baac9a3a Mon Sep 17 00:00:00 2001
From: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
Date: Thu, 23 May 2019 05:57:52 +0900
Subject: [PATCH] printk: Monitor change of console loglevel.

We are seeing syzbot reports [1] where printk() messages prior to panic()
are missing for unknown reason. To test whether it is due to some testcase
changing console loglevel, let's panic() as soon as console loglevel has
changed. This patch is intended for testing on linux-next.git only, and
will be removed after we found what is wrong.

[1] https://lkml.kernel.org/r/127c9c3b-f878-174f-7065-66dc50fcabcf@i-love.sakura.ne.jp

Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
Cc: Dmitry Vyukov <dvyukov@google.com>
Cc: Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
Cc: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk.c | 20 ++++++++++++++++++++
 1 file changed, 20 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 1888f6a..5326015 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -3343,3 +3343,23 @@ void kmsg_dump_rewind(struct kmsg_dumper *dumper)
 EXPORT_SYMBOL_GPL(kmsg_dump_rewind);
 
 #endif
+
+#ifdef CONFIG_DEBUG_AID_FOR_SYZBOT
+static int initial_loglevel;
+static void check_loglevel(struct timer_list *timer)
+{
+	if (console_loglevel < initial_loglevel)
+		panic("Console loglevel changed (%d->%d)!", initial_loglevel,
+		      console_loglevel);
+	mod_timer(timer, jiffies + HZ);
+}
+static int __init loglevelcheck_init(void)
+{
+	static DEFINE_TIMER(timer, check_loglevel);
+
+	initial_loglevel = console_loglevel;
+	mod_timer(&timer, jiffies + HZ);
+	return 0;
+}
+late_initcall(loglevelcheck_init);
+#endif
-- 
1.8.3.1

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

* Re: [PATCH] printk: Monitor change of console loglevel.
  2019-05-23  9:56     ` Tetsuo Handa
@ 2019-05-24  7:55       ` Dmitry Vyukov
  2019-05-24 10:35         ` Tetsuo Handa
  0 siblings, 1 reply; 11+ messages in thread
From: Dmitry Vyukov @ 2019-05-24  7:55 UTC (permalink / raw)
  To: Tetsuo Handa
  Cc: Andrew Morton, Sergey Senozhatsky, LKML, Petr Mladek, Steven Rostedt

On Thu, May 23, 2019 at 11:57 AM Tetsuo Handa
<penguin-kernel@i-love.sakura.ne.jp> wrote:
>
> Well, the culprit of this problem might be syz_execute_func().
>
>   https://twitter.com/ed_maste/status/1131165065485398016
>
> Then, blacklisting specific syscalls/arguments might not work.
> We will need to guard specific paths on the kernel side using
> some kernel config option...

Yes, that's a nasty issue. We could stop running random code, or
setuid into nobody, but then we will lose lots of test coverage...

> Anyway, Andrew, will you send this patch to linux-next.git ?
> syzbot would identify which syz_execute_func() call is triggering
> this problem.
>
> From 96e0741839f56c461f85d83e20bf5ae6baac9a3a Mon Sep 17 00:00:00 2001
> From: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
> Date: Thu, 23 May 2019 05:57:52 +0900
> Subject: [PATCH] printk: Monitor change of console loglevel.
>
> We are seeing syzbot reports [1] where printk() messages prior to panic()
> are missing for unknown reason. To test whether it is due to some testcase
> changing console loglevel, let's panic() as soon as console loglevel has
> changed. This patch is intended for testing on linux-next.git only, and
> will be removed after we found what is wrong.
>
> [1] https://lkml.kernel.org/r/127c9c3b-f878-174f-7065-66dc50fcabcf@i-love.sakura.ne.jp
>
> Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
> Cc: Dmitry Vyukov <dvyukov@google.com>
> Cc: Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
> Cc: Petr Mladek <pmladek@suse.com>
> ---
>  kernel/printk/printk.c | 20 ++++++++++++++++++++
>  1 file changed, 20 insertions(+)
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 1888f6a..5326015 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -3343,3 +3343,23 @@ void kmsg_dump_rewind(struct kmsg_dumper *dumper)
>  EXPORT_SYMBOL_GPL(kmsg_dump_rewind);
>
>  #endif
> +
> +#ifdef CONFIG_DEBUG_AID_FOR_SYZBOT
> +static int initial_loglevel;
> +static void check_loglevel(struct timer_list *timer)
> +{
> +       if (console_loglevel < initial_loglevel)
> +               panic("Console loglevel changed (%d->%d)!", initial_loglevel,
> +                     console_loglevel);
> +       mod_timer(timer, jiffies + HZ);
> +}
> +static int __init loglevelcheck_init(void)
> +{
> +       static DEFINE_TIMER(timer, check_loglevel);
> +
> +       initial_loglevel = console_loglevel;
> +       mod_timer(&timer, jiffies + HZ);
> +       return 0;
> +}
> +late_initcall(loglevelcheck_init);
> +#endif
> --
> 1.8.3.1

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

* Re: [PATCH] printk: Monitor change of console loglevel.
  2019-05-24  7:55       ` Dmitry Vyukov
@ 2019-05-24 10:35         ` Tetsuo Handa
  0 siblings, 0 replies; 11+ messages in thread
From: Tetsuo Handa @ 2019-05-24 10:35 UTC (permalink / raw)
  To: Dmitry Vyukov
  Cc: Andrew Morton, Sergey Senozhatsky, LKML, Petr Mladek,
	Steven Rostedt, Linus Torvalds

On 2019/05/24 16:55, Dmitry Vyukov wrote:
> On Thu, May 23, 2019 at 11:57 AM Tetsuo Handa
> <penguin-kernel@i-love.sakura.ne.jp> wrote:
>>
>> Well, the culprit of this problem might be syz_execute_func().
>>
>>   https://twitter.com/ed_maste/status/1131165065485398016
>>
>> Then, blacklisting specific syscalls/arguments might not work.
>> We will need to guard specific paths on the kernel side using
>> some kernel config option...
> 
> Yes, that's a nasty issue. We could stop running random code, or
> setuid into nobody, but then we will lose lots of test coverage...
> 

I think that guarding specific paths on the kernel side is better.
TOMOYO already added CONFIG_SECURITY_TOMOYO_INSECURE_BUILTIN_SETTING for
avoid emitting WARNING: string and getting more test coverage. There are
other codes emitting WARNING: string that confuses syzbot. If we guard
critical paths like reboot/poweroff request that will destroy the target
VM instance, we can get more test coverage while reducing pointless reports.


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

* Re: [PATCH] printk: Monitor change of console loglevel.
  2019-05-10 15:19 [PATCH] printk: Monitor change of console loglevel Tetsuo Handa
  2019-05-14  9:19 ` Sergey Senozhatsky
@ 2019-05-24 17:17 ` Linus Torvalds
  2019-05-24 17:40   ` Joe Perches
  2019-05-25  0:14   ` Tetsuo Handa
  1 sibling, 2 replies; 11+ messages in thread
From: Linus Torvalds @ 2019-05-24 17:17 UTC (permalink / raw)
  To: Tetsuo Handa
  Cc: Andrew Morton, Linux List Kernel Mailing, Dmitry Vyukov,
	Petr Mladek, Sergey Senozhatsky

On Fri, May 10, 2019 at 8:19 AM Tetsuo Handa
<penguin-kernel@i-love.sakura.ne.jp> wrote:
>
> This patch is intended for testing on linux-next.git only, and
> will be removed after we found what is wrong.

Honestly, wouldn't it be much better to try to come up with a patch
that might be acceptable in general.

For example, how about a config option that just hardcodes
console_loglevel as a compile-time constant, and where you can't
change it at all? There are not that many paths that set the console
log-level, and the few that do could be made to use

    set_console_log_level(x);

instead of

    console_loglevel = x;

like they do.

We already have a number of loglevel config options, adding another
that says "fix log levels at compile time" doesn't sound too bad, and
I suspect a patch that introduces that set_console_log_level() kind of
model and just makes "console_loglevel" a constant #define wouldn't be
too ugly.

A config option or two that help syzbot doesn't sound like a bad idea to me.

Hmm?

                   Linus

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

* Re: [PATCH] printk: Monitor change of console loglevel.
  2019-05-24 17:17 ` Linus Torvalds
@ 2019-05-24 17:40   ` Joe Perches
  2019-05-24 17:55     ` Linus Torvalds
  2019-05-25  0:14   ` Tetsuo Handa
  1 sibling, 1 reply; 11+ messages in thread
From: Joe Perches @ 2019-05-24 17:40 UTC (permalink / raw)
  To: Linus Torvalds
  Cc: Andrew Morton, Linux List Kernel Mailing, Dmitry Vyukov,
	Petr Mladek, Sergey Senozhatsky

On Fri, 2019-05-24 at 10:17 -0700, Linus Torvalds wrote:
> > This patch is intended for testing on linux-next.git only, and
> > will be removed after we found what is wrong.
> 
> Honestly, wouldn't it be much better to try to come up with a patch
> that might be acceptable in general.
> 
> For example, how about a config option that just hardcodes
> console_loglevel as a compile-time constant, and where you can't
> change it at all? There are not that many paths that set the console
> log-level, and the few that do could be made to use
> 
>     set_console_log_level(x);
> 
> instead of
> 
>     console_loglevel = x;
> 
> like they do.
> 
> We already have a number of loglevel config options, adding another
> that says "fix log levels at compile time" doesn't sound too bad, and
> I suspect a patch that introduces that set_console_log_level() kind of
> model and just makes "console_loglevel" a constant #define wouldn't be
> too ugly.
> 
> A config option or two that help syzbot doesn't sound like a bad idea to me.
> 
> Hmm?

That could also help eliminate unnecessary pr_<foo> output
from object code.




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

* Re: [PATCH] printk: Monitor change of console loglevel.
  2019-05-24 17:40   ` Joe Perches
@ 2019-05-24 17:55     ` Linus Torvalds
  0 siblings, 0 replies; 11+ messages in thread
From: Linus Torvalds @ 2019-05-24 17:55 UTC (permalink / raw)
  To: Joe Perches
  Cc: Andrew Morton, Linux List Kernel Mailing, Dmitry Vyukov,
	Petr Mladek, Sergey Senozhatsky

On Fri, May 24, 2019 at 10:41 AM Joe Perches <joe@perches.com> wrote:
>
> That could also help eliminate unnecessary pr_<foo> output
> from object code.

Indeed. The small-config people might like it (if they haven't already
given up..)

              Linus

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

* Re: [PATCH] printk: Monitor change of console loglevel.
  2019-05-24 17:17 ` Linus Torvalds
  2019-05-24 17:40   ` Joe Perches
@ 2019-05-25  0:14   ` Tetsuo Handa
  2019-05-25  0:56     ` Joe Perches
  1 sibling, 1 reply; 11+ messages in thread
From: Tetsuo Handa @ 2019-05-25  0:14 UTC (permalink / raw)
  To: Linus Torvalds
  Cc: Andrew Morton, Linux List Kernel Mailing, Dmitry Vyukov,
	Petr Mladek, Sergey Senozhatsky, Joe Perches

On 2019/05/25 2:17, Linus Torvalds wrote:
> A config option or two that help syzbot doesn't sound like a bad idea to me.

Thanks for suggestion. I think that #ifdef'ing

  static bool suppress_message_printing(int level)
  {
  	return (level >= console_loglevel && !ignore_loglevel);
  }

is simpler. If the cause of unexpected change of console loglevel
turns out to be syz_execute_func(), we will want a config option
which controls suppress_message_printing() for syzbot. That option
would also be used for guarding printk("WARNING:" ...) users.

Well, syzbot does not want to use ignore_loglevel kernel command
line option because that option would generate too much output...

  https://lkml.kernel.org/r/CACT4Y+ay7nuT-7y2JARozV1s0VisuLdN6VT+w9OsEDs1PeBRoA@mail.gmail.com



On 2019/05/25 2:55, Linus Torvalds wrote:
> On Fri, May 24, 2019 at 10:41 AM Joe Perches <joe@perches.com> wrote:
> >
> > That could also help eliminate unnecessary pr_<foo> output
> > from object code.
> 
> Indeed. The small-config people might like it (if they haven't already
> given up..)

Do you mean doing e.g.

  #define pr_debug(fmt, ...) no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)

depending on the minimal console loglevel kernel config option? Then, OK.
But callers using e.g. printk(KERN_DEBUG ...) and printk(KERN_SOH "%u" ...)
will remain unfiltered...


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

* Re: [PATCH] printk: Monitor change of console loglevel.
  2019-05-25  0:14   ` Tetsuo Handa
@ 2019-05-25  0:56     ` Joe Perches
  0 siblings, 0 replies; 11+ messages in thread
From: Joe Perches @ 2019-05-25  0:56 UTC (permalink / raw)
  To: Tetsuo Handa, Linus Torvalds
  Cc: Andrew Morton, Linux List Kernel Mailing, Dmitry Vyukov,
	Petr Mladek, Sergey Senozhatsky

On Sat, 2019-05-25 at 09:14 +0900, Tetsuo Handa wrote:
> On 2019/05/25 2:17, Linus Torvalds wrote:
> > A config option or two that help syzbot doesn't sound like a bad idea to me.
> 
> Thanks for suggestion. I think that #ifdef'ing
> 
>   static bool suppress_message_printing(int level)
>   {
>   	return (level >= console_loglevel && !ignore_loglevel);
>   }
> 
> is simpler.
[]
> On 2019/05/25 2:55, Linus Torvalds wrote:
> > On Fri, May 24, 2019 at 10:41 AM Joe Perches <joe@perches.com> wrote:
> > > That could also help eliminate unnecessary pr_<foo> output
> > > from object code.
> > 
> > Indeed. The small-config people might like it (if they haven't already
> > given up..)
> 
> Do you mean doing e.g.
> 
>   #define pr_debug(fmt, ...) no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
> 
> depending on the minimal console loglevel kernel config option? Then, OK.

Yes.

Perhaps something like the below (or an equivalent generic wrapper)

#define pr_info(fmt, ...) \
do { \
	if (CONFIG_STATIC_CONSOLE_LEVEL >= LOGLEVEL_INFO) \
		printk(KERN_INFO pr_fmt(fmt), ##__VA_ARGS__); \
	else \
		no_printk(KERN_INFO pr_fmt(fmt), ##__VA_ARGS__); \
} while (0)

for each pr_<level>, dev_<level> and netdev_<level>



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

end of thread, other threads:[~2019-05-25  0:56 UTC | newest]

Thread overview: 11+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-05-10 15:19 [PATCH] printk: Monitor change of console loglevel Tetsuo Handa
2019-05-14  9:19 ` Sergey Senozhatsky
2019-05-15 14:32   ` Tetsuo Handa
2019-05-23  9:56     ` Tetsuo Handa
2019-05-24  7:55       ` Dmitry Vyukov
2019-05-24 10:35         ` Tetsuo Handa
2019-05-24 17:17 ` Linus Torvalds
2019-05-24 17:40   ` Joe Perches
2019-05-24 17:55     ` Linus Torvalds
2019-05-25  0:14   ` Tetsuo Handa
2019-05-25  0:56     ` Joe Perches

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).