Bug 1288591

Summary: systemd-udevd is overly verbose
Product: Red Hat Enterprise Linux 7 Reporter: Phil Sutter <psutter>
Component: grubbyAssignee: Peter Jones <pjones>
Status: CLOSED DUPLICATE QA Contact: Release Test Team <release-test-team-automation>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 7.2CC: lnykryn, msekleta, psutter, systemd-maint-list
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2015-12-07 15:34:21 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

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 ***