Bug 867130 - RFE: Copy dmesg content into journal during boot
RFE: Copy dmesg content into journal during boot
Status: CLOSED NOTABUG
Product: Fedora
Classification: Fedora
Component: systemd (Show other bugs)
rawhide
Unspecified Unspecified
unspecified Severity unspecified
: ---
: ---
Assigned To: systemd-maint
Fedora Extras Quality Assurance
: Reopened
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2012-10-16 16:14 EDT by John Florian
Modified: 2012-10-17 11:43 EDT (History)
8 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2012-10-17 11:43:24 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description John Florian 2012-10-16 16:14:42 EDT
Description of problem:
journalctl is a wonderful interface to the system logging data.  Unfortunately it doesn't always have the entire picture.  A useful enhancement would be to make journald, when it is first started, to dump the kernel message ring buffer (dmesg) into the journal so that journalctl can provide a complete picture w/o having to also run dmesg.

Additional info:
For example, I recently went debugging in the wrong direction when I saw, via journalctl, kernel messages like:

Request for unknown module key 'Fedora kernel signing key: c6fb6e1f2b79b50ab078f4d6b9fc9b2204a692a7' err -11

I bothered the Fedora Testing mailing list, filed bug #865938 and only quite a bit later learned the cause, which was revealed by dmesg, but not journalctl:

[    3.591826] Loading module verification certificates
[    3.601372] Cert Valid From: 2012-10-08 16:52:26
[    3.610300] Cert Valid To: 2112-09-14 16:52:26
[    3.618967] Now: 2003-01-01 00:02:42
[    3.626830] X.509: Cert c6fb6e1f2b79b50ab078f4d6b9fc9b2204a692a7 is not yet valid
[    3.643056] MODSIGN: Problem loading in-kernel X.509 certificate (-129)
[    3.654414] registered taskstats version 1
[    3.664906]   Magic number: 3:0:0
[    3.673116] rtc_cmos 00:04: setting system clock to 2003-01-01 00:02:44 UTC (1041379364)
Comment 1 Lennart Poettering 2012-10-16 17:05:06 EDT
Humm? We actually do that on F18 by default, and on F17 you can enable this by setting ImportKernel=yes (but if you do that you have to turn kmsg off in rsyslog).

Closing. Feel free to reopen, if I misunderstood something here.
Comment 2 John Florian 2012-10-16 17:30:14 EDT
(In reply to comment #1)
> Humm? We actually do that on F18 by default, and on F17 you can enable this
> by setting ImportKernel=yes (but if you do that you have to turn kmsg off in
> rsyslog).
> 
> Closing. Feel free to reopen, if I misunderstood something here.

I could have sworn I'd seen some sort of evidence supporting that.  However, it's clearly not working for me.  I don't think I'm getting any dmesg data via journalctl.  What do you suggest for debugging?

This is with:

systemd-194-1.fc18
kernel-3.6.1-1.fc18
Comment 3 Kay Sievers 2012-10-16 17:46:43 EDT
This works fine, and I can't see why it wouldn't. It can not even be disabled
in the systemd version you run.

# journalctl 
Logs begin at Tue, 16 Oct 2012 23:42:47 +0200, end at Tue, 16 Oct 2012 23:42:54 +0200.
Oct 16 23:42:47 mop systemd-journal[80]: Allowing runtime journal files to grow 
Oct 16 23:42:47 mop kernel: Linux version 3.6.0-rc7+ (kay@mop) (gcc version 4.7.
Oct 16 23:42:47 mop kernel: Command line: root=/dev/sda2 console=tty0 console=tt
Oct 16 23:42:47 mop kernel: KERNEL supported cpus:
Oct 16 23:42:47 mop kernel:   Intel GenuineIntel
Oct 16 23:42:47 mop kernel: e820: BIOS-provided physical RAM map:
Oct 16 23:42:47 mop kernel: BIOS-e820: [mem 0x0000000000000000-0x000000000009fbf
...

Does:
  $ cat /dev/kmsg
work?

What does:
  $ ls -l /proc/$(pidof /usr/lib/systemd/systemd-journald)/fd
print?
Comment 4 Lennart Poettering 2012-10-17 08:07:03 EDT
Also, try "journalctl _TRANSPORT=kernel" to only show kernel messages!

Maybe it already got rotated away? By default on Fedora we'll only log to volatile (and small) /run, rather than persistant (and large) /var. By simply creating /var/log/journal you can turn on persistant logging.
Comment 5 John Florian 2012-10-17 08:33:47 EDT
(In reply to comment #3)
> Does:
>   $ cat /dev/kmsg
> work?

I'd say yes given that it appears to have the earliest messages I'd expect to see:
# head -15 /dev/kmsg
6,0,0,-;Initializing cgroup subsys cpuset
6,1,0,-;Initializing cgroup subsys cpu
5,2,0,-;Linux version 3.6.1-1.fc18.i686 (mockbuild@) (gcc version 4.7.2 20120921 (Red Hat 4.7.2-2) (GCC) ) #1 SMP Mon Oct 8 18:03:51 UTC 2012
6,3,0,-;e820: BIOS-provided physical RAM map:
6,4,0,-;BIOS-e820: [mem 0x0000000000000000-0x000000000009dfff] usable
6,5,0,-;BIOS-e820: [mem 0x000000000009e000-0x000000000009ffff] reserved
6,6,0,-;BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
6,7,0,-;BIOS-e820: [mem 0x0000000000100000-0x000000003dfaffff] usable
6,8,0,-;BIOS-e820: [mem 0x000000003dfb0000-0x000000003dfb2fff] ACPI NVS
6,9,0,-;BIOS-e820: [mem 0x000000003dfb3000-0x000000003dfbffff] ACPI data
6,10,0,-;BIOS-e820: [mem 0x00000000ffff0000-0x00000000ffffffff] reserved
5,11,0,-;Notice: NX (Execute Disable) protection missing in CPU!
6,12,0,-;DMI 2.2 present.
7,13,0,-;DMI:    /AMD-GX3, BIOS 6.00 PG 08/05/2008
7,14,0,-;e820: update [mem 0x00000000-0x0000ffff] usable ==> reserved


> What does:
>   $ ls -l /proc/$(pidof /usr/lib/systemd/systemd-journald)/fd
> print?

# ls -l /proc/$(pidof /usr/lib/systemd/systemd-journald)/fd
total 0
lr-x------ 1 root root 64 Oct 17 08:19 0 -> /dev/null
l-wx------ 1 root root 64 Oct 17 08:19 1 -> /dev/null
lrwx------ 1 root root 64 Oct 17 08:19 10 -> /run/log/journal/865974fccbfe22a04a9c9ed7a7e7565f/system.journal
lrwx------ 1 root root 64 Oct 17 08:19 11 -> socket:[11634]
lrwx------ 1 root root 64 Oct 17 08:19 14 -> socket:[10579]
lrwx------ 1 root root 64 Oct 17 08:19 15 -> socket:[10580]
lrwx------ 1 root root 64 Oct 17 08:19 16 -> socket:[10576]
l-wx------ 1 root root 64 Oct 17 08:19 2 -> /dev/null
lrwx------ 1 root root 64 Oct 17 08:19 3 -> socket:[6097]
lrwx------ 1 root root 64 Oct 17 08:19 4 -> socket:[6100]
lrwx------ 1 root root 64 Oct 17 08:19 5 -> socket:[6102]
l-wx------ 1 root root 64 Oct 17 08:19 6 -> /dev/kmsg
lrwx------ 1 root root 64 Oct 17 08:19 7 -> anon_inode:[eventpoll]
lrwx------ 1 root root 64 Oct 17 08:19 8 -> /dev/kmsg
lrwx------ 1 root root 64 Oct 17 08:19 9 -> anon_inode:[signalfd]


(In reply to comment #4)
> Also, try "journalctl _TRANSPORT=kernel" to only show kernel messages!

This shows (in its entirety):
Oct 17 08:22:44 localhost.localdomain systemd-journald[47]: Received SIGTERM
Oct 17 08:22:44 localhost.localdomain systemd-udevd[246]: starting version 194
Oct 17 08:22:45 localhost.localdomain kernel: EXT4-fs (dm-0): re-mounted. Opts: (null)
Oct 17 08:22:49 localhost.localdomain kernel: AMD Geode RNG detected
Oct 17 08:22:50 localhost.localdomain kernel: geode-aes: GEODE AES engine enabled.
Oct 17 08:22:51 localhost.localdomain kernel: ACPI: Invalid Power Resource to register!
Oct 17 08:22:51 localhost.localdomain kernel: ACPI Warning: 
Oct 17 08:22:51 localhost.localdomain kernel: 0x00006100-0x000061ff SystemIO conflicts with Region \_SB_.GPIO 1 (20120711/utaddress-251)
Oct 17 08:22:51 localhost.localdomain kernel: ACPI: If an ACPI driver is available for this device, you should use it instead of the native driver
Oct 17 08:22:51 localhost.localdomain kernel: cs5535-mfd 0000:00:0f.0: MFD add devices failed: -16
Oct 17 08:22:51 localhost.localdomain kernel: cs5535-mfd: probe of 0000:00:0f.0 failed with error -16
Oct 17 08:22:52 localhost.localdomain kernel: parport_pc 00:0b: reported by Plug and Play ACPI
Oct 17 08:22:52 localhost.localdomain kernel: parport0: PC-style at 0x378, irq 7 [PCSPP,TRISTATE,EPP]
Oct 17 08:22:52 localhost.localdomain kernel: microcode: AMD CPU family 0x5 not supported
Oct 17 08:22:53 localhost.localdomain kernel: e100: Intel(R) PRO/100 Network Driver, 3.5.24-k2-NAPI
Oct 17 08:22:53 localhost.localdomain kernel: e100: Copyright(c) 1999-2006 Intel Corporation
Oct 17 08:22:53 localhost.localdomain kernel: ACPI: PCI Interrupt Link [LNKC] BIOS reported IRQ 0, using IRQ 11
Oct 17 08:22:53 localhost.localdomain kernel: ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 11
Oct 17 08:22:53 localhost.localdomain kernel: e100 0000:00:10.0: setting latency timer to 64
Oct 17 08:22:53 localhost.localdomain kernel: e100 0000:00:10.0: eth0: addr 0xefffd000, irq 11, MAC addr 00:0b:ab:25:e6:3f
Oct 17 08:22:53 localhost.localdomain kernel: ppdev: user-space parallel port driver
Oct 17 08:22:55 localhost.localdomain kernel: ACPI: PCI Interrupt Link [LNKB] enabled at IRQ 11
Oct 17 08:22:55 localhost.localdomain kernel: snd_cs5535audio 0000:00:0f.3: setting latency timer to 64
Oct 17 08:23:01 localhost.localdomain kernel: EXT4-fs (sda1): re-mounted. Opts: (null)
Oct 17 08:23:12 aos-000bab25e63f.dartcontainer.com kernel: IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
Oct 17 08:23:12 aos-000bab25e63f.dartcontainer.com kernel: e100 0000:00:10.0: eth0: NIC Link is Up 100 Mbps Full Duplex
Oct 17 08:23:12 aos-000bab25e63f.dartcontainer.com kernel: IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready


> Maybe it already got rotated away?

I suppose that's possible, but it seems unlikely if that were the case that the first two messages journalctl always shows me are:

Oct 17 08:22:44 localhost.localdomain systemd-journal[252]: Allowing runtime journal files to grow to 48.5M.
Oct 17 08:22:44 localhost.localdomain systemd-journald[47]: Received SIGTERM

> By default on Fedora we'll only log to
> volatile (and small) /run, rather than persistant (and large) /var. By
> simply creating /var/log/journal you can turn on persistant logging.

I'll give that a try and report back later.  Since this is a Live image, I'll need to retool the spin slightly to test this theory.
Comment 6 John Florian 2012-10-17 08:37:05 EDT
FWIW, I do get the correct behavior on the F18 host that produces these Live spins.  I must say this is a most welcome improvement to our logging environment -- I'm most pleased with the journal (and systemd)!
Comment 7 John Florian 2012-10-17 11:25:22 EDT
(In reply to comment #5)
> (In reply to comment #3)
> > Maybe it already got rotated away?
> 
[snip]
> 
> > By default on Fedora we'll only log to
> > volatile (and small) /run, rather than persistant (and large) /var. By
> > simply creating /var/log/journal you can turn on persistant logging.
> 
> I'll give that a try and report back later.  Since this is a Live image,
> I'll need to retool the spin slightly to test this theory.


Apparently it was due to rotation.  My spins now have /var/log/journal extant at boot and now journalctl does seem to show the initial (and likely entire) content that dmesg shows.  

Interestingly, /var is over tmpfs so this still really isn't persistent.  How does this affect the journal's rotation algorithms?  I'm guessing it now just looks like a normal (persistent) file system and rotation will be governed by the free space of /var.  Is that correct?  

Which route would you consider more reliable for:
    1. capturing as much log history as practical (needed only for debugging)
    2. while remaining extremely reliable for not exhausting system resources on embedded systems that are administered "only as needed" -- I don't have the man power to keep a close eye on the hundreds of systems that will be running this
Comment 8 Kay Sievers 2012-10-17 11:31:20 EDT
(In reply to comment #7)
> Apparently it was due to rotation.

Ah, good.

> Interestingly, /var is over tmpfs so this still really isn't persistent.

Yeah, it's similar to the thing in /run, we always require. 

> Which route would you consider more reliable for:
>     1. capturing as much log history as practical (needed only for debugging)
>     2. while remaining extremely reliable for not exhausting system
> resources on embedded systems that are administered "only as needed" -- I
> don't have the man power to keep a close eye on the hundreds of systems that
> will be running this

Check out:
  man journald.conf

There is:
  RuntimeMaxUse=, RuntimeKeepFree=, RuntimeMaxFileSize=

maybe you can tweak the deaults and get away with using the stuff in /run
only, if /var is a tmpfs anyway.
Comment 9 John Florian 2012-10-17 11:43:24 EDT
Okay, thanks for the conf pointers.  Thanks all!  I'm glad this turned out to be nothing more than a false alarm.

Consider it a testing gift for lowly Geode powered boards with 1 GB of RAM.  :-)

Note You need to log in before you can comment on or make changes to this bug.