journald misses initial kernel messages on arm64

[abogdanenko]

systemd version the issue has been seen with

a01eb97

Expected behaviour you didn't see

"kernel: Command line: " message in the journal

Unexpected behaviour you saw

systemd-journald[363]: Missed 81 kernel messages

Steps to reproduce the problem
Run CI autopkgtest, case JournalTest.test_no_options.

[abogdanenko]

Test failed in #11099, see "bionic-arm64 — autopkgtest finished (failure)"

======================================================================
FAIL: test_no_options (__main__.JournalTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/autopkgtest.CSc4Sx/build.ymn/systemd/debian/tests/boot-and-services", line 179, in test_no_options
    self.assertRegex(out, b'kernel:.*[cC]ommand line:')
AssertionError: Regex didn't match: b'kernel:.*[cC]ommand line:' not found in b'-- Logs begin at Sun 2018-12-09 03:24:51 UTC, end at Sun 2018-12-09 19:28:29 UTC. --
Dec 09 03:24:51 ubuntu systemd-journald[363]: Missed 81 kernel messages

Full log:

https://objectstorage.prodstack4-5.canonical.com/v1/AUTH_77e2ada1e7a84929a74ba3b87153c0ac/autopkgtest-bionic-pitti-systemd-semaphore/bionic/arm64/s/systemd-upstream/20181209_201440_8524e@/log.gz

[abogdanenko]

Another example:

-- Reboot --
Dec 09 03:32:13 d8cc63b4-51ef-4127-8168-e6b23ba188c3-adt-prepare systemd-journald[245]: Missed 81 kernel messages
Dec 09 03:32:13 d8cc63b4-51ef-4127-8168-e6b23ba188c3-adt-prepare kernel:   EFI remap 0x00000000b86e0000 =>         (ptrval)
Dec 09 03:32:13 d8cc63b4-51ef-4127-8168-e6b23ba188c3-adt-prepare kernel:   EFI remap 0x00000000bbc20000 =>         (ptrval)

[abogdanenko]

It could be a problem with the way the test is implemented. If this is the case,
the issue may be closed and fixed in the test code:

class JournalTest(unittest.TestCase):
    '''Check journal functionality'''

    def test_no_options(self):
        out = subprocess.check_output(['journalctl'])
        # has kernel messages
        self.assertRegex(out, b'kernel:.*[cC]ommand line:')
        # has init messages
        self.assertRegex(out, b'systemd.*Reached target Graphical Interface')
        # has other services
        self.assertRegex(out, b'NetworkManager.*:.*starting')

Source: debian/tests/boot-and-services · af81cd9bb7ad140a2886a56ffe73999c65c2c2de · Debian systemd Team / systemd · GitLab

Specifically, kernel message regex can be loosened a bit so that it matches
some other message. On the other hand, this particular message is very useful
to have in a journal.

[abogdanenko]

Noticed the same problem in another PR #11100. Same arch - "bionic-arm64 — autopkgtest finished (failure)".

Full log: https://objectstorage.prodstack4-5.canonical.com/v1/AUTH_77e2ada1e7a84929a74ba3b87153c0ac/autopkgtest-bionic-pitti-systemd-semaphore/bionic/arm64/s/systemd-upstream/20181211_110214_e5cd0@/log.gz

======================================================================
FAIL: test_no_options (__main__.JournalTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/autopkgtest.rTjEqB/build.ZGe/systemd/debian/tests/boot-and-services", line 179, in test_no_options
    self.assertRegex(out, b'kernel:.*[cC]ommand line:')
AssertionError: Regex didn't match: b'kernel:.*[cC]ommand line:' not found in b'-- Logs begin at Sun 2018-12-09 03:24:51 UTC, end at Tue 2018-12-11 09:55:48 UTC. --
Dec 09 03:24:51 ubuntu systemd-journald[363]: Missed 81 kernel messages

Surprisingly to me, the tests aren't run in a clean environment: "Logs begin at" date is the same as in my previous example.

[abogdanenko]

Third data point. PR #11165. The test and the result are the same.

Full log: https://objectstorage.prodstack4-5.canonical.com/v1/AUTH_77e2ada1e7a84929a74ba3b87153c0ac/autopkgtest-bionic-pitti-systemd-semaphore/bionic/arm64/s/systemd-upstream/20181215_090034_f0433@/log.gz

======================================================================
FAIL: test_no_options (__main__.JournalTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/autopkgtest.rljnJn/build.qNZ/systemd/debian/tests/boot-and-services", line 179, in test_no_options
    self.assertRegex(out, b'kernel:.*[cC]ommand line:')
AssertionError: Regex didn't match: b'kernel:.*[cC]ommand line:' not found in b'-- Logs begin at Sun 2018-12-09 03:24:51 UTC, end at Sat 2018-12-15 07:58:23 UTC. --
Dec 09 03:24:51 ubuntu systemd-journald[363]: Missed 81 kernel messages

Again, "Logs begin at" date is the same as in other examples.

[abogdanenko]

Fourth data point. PR #11177. The same test failed.

Full log: https://objectstorage.prodstack4-5.canonical.com/v1/AUTH_77e2ada1e7a84929a74ba3b87153c0ac/autopkgtest-bionic-pitti-systemd-semaphore/bionic/arm64/s/systemd-upstream/20181217_064330_3597e@/log.gz

======================================================================
FAIL: test_no_options (__main__.JournalTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/autopkgtest.qcbBK0/build.AGu/systemd/debian/tests/boot-and-services", line 179, in test_no_options
    self.assertRegex(out, b'kernel:.*[cC]ommand line:')
AssertionError: Regex didn't match: b'kernel:.*[cC]ommand line:' not found in b'-- Logs begin at Mon 2018-12-17 03:08:08 UTC, end at Mon 2018-12-17 05:40:47 UTC. --
Dec 17 03:08:08 ubuntu systemd-journald[384]: Missed 83 kernel messages

This time, "Logs begin at" date is different, so the test is probably running
in a different VM instance.

[evverx]

bionic-arm64 has just been turned off entirely but journald is still missing messages so let's keep the issue open.

[xnox]

To get this test case passing on arm64 I did short-circuit the test for kernel log in the Ubuntu builds. I should upstream this, but also it is worrying that journald does consistently miss early kernel kmsg on arm64. I wonder if the buffer is too small, or there are too many kmsg by the time journald starts, or something like that.

[mbiebl]

Is this the kernel discarding log messages or journald? If the former, might log_buf_len=1M printk.devkmsg=on help?

[evverx]

@mbiebl I'm wondering if you have ever seen this on Debian CI on arm. Frankly, I'm inclined to forward the issue to https://bugs.launchpad.net because I don't think there is anything we can do here to even debug this without access to the Ubuntu infrastructure.

[evverx]

To get this test case passing on arm64 I did short-circuit the test for kernel log in the Ubuntu builds

Judging by @xnox's comment it seems to be a known issue that was "resolved" somewhere so apparently I don't even need to file an issue on https://bugs.launchpad.net/. I'm going to close it here.

[xnox]

well, but it's not yet in bionic kernel, so not quite done done. But it's this one:

https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1824864

[evverx]

@xnox thank you for the link!

Would it be possible to pass log_buf_len (as suggested by @mbiebl) on the Ubuntu CI side until the fix gets backported to Bionic so that I could turn arm64 on again?

[xnox]

all supported series now have the log_buf_len kernel config option bumped up.

[evverx]

Good to know. The test itself was fixed several months ago and arm64 has been on since then.