RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 2059633 - systemd doesn't record messages to the journal during boot
Summary: systemd doesn't record messages to the journal during boot
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 8
Classification: Red Hat
Component: systemd
Version: 8.5
Hardware: All
OS: Linux
urgent
urgent
Target Milestone: rc
: ---
Assignee: Michal Sekletar
QA Contact: Frantisek Sumsal
URL:
Whiteboard:
Depends On:
Blocks: 2164049 2164050
TreeView+ depends on / blocked
 
Reported: 2022-03-01 15:15 UTC by Renaud Métrich
Modified: 2023-05-16 11:10 UTC (History)
8 users (show)

Fixed In Version: systemd-239-71.el8
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 2164049 2164050 (view as bug list)
Environment:
Last Closed: 2023-05-16 09:07:15 UTC
Type: Bug
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Issue Tracker RHELPLAN-114129 0 None None None 2022-03-01 15:21:38 UTC
Red Hat Knowledge Base (Solution) 3032831 0 None None None 2022-03-22 07:57:08 UTC
Red Hat Product Errata RHBA-2023:2985 0 None None None 2023-05-16 09:07:42 UTC

Description Renaud Métrich 2022-03-01 15:15:18 UTC 
Description of problem:

Many debugging messages such as "Activating default unit: xxx" are not recorded in the journal when booting, even with LogLevel=debug.

See below a "standard boot":
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
# journalctl -b | grep "Activating default"
--> nothing
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

However, by specifying `systemd.log_target=kmsg` on the kernel command line, those messages are recorded (because they are pushed to kmsg buffer, then read by the journal later):
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
# dmesg | grep "Activating default"
[    1.138475] systemd[1]: Activating default unit: default.target
[   24.949661] systemd[1]: Activating default unit: default.target

# journalctl -b | grep "Activating default"
Mar 01 16:09:11 vm-relabel8 systemd[1]: Activating default unit: default.target
Mar 01 16:09:35 vm-relabel8 systemd[1]: Activating default unit: default.target
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

This is super annoying when debugging boot issues.


Version-Release number of selected component (if applicable):

systemd-239-45.el8.x86_64 or later

How reproducible:

Always

Steps to Reproduce:
1. Enable debug level `systemd.log_level=debug` on kernel command line
2. Boot

Actual results:

No "Activating default unit" message (it's at debug level)

Expected results:

"Activating default unit" message

Additional info:
Comment 1 David Tardon 2022-03-02 12:41:25 UTC 
I can reproduce this reliably, except that changing the log target makes no difference.
Comment 2 Renaud Métrich 2022-03-02 12:59:13 UTC 
"systemd.log_level=debug systemd.log_target=kmsg log_buf_len=15M printk.devkmsg=on" solves the issue for me.

which is expected since systemd then writes to /dev/kmsg, which already exists just after switching root.
Whereas for some time the /run/systemd/journal/dev-log socket is not there or somehow usable, which causes systemd to fallback to /dev/ksmg, as seen by stracing systemd early:

-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
13:50:07.182971 sendmsg(46<UNIX:[22636->12503]>, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="PRIORITY=7\nSYSLOG_FACILITY=3\nCODE_FILE=../src/core/service.c\nCODE_LINE=406\nCODE_FUNC=on_fd_store_io\nUNIT=systemd-journald.servic"..., iov_len=203}, {iov_base="MESSAGE=", iov_len=8}, {iov_base="systemd-journald.service: Received EPOLLHUP on stored fd 75 (stored), closing.", iov_len=78}, {iov_base="\n", iov_len=1}], msg_iovlen=4, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 290 <0.000007>

--> last message before switching root sent to dev-log socket

 :
13:49:31.725316 writev(3</dev/kmsg<char 1:11>>, [{iov_base="<31>", iov_len=4}, {iov_base="systemd", iov_len=7}, {iov_base="[1]: ", iov_len=5}, {iov_base="Activating default unit: default.target", iov_len=39}, {iov_base="\n", iov_len=1}], 5) = 56 <0.000006>
 :
13:49:31.799750 epoll_ctl(4<anon_inode:[eventpoll]>, EPOLL_CTL_ADD, 41<UNIX:[12491,"/run/systemd/journal/dev-log"]>, {EPOLLIN, {u32=2066902816, u64=93898641927968}}) = 0 <0.000010>

--> listening on the socket but systemd-journald not yet there

13:49:32.138939 epoll_ctl(4<anon_inode:[eventpoll]>, EPOLL_CTL_DEL, 41<UNIX:[12491,"/run/systemd/journal/dev-log"]>, NULL) = 0 <0.000003>

--> systemd-journald now there, stop listening on the socket

 :
13:49:32.139009 writev(3</dev/kmsg<char 1:11>>, [{iov_base="<31>", iov_len=4}, {iov_base="systemd", iov_len=7}, {iov_base="[1]: ", iov_len=5}, {iov_base="systemd-journald.socket: Changed listening -> running", iov_len=53}, {iov_base="\n", iov_len=1}], 5) = 70 <0.000002>

--> last message sent to /dev/kmsg

13:49:32.140149 sendmsg(46<UNIX:[22636->12503]>, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="PRIORITY=7\nSYSLOG_FACILITY=3\nCODE_FILE=../src/core/service.c\nCODE_LINE=3697\nCODE_FUNC=service_notify_message\nUNIT=systemd-journa"..., iov_len=212}, {iov_base="MESSAGE=", iov_len=8}, {iov_base="systemd-journald.service: Got notification message from PID 1097 (WATCHDOG=1)", iov_len=77}, {iov_base="\n", iov_len=1}], msg_iovlen=4, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 298 <0.000331>

--> first message sent to dev-log socket after switch root
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
Comment 3 David Tardon 2022-03-02 13:56:09 UTC 
https://github.com/systemd/systemd/commit/3ad2afb6a204513c7834c64ab864e40169874390 seems to help.
Comment 5 Renaud Métrich 2022-11-10 13:47:14 UTC 
Hello,

Please fix this issue ASAP, it's making us (Support and Customers) lose a lot of time when troubleshooting boot issues, which are usually due to ordering cycles which do not appear because of that bug.

Renaud.
Comment 11 Plumber Bot 2023-01-27 12:00:56 UTC 
fix merged to github main branch -> https://github.com/redhat-plumbers/systemd-rhel8/pull/358
Comment 17 errata-xmlrpc 2023-05-16 09:07:15 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (systemd bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2023:2985
Note You need to log in before you can comment on or make changes to this bug.