Re: [syzbot? printk?] no WARN_ON() messages printed before "Kernel panic - not syncing: panic_on_warn set ..."

[Dmitry Vyukov]

On Sat, Mar 16, 2019 at 3:09 AM Tetsuo Handa
<penguin-kernel@xxxxxxxxxxxxxxxxxxx> wrote:
>
> Hello.
>
> I found a corrupted report at https://syzkaller.appspot.com/text?tag=CrashLog&x=17c6b82b200000 .
>
> The panic() was caused by by WARN_ON() from generic_make_request_checks(), but there
> was no printk() messages from WARN_ON(). Moreover, there was no printk() messages
> for (at least) nearly one minute despite syzbot's testing likely generates constant
> printk() messages. Unfortunately, since the report was truncated due to size limit,
> we can't check when was the last time prink() succeeded writing messages to consoles.
>
> ----------
> 14:27:02 executing program 1:
> (...snipped...)
> 14:28:00 executing program 3:
> (...snipped...)
> [  974.068065][T22281] Kernel panic - not syncing: panic_on_warn set ...
> [  974.085454][T22281] CPU: 1 PID: 22281 Comm: syz-executor.1 Not tainted 5.0.0+ #23
> [  974.093121][T22281] Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
> [  974.103193][T22281] Call Trace:
> [  974.106513][T22281]  dump_stack+0x172/0x1f0
> [  974.110893][T22281]  ? generic_make_request_checks+0x1be0/0x2160
> [  974.117235][T22281]  panic+0x2cb/0x65c
> [  974.121434][T22281]  ? __warn_printk+0xf3/0xf3
> [  974.126064][T22281]  ? generic_make_request_checks+0x1ca3/0x2160
> [  974.132257][T22281]  ? __sanitizer_cov_trace_const_cmp4+0x16/0x20
> [  974.138521][T22281]  ? __warn.cold+0x5/0x45
> [  974.142877][T22281]  ? __warn+0xe8/0x1d0
> [  974.146978][T22281]  ? generic_make_request_checks+0x1ca3/0x2160
> [  974.153171][T22281]  __warn.cold+0x20/0x45
> [  974.157483][T22281]  ? vprintk_emit+0x1ce/0x6d0
> [  974.162202][T22281]  ? generic_make_request_checks+0x1ca3/0x2160
> [  974.168403][T22281]  report_bug+0x263/0x2b0
> [  974.172847][T22281]  do_error_trap+0x11b/0x200
> [  974.177646][T22281]  do_invalid_op+0x37/0x50
> [  974.182329][T22281]  ? generic_make_request_checks+0x1ca3/0x2160
> [  974.188951][T22281]  invalid_op+0x14/0x20
> [  974.193142][T22281] RIP: 0010:generic_make_request_checks+0x1ca3/0x2160
> ----------
>
> Is it possible that the reason there was no printk() messages is that
> someone kept printing messages to console from userspace such that
> console_trylock() from printk() was not able to succeed for (at least)
> nearly one minute?

Such reports showed up always with low frequency. For all that I
looked at we also always had a normal  non-truncated version, so I was
never too worried.

If something would write from userspace, that would show up in the
output, or not?

Perhaps syzkaller somehow manages to lower console output level? I
figured out that we should restrict it from doing
syslog(SYSLOG_ACTION_CONSOLE_OFF). And I also restricted its access o
/dev/console. But maybe there is something else? It _should_ not be
able to write to random sysctl's.