linux-kernel - Start messages in message buffer missing (dmesg)

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:   Tue, 21 Jul 2020 17:20:37 +0200
From:   Paul Menzel <pmenzel@...gen.mpg.de>
To:     Thomas Gleixner <tglx@...utronix.de>,
        Ingo Molnar <mingo@...hat.com>, Borislav Petkov <bp@...en8.de>,
        x86@...nel.org
Cc:     LKML <linux-kernel@...r.kernel.org>, it+x86@...gen.mpg.de
Subject: Start messages in message buffer missing (dmesg)

Dear Linux folks,


On two indentical Dell PowerEdge T440 with Linux 5.4.39 and systemd 242

     00:00.0 Host bridge [0600]: Intel Corporation Sky Lake-E DMI3 
Registers [8086:2020] (rev 07)

running `dmesg`, it’s truncated despite the buffer not yet filled.

> $ sudo dmidecode -t2
> # dmidecode 3.0
> Getting SMBIOS data from sysfs.
> SMBIOS 3.2 present.
> # SMBIOS implementations newer than version 3.0 are not
> # fully supported by this version of dmidecode.
> 
> Handle 0x0200, DMI type 2, 8 bytes
> Base Board Information
> 	Manufacturer: Dell Inc.
> 	Product Name: 02KM69
> 	Version: A04

The message cutoffs differ.

> @sang:~$ dmesg | head
> [    6.362201] system 00:01: [mem 0xfed12010-0xfed1201f] has been reserved
> [    6.369102] system 00:01: [mem 0xfed1b000-0xfed1bfff] has been reserved
> [    6.376003] system 00:01: Plug and Play ACPI device, IDs PNP0c02 (active)
> [    6.376176] pnp 00:02: Plug and Play ACPI device, IDs PNP0501 (active)
> [    6.376319] pnp 00:03: Plug and Play ACPI device, IDs PNP0501 (active)
> [    6.376451] system 00:04: [mem 0xfd000000-0xfdabffff] has been reserved
> [    6.383352] system 00:04: [mem 0xfdad0000-0xfdadffff] has been reserved
> [    6.390251] system 00:04: [mem 0xfdb00000-0xfdffffff] has been reserved
> [    6.397149] system 00:04: [mem 0xfe000000-0xfe00ffff] has been reserved
> [    6.404049] system 00:04: [mem 0xfe011000-0xfe01ffff] has been reserved

> @mouches:~$ dmesg | head
> [    6.623209] pci 0000:00:1c.4: PCI bridge to [bus 02-03]
> [    6.628723] pci 0000:00:1c.4:   bridge window [mem 0x92000000-0x928fffff]
> [    6.635795] pci 0000:00:1c.4:   bridge window [mem 0x91000000-0x91ffffff 64bit pref]
> [    6.644046] pci 0000:04:00.0: BAR 6: assigned [mem 0x90000000-0x9003ffff pref]
> [    6.651772] pci 0000:04:00.1: BAR 6: assigned [mem 0x90040000-0x9007ffff pref]
> [    6.659494] pci 0000:00:1c.5: PCI bridge to [bus 04]
> [    6.664752] pci 0000:00:1c.5:   bridge window [mem 0x90000000-0x900fffff]
> [    6.671834] pci 0000:00:1c.5:   bridge window [mem 0x92e00000-0x92efffff 64bit pref]
> [    6.680085] pci_bus 0000:00: resource 4 [io  0x0000-0x0cf7 window]
> [    6.686566] pci_bus 0000:00: resource 5 [io  0x1000-0x3fff window]

> @sang:~$ head /dev/kmsg
> 6,862,6362201,-;system 00:01: [mem 0xfed12010-0xfed1201f] has been reserved
>  SUBSYSTEM=pnp
>  DEVICE=+pnp:00:01
> 6,863,6369102,-;system 00:01: [mem 0xfed1b000-0xfed1bfff] has been reserved
>  SUBSYSTEM=pnp
>  DEVICE=+pnp:00:01
> 7,864,6376003,-;system 00:01: Plug and Play ACPI device, IDs PNP0c02 (active)
>  SUBSYSTEM=pnp
>  DEVICE=+pnp:00:01
> 7,865,6376176,-;pnp 00:02: Plug and Play ACPI device, IDs PNP0501 (active)

> @sang:~$ cp /dev/kmsg /dev/shm/kmsg
> ^C
> @sang:~$ ls -lh /dev/shm/kmsg
> -rw-r----- 1 pmenzel pmenzel 135K Jul 21 13:53 /dev/shm/kmsg

So, the size is smaller than 128 KB + 16 * 4 KB = 192 KB. The systemd 
journal contains some earlier messages.

> @sang:~$ sudo journalctl -k | head
> -- Logs begin at Wed 2020-06-03 14:31:56 CEST, end at Tue 2020-07-21 13:54:38 CEST. --
> Jul 16 18:08:59 sang.molgen.mpg.de kernel:   Normal zone: 315392 pages used for memmap
> Jul 16 18:08:59 sang.molgen.mpg.de kernel:   Normal zone: 20185088 pages, LIFO batch:63
> Jul 16 18:08:59 sang.molgen.mpg.de kernel: Initmem setup node 1 [mem 0x0000001440000000-0x000000203fffffff]
> Jul 16 18:08:59 sang.molgen.mpg.de kernel: On node 1 totalpages: 12582912
> Jul 16 18:08:59 sang.molgen.mpg.de kernel:   Normal zone: 196608 pages used for memmap
> Jul 16 18:08:59 sang.molgen.mpg.de kernel:   Normal zone: 12582912 pages, LIFO batch:63
> Jul 16 18:08:59 sang.molgen.mpg.de kernel: ACPI: PM-Timer IO Port: 0x508
> Jul 16 18:08:59 sang.molgen.mpg.de kernel: ACPI: Local APIC address 0xfee00000
> Jul 16 18:08:59 sang.molgen.mpg.de kernel: ACPI: X2APIC_NMI (uid[0xffffffff] high level lint[0x1])
> 
> @sang:~$ sudo journalctl -k > /dev/shm/journalctl-k.txt
> @sang:~$ ls -lh /dev/shm/journalctl-k.txt
> -rw-rw---- 1 pmenzel pmenzel 191K Jul 21 13:55 /dev/shm/journalctl-k.txt

The systemd journal output starts at the same position on both systems.

But now, trying to get the full log over serial console, the full log is 
now present too on one system, when running `dmesg`. Detaching the 
serial console, the behavior stays the same, that means all messages are 
there. I am confused, how this could have fixed anything.

Is somebody interested into looking into this, or should a just fix the 
affected system by plugging in a serial cable too?


Kind regards,

Paul

View attachment "20200721–mouches–linux_5.4.39–messages.txt" of type "text/plain" (92655 bytes)

View attachment "20200721–sang–linux_5.4.39–messages-full.txt" of type "text/plain" (134555 bytes)