Bug#943343: fwupd: fwupd-refresh.service failed to start Refresh fwupd metadata and update motd.
Jean-Marc
Version: 1.3.2-2
Severity: normal
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
-- System Information:
Debian Release: bullseye/sid
APT prefers testing
APT policy: (500, 'testing'), (100, 'unstable'), (1, 'experimental')
Architecture: amd64 (x86_64)
Kernel: Linux 5.2.0-3-amd64 (SMP w/8 CPU cores)
Locale: LANG=fr_BE.UTF-8, LC_CTYPE=fr_BE.UTF-8 (charmap=UTF-8), LANGUAGE=fr_BE:fr (charmap=UTF-8)
Shell: /bin/sh linked to /usr/bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled
Versions of packages fwupd depends on:
ii libarchive13 3.4.0-1
ii libc6 2.29-2
ii libefiboot1 37-2
ii libefivar1 37-2
ii libelf1 0.176-1.1
ii libfwupd2 1.3.2-2
ii libgcab-1.0-0 1.3-1
ii libglib2.0-0 2.62.1-1
ii libgnutls30 3.6.9-5
ii libgpg-error0 1.36-7
ii libgpgme11 1.13.1-1
ii libgudev-1.0-0 233-1
ii libgusb2 0.3.0-1
ii libjson-glib-1.0-0 1.4.4-2
ii libpolkit-gobject-1-0 0.105-26
ii libsmbios-c2 2.4.1-1
ii libsoup2.4-1 2.68.2-1
ii libsqlite3-0 3.30.1-1
ii libtss2-esys0 2.1.0-4+b1
ii libxmlb1 0.1.13-1
ii shared-mime-info 1.10-1
Versions of packages fwupd recommends:
ii bolt 0.8-4
ii fwupd-amd64-signed [fwupd-signed] 1.3.2+2
ii python3 3.7.5-1
fwupd suggests no packages.
-- no debconf information
Jean-Marc
<Mario.Li...@dell.com> wrote :
Hi Mario,
> Internal Use - Confidential
>
> In 1.3.2-5 the service is disabled by default (and also this issue should be fixed).
Okay. So, the bug can be closed, I guess.
Jean-Marc <jean...@6jf.be>
https://6jf.be/keys/ED863AD1.txt
Werner Mahr
> >
> > In 1.3.2-5 the service is disabled by default (and also this issue should
be fixed).
> Okay. So, the bug can be closed, I guess.
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
Loaded: loaded (/lib/systemd/system/fwupd-refresh.service; static; vendor
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.
--
MfG usw.
Werner Mahr
Mario.Li...@dell.com
> -----Original Message-----
> From: Werner Mahr <wer...@vollstreckernet.de>
> Sent: Tuesday, December 3, 2019 6:52 AM
> To: 943...@bugs.debian.org
> Subject: Bug#943343: fwupd: fwupd-refresh.service failed to start Refresh fwupd
> metadata and update motd.
>
>
from unstable as well?
Ritesh Raj Sarraf
Version: 1.3.4-1
Followup-For: Bug #943343
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
-- System Information:
Debian Release: bullseye/sid
APT prefers testing
APT policy: (900, 'testing'), (500, 'unstable'), (500, 'stable'), (1, 'experimental')
Architecture: amd64 (x86_64)
Foreign Architectures: i386
Kernel: Linux 5.4.0-1-amd64 (SMP w/8 CPU cores)
Kernel taint flags: TAINT_USER
Locale: LANG=en_IN.UTF-8, LC_CTYPE=en_IN.UTF-8 (charmap=UTF-8), LANGUAGE=en_US (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled
Versions of packages fwupd depends on:
ii libarchive13 3.4.0-1+b1
ii libc6 2.29-3
ii libefiboot1 37-2
ii libefivar1 37-2
ii libelf1 0.176-1.1
ii libfwupd2 1.3.4-1
ii libgcab-1.0-0 1.3-1
ii libglib2.0-0 2.62.3-2
ii libgnutls30 3.6.11.1-2
ii libgpg-error0 1.36-7
ii libgpgme11 1.13.1-1
ii libgudev-1.0-0 233-1
ii libgusb2 0.3.0-1
ii libjson-glib-1.0-0 1.4.4-2
ii libpolkit-gobject-1-0 0.105-26
ii libsmbios-c2 2.4.1-1
ii libsoup2.4-1 2.68.2-1
ii libsqlite3-0 3.30.1-1
ii libtss2-esys0 2.3.1-3
ii libxmlb1 0.1.14-1
ii shared-mime-info 1.10-1
Versions of packages fwupd recommends:
ii bolt 0.8-4
ii fwupd-amd64-signed [fwupd-signed] 1.3.4+1
Mario.Li...@dell.com
I expect that this should not be happening with current systemd in testing and fwupd in testing (or unstable). Can you please confirm?
Diederik de Haas
Version: 1.3.9-2
Followup-For: Bug #943343
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
-- System Information:
Debian Release: bullseye/sid
APT prefers unstable-debug
APT policy: (500, 'unstable-debug'), (500, 'unstable'), (500, 'testing'), (101, 'experimental'), (1, 'experimental-debug')
Architecture: amd64 (x86_64)
Kernel: Linux 5.4.0-4-amd64 (SMP w/16 CPU cores)
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8), LANGUAGE=en_US:en (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled
Versions of packages fwupd depends on:
ii libc6 2.30-2
ii libefiboot1 37-2
ii libefivar1 37-2
ii libelf1 0.176-1.1
ii libflashrom1 1.2-5
ii libfwupd2 1.3.9-2
ii libfwupdplugin1 1.3.9-2
ii libglib2.0-0 2.64.0-2
ii libgnutls30 3.6.12-2
ii libgpg-error0 1.37-1
ii libgpgme11 1.13.1-7
ii libgudev-1.0-0 233-1
ii libgusb2 0.3.0-1
ii libjson-glib-1.0-0 1.4.4-2
ii libpolkit-gobject-1-0 0.105-26
ii libsmbios-c2 2.4.3-1
ii libsoup2.4-1 2.70.0-1
ii libsqlite3-0 3.31.1-4
ii libtss2-esys0 2.3.3-1
ii libxmlb1 0.1.15-1
ii shared-mime-info 1.10-1
Versions of packages fwupd recommends:
ii bolt 0.8-4
ii fwupd-amd64-signed [fwupd-signed] 1.3.9+2
ii python3 3.8.2-1
Diederik de Haas
> 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?
It seems there are no symlinks, so also not broken symlinks.
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
Diederik de Haas
> Has your system been rebooted recently?
Yes. I usually shutdown my system at night.
> 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.
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)
Diederik de Haas
> Sorry - I see now that was from a while back.
And also a different user (OP).
Thomas Stewart
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
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)
Thomas Stewart
> Can you check if fwupdmgr works as a standard user to talk to the daemon for you?
As a normal user I can run "fwupdmgr --version" fine[0].
However if I amend the unit to run the above[1] the output stops before
daemon version[2].
Kind Regards
--
Tom
[0]
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.
Thomas Stewart
Tom
On 28 January 2021 02:12:11 GMT, "Limonciello, Mario" <Mario.Li...@dell.com> wrote:
>Are you by chance using NFS mounted directories? Or external entity
>for authentication such as LDAP or SSSD?
Thomas Stewart
> 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
Amit
fwupd-1.5.3.-2. Removing DynamicUser=yes resolves the issue.
Ross Vandegrift
Version: 1.5.7-3
Followup-For: Bug #943343
X-Debbugs-Cc: rvand...@debian.org
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
-- System Information:
Debian Release: bullseye/sid
APT prefers testing
Architecture: amd64 (x86_64)
Kernel: Linux 5.10.0-6-amd64 (SMP w/4 CPU threads)
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8), LANGUAGE not set
LSM: AppArmor: enabled
Versions of packages fwupd depends on:
ii libcurl3-gnutls 7.74.0-1.2
ii libefiboot1 37-6
ii libelf1 0.183-1
ii libflashrom1 1.2-5
ii libfwupd2 1.5.7-2
ii libfwupdplugin1 1.5.7-2
ii libglib2.0-0 2.66.8-1
ii libgnutls30 3.7.1-3
ii libgudev-1.0-0 234-1
ii libgusb2 0.3.5-1
ii libjcat1 0.1.3-2
ii libjson-glib-1.0-0 1.6.2-1
ii libpolkit-gobject-1-0 0.105-30
ii libsmbios-c2 2.4.3-1
ii libsqlite3-0 3.34.1-3
ii libsystemd0 247.3-3
ii libtss2-esys-3.0.2-0 3.0.3-2
ii libxmlb1 0.1.15-2
ii shared-mime-info 2.0-1
Versions of packages fwupd recommends:
ii dbus 1.12.20-2
ii fwupd-amd64-signed [fwupd-signed] 1.5.7+3
ii python3 3.9.2-2
pn secureboot-db <none>
ii udisks2 2.9.2-1
Versions of packages fwupd suggests:
pn gir1.2-fwupd-2.0 <none>
-- no debconf information
Matthew Gabeler-Lee
Version: 1.5.7-2
Followup-For: Bug #943343
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.
-- System Information:
Debian Release: 11.0
APT prefers testing
APT policy: (990, 'testing'), (500, 'stable'), (500, 'oldstable'), (490, 'unstable'), (1, 'experimental')
Architecture: amd64 (x86_64)
Kernel: Linux 5.10.0-6-amd64 (SMP w/16 CPU threads)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)
ii libefiboot1 37-6
ii libelf1 0.183-1
ii libflashrom1 1.2-5
ii libfwupd2 1.5.7-2
ii libfwupdplugin1 1.5.7-2
ii libglib2.0-0 2.66.8-1
ii libgusb2 0.3.5-1
ii libjcat1 0.1.3-2
ii libjson-glib-1.0-0 1.6.2-1
ii libsqlite3-0 3.34.1-3
ii libxmlb1 0.1.15-2
ii shared-mime-info 2.0-1
ii dbus 1.12.20-2
ii fwupd-amd64-signed [fwupd-signed] 1.5.7+2
ii python3 3.9.2-3
pn secureboot-db <none>
ii udisks2 2.9.2-2
Versions of packages fwupd suggests:
pn gir1.2-fwupd-2.0 <none>
/etc/fwupd/uefi_capsule.conf changed [not included]
-- no debconf information
Philipp Huebner
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
Klaus Kudielka
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:
Tj
Version: 1.5.7-4
Followup-For: Bug #943343
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.
-- System Information:
Debian Release: 11.6
APT prefers stable-updates
APT policy: (500, 'stable-updates'), (500, 'stable-security'), (500, 'stable')
Architecture: amd64 (x86_64)
Foreign Architectures: i386
Kernel: Linux 6.1.7-tj-00007-g94868ba9f924 (SMP w/16 CPU threads; PREEMPT)
Kernel taint flags: TAINT_OOT_MODULE, TAINT_UNSIGNED_MODULE
Locale: LANG=en_GB.UTF-8, LC_CTYPE=en_GB.UTF-8 (charmap=UTF-8), LANGUAGE=en_GB:en
Shell: /bin/sh linked to /usr/bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled
Versions of packages fwupd depends on:
ii libc6 2.31-13+deb11u5
ii libcurl3-gnutls 7.87.0-2~bpo11+1
ii libefiboot1 37-6
ii libelf1 0.183-1
ii libflashrom1 1.2-5
ii libfwupd2 1.5.7-4
ii libfwupdplugin1 1.5.7-4
ii libglib2.0-0 2.66.8-1
ii libgnutls30 3.7.1-5+deb11u2
ii libgudev-1.0-0 234-1
ii libgusb2 0.3.5-1
ii libjcat1 0.1.3-2
ii libjson-glib-1.0-0 1.6.2-1
ii libpolkit-gobject-1-0 0.105-31+deb11u1
ii libsmbios-c2 2.4.3-1
ii libsqlite3-0 3.34.1-3
ii libsystemd0 252.4-1~bpo11+1
ii libtss2-esys-3.0.2-0 3.0.3-2
ii libxmlb1 0.1.15-2
ii shared-mime-info 2.0-1
Versions of packages fwupd recommends:
ii bolt 0.9.1-1
ii dbus 1.12.24-0+deb11u1
ii fwupd-amd64-signed [fwupd-signed] 1.5.7+4
ii python3 3.9.2-3
pn secureboot-db <none>
ii udisks2 2.9.2-2+deb11u1