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 1288591 - systemd-udevd is overly verbose
Summary: systemd-udevd is overly verbose
Keywords:
Status: CLOSED DUPLICATE of bug 1212128
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: grubby
Version: 7.2
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: rc
: ---
Assignee: Peter Jones
QA Contact: Release Test Team
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2015-12-04 16:46 UTC by Phil Sutter
Modified: 2015-12-07 15:34 UTC (History)
4 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2015-12-07 15:34:21 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)

Description Phil Sutter 2015-12-04 16:46:30 UTC 
While testing some upstream changes to rhashtable implementation, I noticed that systemd seems to have gotten pretty verbose when it comes to loading kernel modules.

Maybe this is just a local issue, I'm running RHEL7.2 Server with a custom-built kernel from mainline. My test-case is 'modprobe test_rhashtable', which makes 'dmesg -w' print the following:

[ 4595.450793] Running rhashtable test nelem=8, max_size=0, shrinking=0
[ 4595.450841] systemd-udevd[525]: Validate module index
[ 4595.450862] systemd-udevd[525]: Check if link configuration needs reloading.
[ 4595.450895] systemd-udevd[525]: seq 3157 queued, 'add' 'module'
[ 4595.451112] systemd-udevd[525]: seq 3157 forked new worker [11556]
[ 4595.451387] systemd-udevd[11556]: seq 3157 running
[ 4595.451457] systemd-udevd[11556]: no db file to read /run/udev/data/+module:test_rhashtable: No such file or directory
[ 4595.451503] systemd-udevd[11556]: PROGRAM '/usr/bin/systemctl is-active trace-cmd.service' /usr/lib/udev/rules.d/98-trace-cmd.rules:1
[ 4595.451660] systemd-udevd[11557]: starting '/usr/bin/systemctl is-active trace-cmd.service'
[ 4595.463689] Test 00:
[ 4595.466747] systemd[1]: Got unexpected auxiliary data with level=1 and type=2
[ 4595.468601] systemd[1]: Accepted new private connection.
[ 4595.469624] systemctl[11557]: Got unexpected auxiliary data with level=1 and type=2
[ 4595.470241] systemd[1]: Got notification message for unit systemd-journald.service
[ 4595.470245] systemd[1]: systemd-journald.service: Got notification message from PID 492 (WATCHDOG=1)
[ 4595.470247] systemd[1]: systemd-journald.service: got WATCHDOG=1
[ 4595.470260]   Adding 50000 keys
[ 4595.475156] systemctl[11557]: Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=GetUnit cookie=1 reply_cookie=0 error=n/a
[ 4595.475281] Info: encountered resize
[ 4595.475282] Info: encountered resize
[ 4595.475283] Info: encountered resize
[ 4595.475284] Info: encountered resize
[ 4595.475287] Info: encountered resize
[ 4595.475293] Info: encountered resize
[ 4595.475306] Info: encountered resize
[ 4595.475329] Info: encountered resize
[ 4595.475376] Info: encountered resize
[ 4595.475468] Info: encountered resize
[ 4595.475652] Info: encountered resize
[ 4595.476045] Info: encountered resize
[ 4595.476513]   Traversal complete: counted=50000, nelems=50000, entries=50000, table-jumps=12
[ 4595.483367] systemd[1]: Got unexpected auxiliary data with level=1 and type=2
[ 4595.483370] systemd[1]: Got unexpected auxiliary data with level=1 and type=2
[ 4595.483380] systemd[1]: Got message type=method_call sender=n/a destination=org.freedesktop.systemd1 object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=GetUnit cookie=1 reply_cookie=0 error=n/a
[ 4595.483400] systemd[1]: Sent message type=error sender=n/a destination=n/a object=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 error=Unit trace-cmd.service not loaded.
[ 4595.483404] systemd[1]: Failed to process message [type=method_call sender=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=GetUnit signature=s]: Unit trace-cmd.service not loaded.
[ 4595.488063]   Traversal complete: counted=50000, nelems=50000, entries=50000, table-jumps=0
[ 4595.488064]   Deleting 50000 keys
[ 4595.491249]   Duration of test: 20988211 ns
[ 4595.491254] Test 01:
[ 4595.492597]   Adding 50000 keys
[ 4595.497090] Info: encountered resize
[ 4595.497285] Info: encountered resize
[ 4595.497708] Info: encountered resize
[ 4595.498312]   Traversal complete: counted=50000, nelems=50000, entries=50000, table-jumps=3
[ 4595.504767] systemctl[11557]: Got unexpected auxiliary data with level=1 and type=2
[ 4595.505941]   Traversal complete: counted=50000, nelems=50000, entries=50000, table-jumps=0
[ 4595.505941]   Deleting 50000 keys
[ 4595.508052] systemctl[11557]: Got unexpected auxiliary data with level=1 and type=2
[ 4595.509143]   Duration of test: 16544855 ns
[ 4595.509149] Test 02:
[ 4595.510473]   Adding 50000 keys
[ 4595.511470] systemd-udevd[11556]: '/usr/bin/systemctl is-active trace-cmd.service'(out) 'unknown'
[ 4595.512931] systemd-udevd[11556]: '/usr/bin/systemctl is-active trace-cmd.service' [11557] exit with return code 3
[ 4595.514650] systemd-udevd[11556]: passed unknown number of bytes to netlink monitor 0x55b4052082a0
[ 4595.515893] systemd[1]: Got disconnect on private connection.
[ 4595.516911] systemd-udevd[11556]: seq 3157 processed with 0
[ 4595.519314]   Traversal complete: counted=50000, nelems=50000, entries=50000, table-jumps=0
[ 4595.525973]   Traversal complete: counted=50000, nelems=50000, entries=50000, table-jumps=0
[ 4595.527552]   Deleting 50000 keys
[ 4595.531807]   Duration of test: 21332071 ns
[ 4595.532670] Test 03:
[ 4595.534690]   Adding 50000 keys
[ 4595.539737] Info: encountered resize
[ 4595.540862] Info: encountered resize
[ 4595.542159]   Traversal complete: counted=50000, nelems=50000, entries=50000, table-jumps=2
[ 4595.554837]   Traversal complete: counted=50000, nelems=50000, entries=50000, table-jumps=0
[ 4595.556203]   Deleting 50000 keys
[ 4595.560886]   Duration of test: 25513812 ns
[ 4595.561957] Average test time: 21094737
[ 4595.562899] Testing concurrent rhashtable access from 10 threads
[ 4595.905471] Started 10 threads, 0 failed
[ 4598.521003] systemd-udevd[525]: cleanup idle workers
[ 4598.521821] systemd-udevd[525]: Validate module index
[ 4598.522590] systemd-udevd[525]: Check if link configuration needs reloading.
[ 4598.522873] systemd-udevd[11556]: Unload module index
[ 4598.522945] systemd-udevd[11556]: Unloaded link configuration context.
[ 4598.529277] systemd-udevd[525]: worker [11556] exit
[ 4598.530035] systemd-udevd[525]: worker [11556] cleaned up
Comment 1 Phil Sutter 2015-12-04 16:48:02 UTC 
I can workaround this problem by calling 'dmesg -k -w' instead to limit output to messages generated by the kernel itself, but since I did not have this issue before a recent system update, I assume this is unintended behaviour.
Comment 2 Michal Sekletar 2015-12-04 19:43:15 UTC 
You should decrease systemd's and udev's log level. I can see that there are debug messages logged in the provided output of dmesg.

At runtime you can call following commands to make systemd and udev more quiet,
# systemd-analyze set-log-level info
# udevadm control --log-priority info

Can you please provide content of your kernel command line?
Comment 3 Phil Sutter 2015-12-07 14:49:14 UTC 
Hi,

I found the cause, thanks for pointing me at cmdline:

# cat /proc/cmdline 
BOOT_IMAGE=/vmlinuz-4.4.0-rc1rhashtable+ root=/dev/mapper/rhel-root ro rd.lvm.lv=rhel/swap crashkernel=auto rd.lvm.lv=rhel/root rhgb quiet console=tty0 console=ttyS0 kgdboc=ttyS0 LANG=en_US.UTF-8 systemd.debug systemd.log_level=debug systemd.log_target=kmsg

From what I can tell, this originates from a bug in new-kernel-pkg script. For details, see: https://bugzilla.redhat.com/show_bug.cgi?id=957681#c11

So I guess systemd is not guilty here. :)

Thanks, Phil
Comment 4 Lukáš Nykrýn 2015-12-07 15:20:57 UTC 
Thanks for checking. Lets reassign this to grubby.
Comment 5 Phil Sutter 2015-12-07 15:32:34 UTC 
Well, I 'sort of' took care of this already, although maybe in a bit too chaotic manner:

- Found bug 957681 and commented on it.
- After being advised by a colleague, created a new ticket for it (bug 1289174).
- Looking into dist-git for grubby, found out about bug 1212128 which is what I should have commented on in the first place.
Comment 6 Lukáš Nykrýn 2015-12-07 15:34:21 UTC 
So lets get rid of this one :)

*** This bug has been marked as a duplicate of bug 1212128 ***
Note You need to log in before you can comment on or make changes to this bug.