[systemd-devel] systemd.journald.forward_to doesn't forward all journal messages

[Chris Murphy]

On Mon, Jul 29, 2019 at 1:26 AM Lennart Poettering
<lennart at poettering.net> wrote:
>
> On So, 28.07.19 22:11, Chris Murphy (lists at colorremedies.com) wrote:
>
> > Using either of the following:
> >
> > systemd.log_level=debug systemd.journald.forward_to_kmsg log_buf_len=8M
> >
> > systemd.log_level=debug systemd.log_target=kmsg log_buf_len=8M
>
> Note that this is not sufficient. You also have to pass
> "printk.devkmsg=on" too, otherwise the kernel ratelimits log output
> from usperspace ridiculously a lot, and you will see lots of dropped
> messages.
>
> I have documented this now here:
>
> https://github.com/systemd/systemd/pull/13208

BOOT_IMAGE=/images/pxeboot/vmlinuz
root=live:CDLABEL=Fedora-WS-Live-rawh-20190728-n-1 rd.live.image
systemd.wants=zram-swap.service systemd.log_level=debug
systemd.journald.forward_to_kmsg log_buf_len=8M printk.devkmsg=on

Many messages I see in the journal still do not appear in kmsg. For
example from /dev/kmsg

6,20619,201107529,-;zram: Cannot change disksize for initialized device
12,23154,208596765,-;org.fedoraproject.Anaconda.Modules.Network[2498]:
DEBUG:anaconda.modules.network.network:Applying boot options
KernelArguments([('BOOT_IMAGE', '/images/pxeboot/vmlinuz'), ('root',
'live:CDLABEL=Fedora-WS-Live-rawh-20190728-n-1'), ('rd.live.image',
None), ('systemd.wants', 'zram-swap.service'), ('systemd.log_level',
'debug'), ('systemd.journald.forward_to_kmsg', None), ('log_buf_len',
'8M'), ('printk.devkmsg', 'on')])
12,25049,210822858,-;org.fedoraproject.Anaconda.Modules.Storage[2498]:
DEBUG:anaconda.modules.storage.disk_selection.selection:Protected
devices are set to '['/dev/zram0']'.
^C
[root at localhost-live liveuser]# journalctl -o short-monotonic | grep zram
[  203.224915] localhost-live systemd[1477]: Added job
dev-zram0.device/nop to transaction.
[  203.225017] localhost-live systemd[1477]: dev-zram0.device:
Installed new job dev-zram0.device/nop as 295
[  203.225143] localhost-live systemd[1477]: Added job
sys-devices-virtual-block-zram0.device/nop to transaction.
[  203.225245] localhost-live systemd[1477]:
sys-devices-virtual-block-zram0.device: Installed new job
sys-devices-virtual-block-zram0.device/nop as 296
[  203.225355] localhost-live systemd[1477]:
sys-devices-virtual-block-zram0.device: Job 296
sys-devices-virtual-block-zram0.device/nop finished, result=done
[  203.225570] localhost-live systemd[1477]: dev-zram0.device: Job 295
dev-zram0.device/nop finished, result=done
[  208.959944] localhost-live systemd[1477]: Added job
dev-zram0.device/nop to transaction.
[  208.961015] localhost-live systemd[1477]: dev-zram0.device:
Installed new job dev-zram0.device/nop as 340
[  208.961324] localhost-live systemd[1477]: Added job
sys-devices-virtual-block-zram0.device/nop to transaction.
[  208.961508] localhost-live systemd[1477]:
sys-devices-virtual-block-zram0.device: Installed new job
sys-devices-virtual-block-zram0.device/nop as 341
[  208.961789] localhost-live systemd[1477]:
sys-devices-virtual-block-zram0.device: Job 341
sys-devices-virtual-block-zram0.device/nop finished, result=done
[  208.962021] localhost-live systemd[1477]: dev-zram0.device: Job 340
dev-zram0.device/nop finished, result=done
[  209.822448] localhost-live systemd[1477]: Added job
dev-zram0.device/nop to transaction.
[  209.822625] localhost-live systemd[1477]: dev-zram0.device:
Installed new job dev-zram0.device/nop as 377
[  209.822757] localhost-live systemd[1477]: Added job
sys-devices-virtual-block-zram0.device/nop to transaction.
[  209.822861] localhost-live systemd[1477]:
sys-devices-virtual-block-zram0.device: Installed new job
sys-devices-virtual-block-zram0.device/nop as 378
[  209.822983] localhost-live systemd[1477]:
sys-devices-virtual-block-zram0.device: Job 378
sys-devices-virtual-block-zram0.device/nop finished, result=done
[  209.823106] localhost-live systemd[1477]: dev-zram0.device: Job 377
dev-zram0.device/nop finished, result=done
[  213.866820] localhost-live anaconda[2490]: blivet:
DeviceTree.get_device_by_path: path: /dev/zram0 ; incomplete: False ;
hidden: False ;
[  213.868392] localhost-live anaconda[2490]: blivet: failed to
resolve '/dev/zram0'
[root at localhost-live liveuser]#


Literally zero of those lines appear in kmsg

6,20619,201107529,-;zram: Cannot change disksize for initialized device
12,23154,208596765,-;org.fedoraproject.Anaconda.Modules.Network[2498]:
DEBUG:anaconda.modules.network.network:Applying boot options
KernelArguments([('BOOT_IMAGE', '/images/pxeboot/vmlinuz'), ('root',
'live:CDLABEL=Fedora-WS-Live-rawh-20190728-n-1'), ('rd.live.image',
None), ('systemd.wants', 'zram-swap.service'), ('systemd.log_level',
'debug'), ('systemd.journald.forward_to_kmsg', None), ('log_buf_len',
'8M'), ('printk.devkmsg', 'on')])
12,25049,210822858,-;org.fedoraproject.Anaconda.Modules.Storage[2498]:
DEBUG:anaconda.modules.storage.disk_selection.selection:Protected
devices are set to '['/dev/zram0']'.

The first is a kernel message, the next two are anaconda messages that
don't appear in the journal, where the two anaconda-blivet messages in
the journal do not appear in kmsg. But none of the systemd messages in
the journal appear in kmsg. It's like they each are missing some of
what appears in the other.

Between this behavior, and the journals being deleted on Lives bug,
I'm totally stuck being unable to introspect early boot problems, or
even confirm working things are working as intended and in the proper
order.
https://bugzilla.redhat.com/show_bug.cgi?id=1715699

One of these has to give.

---
Chris Murphy