Bug 2141140
| Summary: | Services fail on startup, service enablement does not work correctly, and gnome-initial-setup disappears on UEFI boots - all Rawhide Silverblue with systemd 252 | ||
|---|---|---|---|
| Product: | [Fedora] Fedora | Reporter: | Adam Williamson <awilliam> |
| Component: | systemd | Assignee: | systemd-maint |
| Status: | CLOSED DUPLICATE | QA Contact: | Fedora Extras Quality Assurance <extras-qa> |
| Severity: | high | Docs Contact: | |
| Priority: | unspecified | ||
| Version: | rawhide | CC: | fedoraproject, filbranden, flepied, lnykryn, msekleta, ryncsn, ssahani, s, systemd-maint, walters, yaneti, yuwatana, zbyszek |
| Target Milestone: | --- | ||
| Target Release: | --- | ||
| Hardware: | All | ||
| OS: | Linux | ||
| Whiteboard: | openqa | ||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2022-12-09 20:28:27 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: | |||
CCing Colin for the rpm-ostree angle here. There is a likely-related problem in another test. In that test, we test service manipulation - starting, stopping, enabling, and disabling services. One test is to do `systemctl disable chronyd.service` , verify that it seems to be disabled, reboot, and check whether it started. That test also fails - see e.g. https://openqa.fedoraproject.org/tests/1577076 . Running `systemd disable chronyd.service` produces the expected output saying /etc/systemd/system/multi-user-target.wants/chronyd.service was removed, and running `systemctl is-enabled chronyd.service` says it's disabled, but on reboot, it gets started. Again, I can reproduce this locally, and it's not happening on non-ostree-based editions, only on Silverblue. Another problem that appeared at exactly the same time, and also only seems to affect Silverblue, is that the install-on-UEFI test started failing: https://openqa.fedoraproject.org/tests/1579101# . The install process runs perfectly normally, but the installed system boots to a black screen. If you watch the video - https://openqa.fedoraproject.org/tests/1579101/video?filename=video.ogv - it seems there's a very brief flash of the desktop background before it black screens. ctrl-alt-f6 does not get to a tty (or else the test would be able to upload logs at the end). Not 100% sure these are all the same problem, but at least the timing and the specific impact only on Silverblue seems to suggest it's likely... > So, I suspect something off in systemd 252's interaction with rpm-ostree-based installs here. Hm, probably related to this from 252: > * Systemd can optionally do a full preset in the "first boot" condition (instead of just enable-only). This behaviour is controlled by the compile-time option -Dfirst-boot-full-preset. Right now it defaults to 'false', but the plan is to switch it to 'true' for the subsequent release. And see https://src.fedoraproject.org/rpms/systemd/blob/rawhide/f/systemd.spec#_504 The UEFI bug I can also reproduce locally. I see the first-run wizard for a few seconds, then a black screen with flashing cursor. I *can* get a console on tty3, but of course I can't log into it - at this point in a Silverblue install there's no root password or user account. `systemd.debug-shell=1`, which should start a root shell on tty9, doesn't seem to work - don't know if that's another element of this bug, or if it just never works on Silverblue, or what. enforcing=0 does not seem to help with the UEFI bug (as it doesn't with dbus-daemon.service). Ping? any progress here? It's rather a significant bug, and it's still affecting Rawhide. I want to enable a test on updates that builds an ostree installer image and tests it, but it's going to fail for UEFI on every Rawhide update if we don't fix this, which would be a shame. I also see the failed services on my personal Silverblue laptop after rebasing it to Rawhide. The system boots to a login screen, but the first attempt to log in often immediately cycles back to GDM, and a second often hangs. If I do reach a working desktop I've seen it hang after that too. If nobody replies to this bug soon, I'm going to build systemd with the new feature disabled and see what happens. Sorry for the slow response. I don't know enough about silverblue to diagnose this.
> Hm, probably related to this from 252:
>> * Systemd can optionally do a full preset in the "first boot" condition
That change was done exactly because it was requested by ostree folks. Maybe it is related,
but I'm not sure. There were many other changes in v252…
Some real debug logs would be useful. Adam: can you post the full log, not just the avcs?
Please also check with v252.3 that should build later today. I suspect #2136916. Thanks. I'll check with 252.3 and if that doesn't fix it, get some more logs. I did notice that after rebasing my Silverblue install to Rawhide, then rebasing back to F37 after running into this bug, I'm pretty sure the state of some services (like sshd) changed - I had it enabled, it went to disabled. It does indeed look like 252.3 fixed this - all the related tests passed on Rawhide today, they were consistently failing before. Thanks. *** This bug has been marked as a duplicate of bug 2136916 *** |
Since Fedora-Rawhide-20221008.n.0 , several services have failed to start on first boot of a freshly-installed Silverblue: dbus-daemon.service , speech-dispatcherd.service , and systemd-time-wait-sync.service . If I boot with enforcing=0 , speech-dispatcherd.service and systemd-time-wait-sync.service work, but dbus-daemon.service still does not. I don't think this is a straightforward SELinux policy issue for a couple of reasons. One, neither selinux-policy nor speech-dispatcher changed in the 20221008.n.0 compose, but systemd did - it went from 251.5-607.fc38 to 252~rc1-608.fc38. Two, this bug is not affecting the Workstation edition. So, I suspect something off in systemd 252's interaction with rpm-ostree-based installs here. When I boot with enforcing=0 , the following AVCs are logged: Nov 08 14:38:38 fedora audit[671]: AVC avc: denied { watch } for pid=671 comm="systemd-time-wa" path="/run/systemd" dev="tmpfs" ino=2 scontext=system_u:system_r:systemd_timedated_t:s0 tcontext=system_u:object_r:init_var_run_t:s0 tclass=dir permissive=1 Nov 08 14:38:40 fedora audit[775]: AVC avc: denied { name_bind } for pid=775 comm="rpcbind" src=61843 scontext=system_u:system_r:rpcbind_t:s0 tcontext=system_u:object_r:unreserved_port_t:s0 tclass=udp_socket permissive=1 Nov 08 14:38:40 fedora audit[819]: AVC avc: denied { create } for pid=819 comm="speech-dispatch" name="speech-dispatcher" scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:cache_home_t:s0 tclass=dir permissive=1 Nov 08 14:38:40 fedora audit[819]: AVC avc: denied { create } for pid=819 comm="speech-dispatch" name="speech-dispatcher.pid" scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:cache_home_t:s0 tclass=file permissive=1 Nov 08 14:38:40 fedora audit[819]: AVC avc: denied { write open } for pid=819 comm="speech-dispatch" path="/var/roothome/.cache/speech-dispatcher/pid/speech-dispatcher.pid" dev="vda3" ino=67196 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:cache_home_t:s0 tclass=file permissive=1 Nov 08 14:38:40 fedora audit[819]: AVC avc: denied { getattr } for pid=819 comm="speech-dispatch" path="/var/roothome/.cache/speech-dispatcher/pid/speech-dispatcher.pid" dev="vda3" ino=67196 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:cache_home_t:s0 tclass=file permissive=1 Nov 08 14:38:40 fedora audit[819]: AVC avc: denied { lock } for pid=819 comm="speech-dispatch" path="/var/roothome/.cache/speech-dispatcher/pid/speech-dispatcher.pid" dev="vda3" ino=67196 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:cache_home_t:s0 tclass=file permissive=1 Nov 08 14:38:40 fedora audit[819]: AVC avc: denied { append } for pid=819 comm="speech-dispatch" path="/var/roothome/.cache/speech-dispatcher/log/speech-dispatcher.log" dev="vda3" ino=67199 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:cache_home_t:s0 tclass=file permissive=1 Nov 08 14:38:40 fedora audit[859]: AVC avc: denied { execute } for pid=859 comm="speech-dispatch" name="bash" dev="vda3" ino=541 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:shell_exec_t:s0 tclass=file permissive=1 Nov 08 14:38:40 fedora audit[859]: AVC avc: denied { execute_no_trans } for pid=859 comm="speech-dispatch" path="/usr/bin/bash" dev="vda3" ino=541 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:shell_exec_t:s0 tclass=file permissive=1 Nov 08 14:38:40 fedora audit[859]: AVC avc: denied { map } for pid=859 comm="sh" path="/usr/bin/bash" dev="vda3" ino=541 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:shell_exec_t:s0 tclass=file permissive=1 Nov 08 14:38:40 fedora audit[877]: AVC avc: denied { execute } for pid=877 comm="sh" name="curl" dev="vda3" ino=805 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:bin_t:s0 tclass=file permissive=1 Nov 08 14:38:40 fedora audit[819]: AVC avc: denied { name_connect } for pid=819 comm="speech-dispatch" dest=59125 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:ephemeral_port_t:s0 tclass=tcp_socket permissive=1 Nov 08 14:38:40 fedora audit[881]: AVC avc: denied { execute } for pid=881 comm="speech-dispatch" name="bash" dev="vda3" ino=541 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:shell_exec_t:s0 tclass=file permissive=1 Nov 08 14:38:40 fedora audit[881]: AVC avc: denied { execute_no_trans } for pid=881 comm="speech-dispatch" path="/usr/bin/bash" dev="vda3" ino=541 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:shell_exec_t:s0 tclass=file permissive=1 Nov 08 14:38:40 fedora audit[881]: AVC avc: denied { map } for pid=881 comm="sh" path="/usr/bin/bash" dev="vda3" ino=541 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:shell_exec_t:s0 tclass=file permissive=1 Nov 08 14:38:40 fedora audit[819]: AVC avc: denied { create } for pid=819 comm="speech-dispatch" name="cicero.log" scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:cache_home_t:s0 tclass=file permissive=1 Nov 08 14:38:40 fedora audit[819]: AVC avc: denied { write open } for pid=819 comm="speech-dispatch" path="/var/roothome/.cache/speech-dispatcher/log/cicero.log" dev="vda3" ino=67204 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:cache_home_t:s0 tclass=file permissive=1 Nov 08 14:38:40 fedora audit[891]: AVC avc: denied { execute_no_trans } for pid=891 comm="speech-dispatch" path="/usr/lib64/speech-dispatcher-modules/sd_cicero" dev="vda3" ino=8502 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:lib_t:s0 tclass=file permissive=1 Nov 08 14:38:40 fedora audit[893]: AVC avc: denied { map } for pid=893 comm="sd_espeak-ng-mb" path=2F6D656D66643A70756C7365617564696F202864656C6574656429 dev="tmpfs" ino=2050 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:speech_dispatcher_tmpfs_t:s0 tclass=file permissive=1 Nov 08 14:38:40 fedora audit[893]: AVC avc: denied { create } for pid=893 comm="sd_espeak-ng-mb" name="pulse" scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:pulseaudio_home_t:s0 tclass=dir permissive=1 Nov 08 14:38:40 fedora audit[893]: AVC avc: denied { read } for pid=893 comm="sd_espeak-ng-mb" name="pulse" dev="vda3" ino=67206 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:pulseaudio_home_t:s0 tclass=dir permissive=1 Nov 08 14:38:40 fedora audit[893]: AVC avc: denied { open } for pid=893 comm="sd_espeak-ng-mb" path="/var/roothome/.config/pulse" dev="vda3" ino=67206 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:pulseaudio_home_t:s0 tclass=dir permissive=1 Nov 08 14:38:40 fedora audit[893]: AVC avc: denied { getattr } for pid=893 comm="sd_espeak-ng-mb" path="/var/roothome/.config/pulse" dev="vda3" ino=67206 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:pulseaudio_home_t:s0 tclass=dir permissive=1 Nov 08 14:38:40 fedora audit[893]: AVC avc: denied { search } for pid=893 comm="sd_espeak-ng-mb" name="pulse" dev="vda3" ino=67206 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:pulseaudio_home_t:s0 tclass=dir permissive=1 Nov 08 14:38:40 fedora audit[893]: AVC avc: denied { create } for pid=893 comm="sd_espeak-ng-mb" name="pulse-PKdhtXMmr18n" scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:tmp_t:s0 tclass=dir permissive=1 Nov 08 14:38:40 fedora audit[893]: AVC avc: denied { write } for pid=893 comm="sd_espeak-ng-mb" name="pulse" dev="vda3" ino=67206 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:pulseaudio_home_t:s0 tclass=dir permissive=1 Nov 08 14:38:40 fedora audit[893]: AVC avc: denied { add_name } for pid=893 comm="sd_espeak-ng-mb" name="621a4ba09bb14feb80a4f8ffcef3b9d2-runtime" scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:pulseaudio_home_t:s0 tclass=dir permissive=1 Nov 08 14:38:40 fedora audit[893]: AVC avc: denied { create } for pid=893 comm="sd_espeak-ng-mb" name="621a4ba09bb14feb80a4f8ffcef3b9d2-runtime" scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:pulseaudio_home_t:s0 tclass=lnk_file permissive=1 Nov 08 14:38:40 fedora audit[893]: AVC avc: denied { read } for pid=893 comm="sd_espeak-ng-mb" name="621a4ba09bb14feb80a4f8ffcef3b9d2-runtime" dev="vda3" ino=67207 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:pulseaudio_home_t:s0 tclass=lnk_file permissive=1 Nov 08 14:38:40 fedora audit[909]: AVC avc: denied { execute_no_trans } for pid=909 comm="speech-dispatch" path="/usr/lib64/speech-dispatcher-modules/sd_espeak-ng" dev="vda3" ino=8506 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:lib_t:s0 tclass=file permissive=1 Nov 08 14:38:40 fedora audit[819]: AVC avc: denied { append } for pid=819 comm="speech-dispatch" name="speech-dispatcher.log" dev="vda3" ino=67199 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:cache_home_t:s0 tclass=file permissive=1 Nov 08 14:38:40 fedora audit[819]: AVC avc: denied { getattr } for pid=819 comm="speech-dispatch" path="/var/roothome/.cache/speech-dispatcher/log/speech-dispatcher.log" dev="vda3" ino=67199 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:cache_home_t:s0 tclass=file permissive=1 Nov 08 14:38:40 fedora audit[819]: AVC avc: denied { create } for pid=819 comm="speech-dispatch" name="speechd.sock" scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:cache_home_t:s0 tclass=sock_file permissive=1 Nov 08 14:38:40 fedora audit[913]: AVC avc: denied { unlink } for pid=913 comm="speech-dispatch" name="speech-dispatcher.pid" dev="vda3" ino=67196 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:cache_home_t:s0 tclass=file permissive=1 Nov 08 14:38:40 fedora audit[913]: AVC avc: denied { lock } for pid=913 comm="speech-dispatch" path="/var/roothome/.cache/speech-dispatcher/pid/speech-dispatcher.pid" dev="vda3" ino=67211 scontext=system_u:system_r:speech_dispatcher_t:s0 tcontext=system_u:object_r:cache_home_t:s0 tclass=file permissive=1