Description of problem: Fedora 34 Workstation ~11s boot, upgraded to Fedora 35 ~33s boot. LENOVO 20QDS3E200 is a ThinkPad X1 Carbon Gen 7 Version-Release number of selected component (if applicable): selinux-policy-34.16-1.fc35.noarch fprintd-1.92.0-2.fc35.x86_64 systemd-249.4-1.fc35.x86_64 How reproducible: Every boot Steps to Reproduce: 1. Upgrade to 35 and boot 2. 3. Actual results: 3x slower than 34 Expected results: same or faster Additional info:
Created attachment 1820328 [details] journal -b -o short-monotonic Large (10s of seconds) gaps in the journal: [ 12.221987] systemd-resolved[795]: wlp0s20f3: Bus client set DNS server list to: 75.75.75.75, 75.75.76.76, 2001:558:feed::1, 2001:558:feed::2 [ 21.016072] systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully. [ 21.017255] audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=NetworkManager-dispatcher comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' [ 21.847713] wpa_supplicant[1114]: wlp0s20f3: CTRL-EVENT-SIGNAL-CHANGE above=1 signal=-41 noise=9999 txrate=866700 [ 31.033714] gnome-shell[1069]: AT-SPI: Error retrieving accessibility bus address: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken. What's it doing?
Created attachment 1820329 [details] systemd-analyze plot svg
Created attachment 1820330 [details] systemd-analyze critical-chain
One possible factor: Bug 2001058 - systemd-udev-settle.service is deprecated. Please fix multipathd.service not to pull it in.
sgallagh gets the prize, it's an selinux related issue, so changing the component. When enforcing, boot time is ~33s and with enforcing=0 boot time goes to 8.8s (yay!) fprintd-1.92.0-2.fc35.x86_64 selinux-policy-34.16-1.fc35.noarch enforcing=0 $ journalctl -b -o short-monotonic --no-hostname | grep AVC [ 6.116151] audit[890]: AVC avc: denied { create } for pid=890 comm="ModemManager" scontext=system_u:system_r:modemmanager_t:s0 tcontext=system_u:system_r:modemmanager_t:s0 tclass=qipcrtr_socket permissive=1 [ 6.116325] audit[890]: AVC avc: denied { module_request } for pid=890 comm="ModemManager" kmod="net-pf-42" scontext=system_u:system_r:modemmanager_t:s0 tcontext=system_u:system_r:kernel_t:s0 tclass=system permissive=1 [ 6.124954] audit[890]: AVC avc: denied { getopt } for pid=890 comm="ModemManager" scontext=system_u:system_r:modemmanager_t:s0 tcontext=system_u:system_r:modemmanager_t:s0 tclass=qipcrtr_socket permissive=1 [ 6.125113] audit[890]: AVC avc: denied { getattr } for pid=890 comm="ModemManager" scontext=system_u:system_r:modemmanager_t:s0 tcontext=system_u:system_r:modemmanager_t:s0 tclass=qipcrtr_socket permissive=1 [ 6.677650] audit[1040]: AVC avc: denied { write } for pid=1040 comm="dbus-daemon" name="/" dev="tmpfs" ino=1 scontext=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 tcontext=system_u:object_r:user_tmp_t:s0 tclass=dir permissive=1 [ 6.677735] audit[1040]: AVC avc: denied { add_name } for pid=1040 comm="dbus-daemon" name="dbus-1" scontext=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 tcontext=system_u:object_r:user_tmp_t:s0 tclass=dir permissive=1 [ 6.677787] audit[1040]: AVC avc: denied { create } for pid=1040 comm="dbus-daemon" name="dbus-1" scontext=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 tcontext=system_u:object_r:user_tmp_t:s0 tclass=dir permissive=1 [ 6.678831] audit[1040]: AVC avc: denied { read } for pid=1040 comm="dbus-daemon" name="services" dev="tmpfs" ino=44 scontext=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 tcontext=system_u:object_r:user_tmp_t:s0 tclass=dir permissive=1 [ 7.181449] audit[1040]: AVC avc: denied { read } for pid=1040 comm="dbus-daemon" name="services" dev="tmpfs" ino=44 scontext=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 tcontext=system_u:object_r:user_tmp_t:s0 tclass=dir permissive=1 [ 7.181562] audit[1066]: AVC avc: denied { write } for pid=1066 comm="gnome-shell" name="dbus-fGCBr2GWOp" dev="tmpfs" ino=40 scontext=system_u:system_r:xdm_t:s0-s0:c0.c1023 tcontext=system_u:object_r:tmp_t:s0 tclass=sock_file permissive=1 [ 7.181661] audit[1066]: AVC avc: denied { connectto } for pid=1066 comm="gnome-shell" path="/tmp/dbus-fGCBr2GWOp" scontext=system_u:system_r:xdm_t:s0-s0:c0.c1023 tcontext=system_u:system_r:unconfined_service_t:s0-s0:c0.c1023 tclass=unix_stream_socket permissive=1 [ 7.774717] audit[1040]: AVC avc: denied { read } for pid=1040 comm="dbus-daemon" name="services" dev="tmpfs" ino=44 scontext=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 tcontext=system_u:object_r:user_tmp_t:s0 tclass=dir permissive=1 [ 8.006161] audit[1436]: AVC avc: denied { write } for pid=1436 comm="fprintd" name="wakeup" dev="sysfs" ino=28044 scontext=system_u:system_r:fprintd_t:s0 tcontext=system_u:object_r:sysfs_t:s0 tclass=file permissive=1 [ 8.125929] audit[1040]: AVC avc: denied { read } for pid=1040 comm="dbus-daemon" name="services" dev="tmpfs" ino=44 scontext=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 tcontext=system_u:object_r:user_tmp_t:s0 tclass=dir permissive=1 [ 8.212806] audit[1299]: AVC avc: denied { write } for pid=1299 comm="gsd-media-keys" name="dbus-fGCBr2GWOp" dev="tmpfs" ino=40 scontext=system_u:system_r:xdm_t:s0-s0:c0.c1023 tcontext=system_u:object_r:tmp_t:s0 tclass=sock_file permissive=1 [ 8.213104] audit[1299]: AVC avc: denied { connectto } for pid=1299 comm="gsd-media-keys" path="/tmp/dbus-fGCBr2GWOp" scontext=system_u:system_r:xdm_t:s0-s0:c0.c1023 tcontext=system_u:system_r:unconfined_service_t:s0-s0:c0.c1023 tclass=unix_stream_socket permissive=1 [ 8.392093] audit[1547]: AVC avc: denied { write } for pid=1547 comm="ibus-x11" name="dbus-fGCBr2GWOp" dev="tmpfs" ino=40 scontext=system_u:system_r:xdm_t:s0-s0:c0.c1023 tcontext=system_u:object_r:tmp_t:s0 tclass=sock_file permissive=1 enforcing=1 $ journalctl -b-1 -o short-monotonic --no-hostname | grep AVC [ 6.595440] audit[881]: AVC avc: denied { create } for pid=881 comm="ModemManager" scontext=system_u:system_r:modemmanager_t:s0 tcontext=system_u:system_r:modemmanager_t:s0 tclass=qipcrtr_socket permissive=0 [ 33.455991] audit[1458]: AVC avc: denied { write } for pid=1458 comm="fprintd" name="wakeup" dev="sysfs" ino=28044 scontext=system_u:system_r:fprintd_t:s0 tcontext=system_u:object_r:sysfs_t:s0 tclass=file permissive=0 [ 33.456109] audit[1458]: AVC avc: denied { write } for pid=1458 comm="fprintd" name="persist" dev="sysfs" ino=28037 scontext=system_u:system_r:fprintd_t:s0 tcontext=system_u:object_r:sysfs_t:s0 tclass=file permissive=0 [ 767.517075] audit[3594]: AVC avc: denied { write } for pid=3594 comm="fprintd" name="wakeup" dev="sysfs" ino=28044 scontext=system_u:system_r:fprintd_t:s0 tcontext=system_u:object_r:sysfs_t:s0 tclass=file permissive=0 [ 767.517219] audit[3594]: AVC avc: denied { write } for pid=3594 comm="fprintd" name="persist" dev="sysfs" ino=28037 scontext=system_u:system_r:fprintd_t:s0 tcontext=system_u:object_r:sysfs_t:s0 tclass=file permissive=0 [ 1067.216453] audit[4004]: AVC avc: denied { write } for pid=4004 comm="fprintd" name="wakeup" dev="sysfs" ino=28044 scontext=system_u:system_r:fprintd_t:s0 tcontext=system_u:object_r:sysfs_t:s0 tclass=file permissive=0 [ 1067.216621] audit[4004]: AVC avc: denied { write } for pid=4004 comm="fprintd" name="persist" dev="sysfs" ino=28037 scontext=system_u:system_r:fprintd_t:s0 tcontext=system_u:object_r:sysfs_t:s0 tclass=file permissive=0 [ 2320.137932] audit[5229]: AVC avc: denied { write } for pid=5229 comm="fprintd" name="wakeup" dev="sysfs" ino=28044 scontext=system_u:system_r:fprintd_t:s0 tcontext=system_u:object_r:sysfs_t:s0 tclass=file permissive=0 [ 2320.138101] audit[5229]: AVC avc: denied { write } for pid=5229 comm="fprintd" name="persist" dev="sysfs" ino=28037 scontext=system_u:system_r:fprintd_t:s0 tcontext=system_u:object_r:sysfs_t:s0 tclass=file permissive=0 [ 3647.403396] audit[6300]: AVC avc: denied { write } for pid=6300 comm="fprintd" name="wakeup" dev="sysfs" ino=28044 scontext=system_u:system_r:fprintd_t:s0 tcontext=system_u:object_r:sysfs_t:s0 tclass=file permissive=0 [ 3647.403611] audit[6300]: AVC avc: denied { write } for pid=6300 comm="fprintd" name="persist" dev="sysfs" ino=28037 scontext=system_u:system_r:fprintd_t:s0 tcontext=system_u:object_r:sysfs_t:s0 tclass=file permissive=0 [ 8631.106108] audit[8961]: AVC avc: denied { write } for pid=8961 comm="fprintd" name="wakeup" dev="sysfs" ino=28044 scontext=system_u:system_r:fprintd_t:s0 tcontext=system_u:object_r:sysfs_t:s0 tclass=file permissive=0 [ 8631.106308] audit[8961]: AVC avc: denied { write } for pid=8961 comm="fprintd" name="persist" dev="sysfs" ino=28037 scontext=system_u:system_r:fprintd_t:s0 tcontext=system_u:object_r:sysfs_t:s0 tclass=file permissive=0 $
Proposed as a Freeze Exception for 35-beta by Fedora user chrismurphy using the blocker tracking app because: 3x longer boot time is a bad UX, so if we can fix it before beta release, that would be awesome. It might arguably be a final blocker, though it'll require some creativity: https://fedoraproject.org/wiki/Fedora_35_Final_Release_Criteria#SELinux_and_crash_notifications "notifications" has been considered to be a desktop notification, not an AVC denial appearing in the journal. But since selinux troubleshooter is no longer shipped by default, this criterion is rendered obsolete/meaningless if we're unwilling to extend it to AVC's that result in negative UI/UX even if it's not a notification.
Following dnf remove fprintd, the slow boot problem remains. ausearch -m AVC time->Sat Sep 4 23:15:37 2021 type=AVC msg=audit(1630818937.500:162): avc: denied { create } for pid=891 comm="ModemManager" scontext=system_u:system_r:modemmanager_t:s0 tcontext=system_u:system_r:modemmanager_t:s0 tclass=qipcrtr_socket permissive=0 But this is well before any of the delays...
Created attachment 1820576 [details] journal systemd.log_level=debug enforcing=1 and fprintd is removed Many time gaps are during systemd-resolved, NetworkManager, or avahi activity. Primarily resolved. [ 21.074419] systemd-resolved[797]: Using feature level TLS+EDNS0 for transaction 17058. [ 21.074465] systemd-resolved[797]: Announcing packet size 512 in egress EDNS(0) packet. [ 23.012508] systemd[1]: Got message type=signal sender=org.freedesktop.DBus destination=n/a path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=NameOwnerChanged cookie=4294967295 reply_cookie=0 signature=sss error-name=n/a error-message=n/a [ 23.013726] systemd[1]: NetworkManager-dispatcher.service: D-Bus name org.freedesktop.nm_dispatcher now not owned by anyone. [ 23.018519] systemd-logind[834]: Got message type=signal sender=:1.0 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitRemoved cookie=584 reply_cookie=0 signature=so error-name=n/a error-message=n/a [ 26.019977] systemd-resolved[797]: Got message type=method_call sender=:1.19 destination=org.freedesktop.resolve1 path=/org/freedesktop/resolve1 interface=org.freedesktop.resolve1.Manager member=ResolveHostname cookie=801 reply_cookie=0 signature=isit error-name=n/a error-message=n/a [ 26.023398] systemd-resolved[797]: Match type='signal',sender='org.freedesktop.DBus',path='/org/freedesktop/DBus',interface='org.freedesktop.DBus',member='NameOwnerChanged',arg0=':1.19' successfully installed. [ 31.270656] systemd-resolved[797]: Timeout reached on transaction 21545. [ 36.029183] systemd-resolved[797]: varlink-23: Changing state processing-method → pending-method [ 37.020915] NetworkManager[917]: varlink: Setting state idle-client [ 47.970520] systemd-resolved[797]: varlink-20: Changing state processing-disconnect → disconnected [ 51.019806] systemd-logind[834]: Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=StopUnit cookie=269 reply_cookie=0 signature=ss error-name=n/a error-message=n/a But no AVC messages throughout.
comparing sd debug log level with enforcing=1 and 0, there's no difference in ModemManager messages or timings. The enforcing=1 case shows 9 messages: [ 21.069739] systemd-resolved[797]: Timeout reached on transaction 21545. These are not found in the enforcing=0 case.
Next, disable systemd-resolved and let NetworkManager create /etc/resolv.conf. No change, still slow. Next, turn off the wifi radio (the only network connection on this laptop). No change, still slow.
Reproduced the problem on different hardware (ancient Macbook Pro), starting with a clean install of Fedora-WS-Live-35-20210811-n-0 which does *not* exhibit the problem; but once updated it does.
System reverted to 20210822 (btrfs snapshot) also doesn't have the problem. And still doesn't have the problem following update from: systemd-249.2-1.fc35.x86_64 selinux-policy-34.15-1.fc35.noarch to systemd-249.4-1.fc35.x86_64 selinux-policy-34.16-1.fc35.noarch *sigh*
Created attachment 1820723 [details] suspect packages After this update, the problem happens, so one of the listed packages+versions is a culprits we haven't yet discovered. (Ignore the kernel in this list; other testing shows it is not the culprit; I'm also skeptical it's grub or firmware related.)
*** Bug 2001374 has been marked as a duplicate of this bug. ***
Network manager requires permissions it did not need previously. It can mean a change in nm, kernel qrtr driver, or a library. In #c5 I can see (at least) 3 independent problems, one already has a fix in bz#1949712, I will try to isolate the rest. There also is an overlap with bz#1997310.
+3 in https://pagure.io/fedora-qa/blocker-review/issue/430 , marking accepted. Doesn't hurt anything if it's a dupe of the g-i-s bug.
I've submitted a Fedora PR for review https://github.com/fedora-selinux/selinux-policy/pull/863 but it is a draft as I cannot reproduce it completely, maybe some hardware is needed? ---- type=PROCTITLE msg=audit(09/06/2021 11:43:19.554:300) : proctitle=/usr/sbin/ModemManager type=SOCKADDR msg=audit(09/06/2021 11:43:19.554:300) : saddr={ saddr_fam=qipcrtr (unsupported) } type=SYSCALL msg=audit(09/06/2021 11:43:19.554:300) : arch=x86_64 syscall=getsockname success=yes exit=0 a0=0x9 a1=0x7fffc8e1cb40 a2=0x7fffc8e1cb30 a3=0x7fffc8e1cb34 items=0 ppid=1 pid=1221 auid=unset uid=root gid=root euid=root suid=root fsuid=root egid=root sgid=root fsgid=root tty=(none) ses=unset comm=ModemManager exe=/usr/sbin/ModemManager subj=system_u:system_r:modemmanager_t:s0 key=(null) type=AVC msg=audit(09/06/2021 11:43:19.554:300) : avc: denied { getattr } for pid=1221 comm=ModemManager scontext=system_u:system_r:modemmanager_t:s0 tcontext=system_u:system_r:modemmanager_t:s0 tclass=qipcrtr_socket permissive=1 BTW this is the first time a qipcrtr socket is namely used in selinux-policy. At first glance it seems the delays may rather be related to uresourced. Anyway, having bz#1949712 fixed should make a change.
Well, openQA just runs in qemu VMs, and I and others have reproduced it in a typical virt-manager VM. But thanks for the potential fixes, I'll try to test those.
It certainly happens on real HW (Lenovo T470s) for me. Just saying.
I've merged the PR, a test build can be used https://github.com/fedora-selinux/selinux-policy/pull/863 Show all checks -> build-rpm -> Details -> Artifacts -> rpms but I prepare a regular build soon.
A scratchbuild available here: https://koji.fedoraproject.org/koji/taskinfo?taskID=75281469 On my vms without fprintd active there are no AVC denials any longer. F34 and rawhide builds should be available later today.
It looks like only a F34 and F36 selinux-policy was build, but no F35. Was this intentional?
I applied the f36 package now and it indeed seems to boot faster again. Thanks a lot, Zdenek :) However, ausearch -m AVC still returns time->Wed Sep 8 20:55:09 2021 type=AVC msg=audit(1631127309.535:279): avc: denied { write } for pid=1924 comm="fprintd" name="wakeup" dev="sysfs" ino=31259 scontext=system_u:system_r:fprintd_t:s0 tcontext=system_u:object_r:sysfs_t:s0 tclass=file permissive=0 ---- time->Wed Sep 8 20:55:09 2021 type=AVC msg=audit(1631127309.535:280): avc: denied { write } for pid=1924 comm="fprintd" name="persist" dev="sysfs" ino=31252 scontext=system_u:system_r:fprintd_t:s0 tcontext=system_u:object_r:sysfs_t:s0 tclass=file permissive=0 ---- time->Wed Sep 8 20:55:52 2021 type=AVC msg=audit(1631127352.511:318): avc: denied { write } for pid=3157 comm="fprintd" name="wakeup" dev="sysfs" ino=31259 scontext=system_u:system_r:fprintd_t:s0 tcontext=system_u:object_r:sysfs_t:s0 tclass=file permissive=0 ---- time->Wed Sep 8 20:55:52 2021 type=AVC msg=audit(1631127352.511:319): avc: denied { write } for pid=3157 comm="fprintd" name="persist" dev="sysfs" ino=31252 scontext=system_u:system_r:fprintd_t:s0 tcontext=system_u:object_r:sysfs_t:s0 tclass=file permissive=0 with the new selinux-policy. Additionally, while the dbus at-spi timeout is gone now, there however now is the following in the gdm log Sep 08 20:55:08 p14s-gen2-amd gnome-shell[1557]: AT-SPI: Error retrieving accessibility bus address: org.freedesktop.DBus.Error.Spawn.ChildExited: Process org.a11y.Bus exited with status 1 indicating stuff still isn't fully working correctly.
Zdenek, we need a build for F35 to resolve this issue.
An F35 build should be available soon (today or tomorrow), together with F34 and rawhide. The fprintd issue is to be addressed later.
There are now builds available for F34, F35, and F36. I believe there will not be any delays or failures caused by a missing SELinux permission. The fprintd issue is likely unrelated and will be addressed later.
I am experiencing the same issue on the latest Silverblue 35. The userspace load time is 3x longer than in case of Fedora 34 Workstation. Silverblue 35 Startup finished in 7.358s (firmware) + 3.971s (loader) + 1.167s (kernel) + 2.131s (initrd) + 32.112s (userspace) = 46.742s graphical.target reached after 32.065s in userspace Fedora 34 Workstation Startup finished in 6.645s (firmware) + 2.382s (loader) + 1.183s (kernel) + 2.131s (initrd) + 10.218s (userspace) = 22.561s graphical.target reached after 9.968s in userspace
FEDORA-2021-a850b07511 has been submitted as an update to Fedora 35. https://bodhi.fedoraproject.org/updates/FEDORA-2021-a850b07511
FEDORA-2021-a850b07511 has been pushed to the Fedora 35 testing repository. Soon you'll be able to install the update with the following command: `sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2021-a850b07511` You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2021-a850b07511 See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.
FEDORA-2021-a850b07511 has been pushed to the Fedora 35 stable repository. If problem still persists, please make note of it in this bug report.
*** Bug 1996905 has been marked as a duplicate of this bug. ***