Dear Maintainer,
On my PC, fwupd-refresh.service failed to start.
$ systemctl status fwupd-refresh.service
● fwupd-refresh.service - Refresh fwupd metadata and update motd
Loaded: loaded (/lib/systemd/system/fwupd-refresh.service; static; vendor preset: enabled)
Active: failed (Result: exit-code) since Wed 2019-10-23 16:06:35 CEST; 2h 13min ago
Docs: man:fwupdmgr(1)
Process: 4608 ExecStart=/usr/bin/fwupdmgr refresh (code=exited, status=0/SUCCESS)
Process: 4624 ExecStart=/usr/bin/fwupdmgr get-updates --log 85-fwupd (code=exited, status=1/FAILURE)
Main PID: 4624 (code=exited, status=1/FAILURE)
oct 23 16:06:35 svrname systemd[1]: Starting Refresh fwupd metadata and update motd...
oct 23 16:06:35 svrname fwupdmgr[4608]: Fetching metadata https://cdn.fwupd.org/downloads/firmware.xml.gz
oct 23 16:06:35 svrname fwupdmgr[4608]: Fetching signature https://cdn.fwupd.org/downloads/firmware.xml.gz.asc
oct 23 16:06:35 svrname systemd[1]: fwupd-refresh.service: Main process exited, code=exited, status=1/FAILURE
oct 23 16:06:35 svrname systemd[1]: fwupd-refresh.service: Failed with result 'exit-code'.
oct 23 16:06:35 svrname systemd[1]: Failed to start Refresh fwupd metadata and update motd.
That's the service definition:
$ systemctl cat fwupd-refresh.service
# /lib/systemd/system/fwupd-refresh.service
[Unit]
Description=Refresh fwupd metadata and update motd
Documentation=man:fwupdmgr(1)
After=network.target network-online.target systemd-networkd.service NetworkManager.service connman.service
[Service]
Type=oneshot
RuntimeDirectory=motd.d
CacheDirectory=fwupdmgr
RuntimeDirectoryPreserve=yes
StandardError=null
ExecStart=/usr/bin/fwupdmgr refresh
ExecStart=/usr/bin/fwupdmgr get-updates --log 85-fwupd
DynamicUser=yes
RestrictAddressFamilies=AF_NETLINK AF_UNIX AF_INET AF_INET6
SystemCallFilter=~@mount
ProtectKernelModules=yes
ProtectControlGroups=yes
RestrictRealtime=yes
And about the runtime directory:
$ ls -ld /run/motd.d
lrwxrwxrwx 1 root root 14 oct 23 16:06 /run/motd.d -> private/motd.d
$ ls -ld /run/private/
drwx------ 3 root root 60 oct 23 16:06 /run/private/
$ sudo ls -ld /run/private/motd.d
drwxr-xr-x 2 62803 62803 40 oct 23 16:06 /run/private/motd.d
$ sudo ls -l /run/private/motd.d
total 0
Kind Regards,
Jean-Marc
Internal Use - Confidential In 1.3.2-5 the service is disabled by default (and also this issue should be fixed).
Wed, 23 Oct 2019 16:40:37 +0000 <Mario.Limonciello@dell.com> wrote : Hi Mario, Okay. So, the bug can be closed, I guess. Jean-Marc <jean-marc@6jf.be> https://6jf.be/keys/ED863AD1.txt
Internal Use - Confidential In 1.3.2-5 the service is disabled by default (and also this issue should be fixed).
be fixed). 1.3.4-1 installed on testing and it fails to start. Unfortunately is is not that verbose on the logs. $ service fwupd-refresh status ● fwupd-refresh.service - Refresh fwupd metadata and update motd Loaded: loaded (/lib/systemd/system/fwupd-refresh.service; static; vendor preset: disabled) Active: failed (Result: exit-code) since Mon 2019-12-02 09:16:34 CET; 2h 8min ago Docs: man:fwupdmgr(1) Process: 144751 ExecStart=/usr/bin/fwupdmgr refresh --no-metadata-check (code=exited, status=1/FAILURE) Main PID: 144751 (code=exited, status=1/FAILURE) Dez 02 09:16:34 werner1 systemd[1]: Starting Refresh fwupd metadata and update motd... Dez 02 09:16:34 werner1 systemd[1]: fwupd-refresh.service: Main process exited, code=exited, status=1/FAILURE Dez 02 09:16:34 werner1 systemd[1]: fwupd-refresh.service: Failed with result 'exit-code'. Dez 02 09:16:34 werner1 systemd[1]: Failed to start Refresh fwupd metadata and update motd. Called from cmdline directly it still works.
Internal Use - Confidential What version of systemd are you running on your local system? Did you bring that back from unstable as well?
This is still broken with current mentioned version in Debian Testing. I
thought this was fixed a couple months ago.
rrs@priyasi:/var/tmp/Debian-Build/Result$ systemctl status fwupd-refresh.service
● fwupd-refresh.service - Refresh fwupd metadata and update motd
Loaded: loaded (/lib/systemd/system/fwupd-refresh.service; static; vendor preset: disabled)
Active: failed (Result: exit-code) since Mon 2019-12-30 21:21:11 IST; 10min ago
TriggeredBy: ● fwupd-refresh.timer
Docs: man:fwupdmgr(1)
Process: 108303 ExecStart=/usr/bin/fwupdmgr refresh --no-metadata-check (code=exited, status=1/FAILURE)
Main PID: 108303 (code=exited, status=1/FAILURE)
Dec 30 21:21:06 priyasi systemd[1]: Starting Refresh fwupd metadata and update motd...
Dec 30 21:21:06 priyasi fwupdmgr[108303]: Fetching metadata https://cdn.fwupd.org/downloads/firmware.xml.gz
Dec 30 21:21:11 priyasi systemd[1]: fwupd-refresh.service: Main process exited, code=exited, status=1/FAILURE
Dec 30 21:21:11 priyasi systemd[1]: fwupd-refresh.service: Failed with result 'exit-code'.
Dec 30 21:21:11 priyasi systemd[1]: Failed to start Refresh fwupd metadata and update motd.
21:32 ♒ ॐ ☹ => 3
I expect that this should not be happening with current systemd in testing and fwupd in testing (or unstable). Can you please confirm?
Essentially the same issue as initially reported, but just got version
1.3.9-2 and it's still happening.
Running the 'ExecStart' line manually succeeded successfully.
root@bagend:~# systemctl status fwupd-refresh.service
● fwupd-refresh.service - Refresh fwupd metadata and update motd
Loaded: loaded (/lib/systemd/system/fwupd-refresh.service; static; vendor preset: disabled)
Active: failed (Result: exit-code) since Sat 2020-03-14 09:37:54 CET; 3h 32min ago
TriggeredBy: ● fwupd-refresh.timer
Docs: man:fwupdmgr(1)
Main PID: 13148 (code=exited, status=1/FAILURE)
mrt 14 09:37:54 bagend systemd[1]: Starting Refresh fwupd metadata and update motd...
mrt 14 09:37:54 bagend systemd[1]: fwupd-refresh.service: Main process exited, code=exited, status=1/FAILURE
mrt 14 09:37:54 bagend systemd[1]: fwupd-refresh.service: Failed with result 'exit-code'.
mrt 14 09:37:54 bagend systemd[1]: Failed to start Refresh fwupd metadata and update motd.
root@bagend:~# systemctl restart fwupd-refresh.service
Job for fwupd-refresh.service failed because the control process exited with error code.
See "systemctl status fwupd-refresh.service" and "journalctl -xe" for details.
root@bagend:~# journalctl -xe
-- A start job for unit fwupd-refresh.timer has finished successfully.
--
-- The job identifier is 5651.
mrt 14 13:08:51 bagend systemd[1]: Reloading.
mrt 14 13:08:51 bagend systemd[1]: /lib/systemd/system/dbus.socket:5: ListenStream= references a path below legacy directory /var/run/, updating /var/run/d>
mrt 14 13:08:52 bagend systemd[1]: Reloading.
mrt 14 13:08:52 bagend systemd[1]: /lib/systemd/system/dbus.socket:5: ListenStream= references a path below legacy directory /var/run/, updating /var/run/d>
mrt 14 13:08:55 bagend dbus-daemon[828]: [system] Reloaded configuration
mrt 14 13:10:24 bagend systemd[1]: Starting Refresh fwupd metadata and update motd...
-- Subject: A start job for unit fwupd-refresh.service has begun execution
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- A start job for unit fwupd-refresh.service has begun execution.
--
-- The job identifier is 5965.
mrt 14 13:10:24 bagend systemd[1]: fwupd-refresh.service: Main process exited, code=exited, status=1/FAILURE
-- Subject: Unit process exited
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- An ExecStart= process belonging to unit fwupd-refresh.service has exited.
--
-- The process' exit code is 'exited' and its exit status is 1.
mrt 14 13:10:24 bagend systemd[1]: fwupd-refresh.service: Failed with result 'exit-code'.
-- Subject: Unit failed
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- The unit fwupd-refresh.service has entered the 'failed' state with result 'exit-code'.
mrt 14 13:10:24 bagend systemd[1]: Failed to start Refresh fwupd metadata and update motd.
-- Subject: A start job for unit fwupd-refresh.service has failed
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- A start job for unit fwupd-refresh.service has finished with a failure.
--
-- The job identifier is 5965 and the job result is failed.
root@bagend:~# cat $(locate fwupd-refresh.service)
[Unit]
Description=Refresh fwupd metadata and update motd
Documentation=man:fwupdmgr(1)
After=network.target network-online.target systemd-networkd.service NetworkManager.service connman.service
[Service]
Type=oneshot
CacheDirectory=fwupdmgr
StandardError=null
DynamicUser=yes
RestrictAddressFamilies=AF_NETLINK AF_UNIX AF_INET AF_INET6
SystemCallFilter=~@mount
ProtectKernelModules=yes
ProtectControlGroups=yes
RestrictRealtime=yes
SuccessExitStatus=2
ExecStart=/usr/bin/fwupdmgr refresh --no-metadata-check
root@bagend:~# /usr/bin/fwupdmgr refresh --no-metadata-check
Fetching metadata https://cdn.fwupd.org/downloads/firmware.xml.gz
Downloading… [***************************************]
Fetching signature https://cdn.fwupd.org/downloads/firmware.xml.gz.asc
Successfully downloaded new metadata: 1 local device supported
I suspect this is related to an upgrade from the intermediary version that had problematic objects/permissions created. Can you please try to check whether there are broken symlinks in /var/lib/private or /var/cache/private? Thanks,
root@bagend:~# ls -la /var/lib/private/ total 12 drwx------ 3 root root 4096 mei 3 2018 . drwxr-xr-x 82 root root 4096 mrt 19 08:47 .. drwxr-xr-x 2 root root 4096 jan 10 2019 systemd root@bagend:~# ls -la /var/lib/private/systemd/ total 8 drwxr-xr-x 2 root root 4096 jan 10 2019 . drwx------ 3 root root 4096 mei 3 2018 .. root@bagend:~# ls -la /var/cache/private/ total 16 drwx------ 4 root root 4096 okt 9 21:36 . drwxr-xr-x 22 root root 4096 mrt 9 11:56 .. drwxr-xr-x 2 62803 62803 4096 jul 30 2019 fwupd drwxr-xr-x 2 62803 62803 4096 okt 9 21:36 fwupdmgr root@bagend:~# ls -la /var/cache/private/fwupd/ total 720 drwxr-xr-x 2 62803 62803 4096 jul 30 2019 . drwx------ 4 root root 4096 okt 9 21:36 .. -rw-r--r-- 1 62803 62803 722862 jul 30 2019 metadata.xmlb -rw-r--r-- 1 62803 62803 1471 jul 30 2019 metainfo.xmlb root@bagend:~# ls -la /var/cache/private/fwupdmgr/ total 8 drwxr-xr-x 2 62803 62803 4096 okt 9 21:36 . drwx------ 4 root root 4096 okt 9 21:36 .. FTR: My system is a fully up-to-date Sid system # systemd --version systemd 245 (245.2-1) +PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=hybrid
Has your system been rebooted recently? I check on my (working) system and I don't have /run/motd.d as a symlink to /run/private/motd.d. For my system /run/motd.d is a real directory with a subdirectory "fwupd". I have a suspicion this is related to the issue.
Yes. I usually shutdown my system at night. I don't have a /run/private directory and also no /run/motd.d. I do have /run/motd.dynamic which is the same as "uname -nrsvm" (uname -a minus the GNU/Linux part)
And about the runtime directory: $ ls -ld /run/motd.d lrwxrwxrwx 1 root root 14 oct 23 16:06 /run/motd.d -> private/motd.d $ ls -ld /run/private/ drwx------ 3 root root 60 oct 23 16:06 /run/private/ $ sudo ls -ld /run/private/motd.d drwxr-xr-x 2 62803 62803 40 oct 23 16:06 /run/private/motd.d $ sudo ls -l /run/private/motd.d total 0
Sorry - I see now that was from a while back.
And also a different user (OP).
After some upstream discussion, any remaining issues with 1.3.x this is expected to be root caused in a CDN caching problem that will be transient. The architecture was changed in the 1.4.x series, so please if this is still present in 1.4.x or 1.5.x please notify.
Hi, I'm running testing/sid and have fwupd-1.5.5-2 installed. I have found that when fwupd-refresh.service restarts either with the timer or manually that if DynamicUser=yes is enabled then the service fails to start[0]. When I remove DynamicUser from the unit it restarts fine. I noticed that the unit has: CacheDirectory=fwupdmgr but the metadata seems to live in /var/cache/fwupd[1]. After purging the package and removing /var/cache/fwup* /var/lib/fwupd /var/cache/private/fwupd and reinstalling I can see the /var/cache dirs created[2] but the service does not start. When removing the "StandardError=null" directive from the unit I get an additional error[3], which seems to indicate it's having trouble talking to dbus. Kind Regards -- Tom [0] $ sudo systemctl restart fwupd-refresh.service Job for fwupd-refresh.service failed because the control process exited with error code. See "systemctl status fwupd-refresh.service" and "journalctl -xe" for details. $ $ sudo journalctl -f Jan 27 10:09:30 systemd[1]: Starting Refresh fwupd metadata and update motd... Jan 27 10:09:31 fwupdmgr[176638]: (fwupdmgr:176638): GLib-DEBUG: 10:09:31.089: setenv()/putenv() are not thread-safe and should not be used after threads are created Jan 27 10:09:31 systemd[1]: fwupd-refresh.service: Main process exited, code=exited, status=1/FAILURE Jan 27 10:09:31 systemd[1]: fwupd-refresh.service: Failed with result 'exit-code'. Jan 27 10:09:31 systemd[1]: Failed to start Refresh fwupd metadata and update motd. $ [1] $ find /var/cache/fw* /var/cache/fwupd /var/cache/fwupd/metadata.xmlb /var/cache/fwupd/quirks.xmlb /var/cache/fwupd/metainfo.xmlb /var/cache/fwupdmgr $ [2] $ sudo ls -la /var/cache/fwupdmgr /var/cache/private/fwupdmgr lrwxrwxrwx 1 root root 16 Jan 27 10:57 /var/cache/fwupdmgr -> private/fwupdmgr /var/cache/private/fwupdmgr: total 8 drwxr-xr-x 2 62803 62803 4096 Jan 27 10:57 . drwx------ 3 root root 4096 Jan 27 10:57 .. $ [3] Jan 27 11:09:30 fwupdmgr[189035]: Failed to connect to daemon: Exhausted all available authentication mechanisms (tried: EXTERNAL) (available: EXTERNAL)
However if I amend the unit to run the above[1] the output stops before
daemon version[2].
Kind Regards
--
Tom
[0]
$ id
uid=1000(thomas) gid=1000(thomas) groups=1000(thomas),20(dialout),27(sudo),128(docker)
$
$ /usr/bin/fwupdmgr --version
client version: 1.5.5
compile-time dependency versions
gusb: 0.3.5
daemon version: 1.5.5
$
[1]
ExecStart=/usr/bin/fwupdmgr --version
[2]
Jan 27 14:24:38 systemd[1]: Starting Refresh fwupd metadata and update motd...
Jan 27 14:24:38 fwupdmgr[199579]: client version: 1.5.5
Jan 27 14:24:38 fwupdmgr[199579]: compile-time dependency versions
Jan 27 14:24:38 fwupdmgr[199579]: gusb: 0.3.5
Jan 27 14:24:38 fwupdmgr[199579]: Failed to connect to daemon: Exhausted all available authentication mechanisms (tried: EXTERNAL) (available: EXTERNAL)
Jan 27 14:24:38 systemd[1]: fwupd-refresh.service: Main process exited, code=exited, status=1/FAILURE
Jan 27 14:24:38 systemd[1]: fwupd-refresh.service: Failed with result 'exit-code'.
Jan 27 14:24:38 systemd[1]: Failed to start Refresh fwupd metadata and update motd.
Can you check if fwupdmgr works as a standard user to talk to the daemon for you?
Are you by chance using NFS mounted directories? Or external entity for authentication such as LDAP or SSSD?
Yes, I'm using sssd against FreeIPA. Tom
I'm unsure what to do here, it seems to me that there is a problem with systemd using DynamicUser and sssd when the service uses dbus. Perhaps this should be re-assigned to systemd.
I will attempt to reproduce on a non freeipa joined machine. Kind Regards -- Tom
Just chiming in here. I see this issue on Debian Testing with fwupd-1.5.3.-2. Removing DynamicUser=yes resolves the issue.
I have a pair of laptops, one where fwupd-refresh.service is broken and one
where it works. Both are running bullseye with the same versions of fwupd,
systemd, and dbus. No remote users, nfs, freeipa, etc.
I've run both with this config:
$ cat /etc/systemd/system/fwupd-refresh.service.d/override.conf
[Service]
StandardError=
StandardError=journal
ExecStart=
ExecStart=/usr/bin/strace -ff /usr/bin/fwupdmgr -v refresh
The results aren't too enlightening - the broken one cannot auth to dbus as
it's systemd dynamic user:
socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC, 0) = 7
fcntl(7, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(7, F_SETFL, O_RDWR|O_NONBLOCK) = 0
connect(7, {sa_family=AF_UNIX, sun_path="/var/run/dbus/system_bus_socket"}, 110) = 0
sendmsg(7, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\0", iov_len=1}], msg_iovlen=1, msg_control=[{cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS, cmsg_data={pid=128515, uid=62803, gid=62803}}], msg_controllen=32, msg_flags=0}, MSG_NOSIGNAL) = 1
sendto(7, "AUTH\r\n", 6, MSG_NOSIGNAL, NULL, 0) = 6
recvfrom(7, "REJECTED EXTERNAL\r\n", 4096, 0, NULL, NULL) = 19
sendto(7, "AUTH EXTERNAL 3632383033\r\n", 26, MSG_NOSIGNAL, NULL, 0) = 26
recvfrom(7, "REJECTED EXTERNAL\r\n", 4096, 0, NULL, NULL) = 19
I don't know why that would fail. If I could provide more details or test
something, please let me know.
Ross
This started out as what I thought may be the same essential data as Ross Vandergrift reported above, but I think I've figured out the problem. I'm seeing this same issue on a bullseye system. Interestingly, not on _all_ of my bullseye systems, even though I thought they were all configured equivalently as far as this package would be concerned. On the failing system, if I use `systemctl edit fwupd-refresh.service` to change `StandardError` from `null` to `inherit`, I see this error when it fails: Jun 21 12:15:26 myhostname systemd[1]: Starting Refresh fwupd metadata and update motd... Jun 21 12:15:26 myhostname fwupdmgr[3874480]: Failed to connect to daemon: Exhausted all available authentication mechanisms (tried: EXTERNAL) (available: EXTERNAL) Jun 21 12:15:26 myhostname systemd[1]: fwupd-refresh.service: Main process exited, code=exited, status=1/FAILURE Jun 21 12:15:26 myhostname systemd[1]: fwupd-refresh.service: Failed with result 'exit-code'. Jun 21 12:15:26 myhostname systemd[1]: Failed to start Refresh fwupd metadata and update motd. If I apply a fixed version of Ross' "strace" change to the refresh service (need to clear ExecStart first), I see the "AUTH EXTERNAL" handshake is _exactly_ the same ... which I guess isn't the same because the dynamic user id is chosen from hashing the same username, and so isn't actually all that "dynamic". Looking for other differences between the working and non-working systems, I notice the working system has a /etc/dbus-1/system.d/org.freedesktop.fwupd.conf file that is an exact copy of its /usr/share/ counterpart. But replicating that on the working system and doing `systemctl reload dbus` doesn't fix things, and removing it on the working system doesn't break things. I resorted to rummaging in the dbus code itself to see why `AUTH EXTERNAL` might fail, and most of it was pretty basic stuff like not providing a user, or malloc failures or things like that, which I was pretty sure were not the problem. About the only thing left was this block of code: https://github.com/freedesktop/dbus/blob/ef55a3db0d8f17848f8a579092fb05900cc076f5/dbus/dbus-auth.c#L1152 if (!_dbus_credentials_add_from_user (auth->desired_identity, &auth->identity, DBUS_CREDENTIALS_ADD_FLAGS_NONE, &error)) { // ... _dbus_verbose ("%s: could not get credentials from uid string: %s\n", DBUS_AUTH_NAME (auth), error.message); // ... return send_rejected (auth); } } And thought "OK, so it wants to look up user info from a uid" and thought "how the heck does that work with dynamic users?" On a lark I went looking at /etc/nsswitch.conf on the working vs. non-working systems, and noticed that the working system has "systemd" listed under "passwd" and "group", and has `libnss-systemd` installed. The non-working system has neither! So I installed that package and did `sudo systemctl restart dbus` and ... Voila! Broken system now works. So, libnss-systemd is only a Recommends in various places. This package seems to _Depend_ on it being installed & configured for its default installation to work properly.
Hi there, looking into the same issues on multiple Bullseye systems, I can confirm the cause to be an incorrect /etc/nsswitch.conf. After fixing that I had to reboot for the fix to work, I guess restarting some systemd or dbus service would have done the trick as well. Now for a proper fix: IMHO fwupd should either depend on libnss-systemd or disable the refresh service and timer in postinst if this recommended package is not present. Best wishes Philipp Huebner
Dear Maintainer, Note that with an old system with libnss-systemd installed my /etc/nssswitch.conf was missing systemd for passwd and group lines. Be it per manual change or my system being an upgrade from pre stretch time, libnss-systemd only adds the systemd entries to these lines on the first install. So a note in the README of the package that this entry is required on those lines seems required, at least if having an nsswitch.conf customized is supported by Debian. Cheers, Alban
For the records: Up to and including systemd 250.3 (testing), the service worked (with libnss-systemd installed). After upgrade to systemd 250.4, yet another failure mechanism seems to have popped up: "DynamicUser is denied access to dbus-daemon after a recent lockup bugfix" https://github.com/systemd/systemd/issues/22737 End result: systemd[1]: Failed to start Refresh fwupd metadata and update motd. Regards, Klaus
Following Klaus Kudielka's discovery of the systemd bug and the finding there that dbus-broker does not suffer the same problem as the dbus reference implementation I installed "dbus-broker" following the instructions at https://github.com/bus1/dbus-broker/wiki which boils down to: apt install dbus-broker systemctl enable dbus-broker.service systemctl --global enable dbus-broker.service systemctl reboot $ sudo systemctl start fwupd-refresh $ systemctl status fwupd-refresh ○ fwupd-refresh.service - Refresh fwupd metadata and update motd Loaded: loaded (/lib/systemd/system/fwupd-refresh.service; static) Active: inactive (dead) since Thu 2023-02-02 11:22:20 GMT; 1s ago TriggeredBy: ● fwupd-refresh.timer Docs: man:fwupdmgr(1) Process: 4870 ExecStart=/usr/bin/fwupdmgr refresh (code=exited, status=2) Main PID: 4870 (code=exited, status=2) CPU: 35ms $ systemctl list-units --state failed UNIT LOAD ACTIVE SUB DESCRIPTION 0 loaded units listed.