linux-kernel - 5.19 printk breaks message ordering

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [thread-next>] [day] [month] [year] [list]

Date:   Fri, 17 Jun 2022 15:23:02 +0200
From:   "Jason A. Donenfeld" <Jason@...c4.com>
To:     John Ogness <john.ogness@...utronix.de>,
        Petr Mladek <pmladek@...e.com>, Marco Elver <elver@...gle.com>,
        linux-kernel@...r.kernel.org
Subject: 5.19 printk breaks message ordering

Hi John & folks,

In 5.19, I'm seeing some changes in message ordering / interleaving
which lead to confusion. The most obvious (and benign) example appears
on system boot, in which the "Run /init as init process" message gets
intermixed with the messages that init actually writes() to stdout. For
example, here's a snippet from build.wireguard.com:

    [    0.469732] Freeing unused kernel image (initmem) memory: 4576K
    [    0.469738] Write protecting the kernel read-only data: 10240k
    [    0.473823] Freeing unused kernel image (text/rodata gap) memory: 2044K
    [    0.475228] Freeing unused kernel image (rodata/data gap) memory: 1136K
    [    0.475236] Run /init as init process

        WireGuard Test Suite on Linux 5.19.0-rc2+ x86_64

    [+] Mounting filesystems...
    [+] Module self-tests:
     *  allowedips self-tests: pass
     *  nonce counter self-tests: pass
     *  ratelimiter self-tests: pass
    [+] Enabling logging...
    [+] Launching tests...
    [    0.475237]   with arguments:
    [    0.475238]     /init
    [    0.475238]   with environment:
    [    0.475239]     HOME=/
    [    0.475240]     TERM=linux
    [+] ip netns add wg-test-46-0
    [+] ip netns add wg-test-46-1

Before the "with arguments:" and such would print prior to the
"wireguard test suite on linux 5.19" banner. Now it shows after.

I see the same thing with "Freeing unused kernel image (text/rodata gap)
memory" printing interwoven into the console of my initramfs on my
laptop. And so forth.

But the bigger issue for me is that it makes it very confusing to
interpret CI results later on. Prior, I would nice a nice correlation
of:

[+] some userspace command
[    1.2345 ] some kernel log output
[+] some userspace command
[    1.2346 ] some kernel log output
[+] some userspace command
[    1.2347 ] some kernel log output

Now, the kernel log outputs are all over the place and out of order with
the sequence of commands. This makes debugging issues somewhat tricky,
because post hoc ergo propter hoc winds up being a good intuition to
follow when tracking down bugs, and now the post hoc part is muddled.

I assume this is mostly caused by your threaded printk patchset, which
moves some of that printing into a worker, which means it's more
dependent on the scheduler than before. This probably has important
benefits. But it certainly makes CI and related debugging a bit
trickier as a result.

So I was wondering if there was some way to boot the kernel with a
command line option or compile-time flag that always flushes printk
messages when they're made, or does something to make the ordering a bit
more faithful.

Thanks,
Jason