[PATCH] printk: Monitor change of console loglevel.

[PATCH] printk: Monitor change of console loglevel.

[Tetsuo Handa]

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

Re: [PATCH] printk: Monitor change of console loglevel.

[Sergey Senozhatsky]

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

Re: [PATCH] printk: Monitor change of console loglevel.

[Tetsuo Handa]

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.

Re: [PATCH] printk: Monitor change of console loglevel.

[Tetsuo Handa]

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

Re: [PATCH] printk: Monitor change of console loglevel.

[Dmitry Vyukov]

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

Re: [PATCH] printk: Monitor change of console loglevel.

[Tetsuo Handa]

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.

Re: [PATCH] printk: Monitor change of console loglevel.

[Linus Torvalds]

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

Re: [PATCH] printk: Monitor change of console loglevel.

[Joe Perches]

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.

Re: [PATCH] printk: Monitor change of console loglevel.

[Linus Torvalds]

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

Re: [PATCH] printk: Monitor change of console loglevel.

[Tetsuo Handa]

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

Re: [PATCH] printk: Monitor change of console loglevel.

[Joe Perches]

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>