fwupd-refresh.service always fails after hibernate

[Fabio Ornellas]

fwupd-refresh.service unit is set to After=network.target, however, in practice, the following happens:

- Desktop is active, NetworkManager is connected.
- Machine is hibernated.
- On wakeup, systemd will start NetworkManager then fwupd-refresh.service.

There's however, a race condition there:

- NetworkManager starts first.
- fwupd-refresh.service is started BEFORE NetworkManager has enough time to reconnect to network.
- fwupd-refresh.service fails due to lack of network.
- NetworkManager connects to network a couple seconds later.

The following journal logs illustrate that:

Feb 27 11:27:27 brown NetworkManager[2048]: <info> [1677497247.0438] device (wlp5s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
Feb 27 11:27:27 brown kernel: r8169 0000:06:00.0 enp6s0: Link is Down
Feb 27 11:27:27 brown fwupd[2459754]: 11:27:27:0099 GLib-GObject value "1818326128" of type 'guint' is invalid or out of range for property 'kind' of type 'guint'
Feb 27 11:27:27 brown acpid[2037]: client connected from 4266[0:0]
Feb 27 11:27:27 brown acpid[2037]: 1 client rule loaded
Feb 27 11:27:27 brown NetworkManager[2048]: <info> [1677497247.2354] device (p2p-dev-wlp5s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
Feb 27 11:27:27 brown NetworkManager[2048]: <info> [1677497247.2355] manager: NetworkManager state is now CONNECTED_LOCAL
Feb 27 11:27:27 brown systemd[1]: man-db.service: Deactivated successfully.
Feb 27 11:27:27 brown systemd[1]: Finished Daily man-db regeneration.
Feb 27 11:27:27 brown NetworkManager[2048]: <info> [1677497247.2943] device (wlp5s0): supplicant interface state: internal-starting -> disconnected
Feb 27 11:27:27 brown NetworkManager[2048]: <info> [1677497247.2943] device (p2p-dev-wlp5s0): state change: unavailable -> unmanaged (reason 'removed', sys-iface-state: 'removed')
Feb 27 11:27:27 brown NetworkManager[2048]: <info> [1677497247.2947] Wi-Fi P2P device controlled by interface wlp5s0 created
Feb 27 11:27:27 brown NetworkManager[2048]: <info> [1677497247.2949] manager: (p2p-dev-wlp5s0): new 802.11 Wi-Fi P2P device (/org/freedesktop/NetworkManager/Devices/232)
Feb 27 11:27:27 brown NetworkManager[2048]: <info> [1677497247.2951] device (p2p-dev-wlp5s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
Feb 27 11:27:27 brown NetworkManager[2048]: <info> [1677497247.2953] device (wlp5s0): state change: unavailable -> disconnected (reason 'supplicant-available', sys-iface-state: 'managed')
Feb 27 11:27:27 brown NetworkManager[2048]: <info> [1677497247.2956] device (p2p-dev-wlp5s0): state change: unavailable -> disconnected (reason 'none', sys-iface-state: 'managed')
Feb 27 11:27:27 brown dbus-daemon[2047]: [system] Successfully activated service 'org.freedesktop.fwupd'
Feb 27 11:27:27 brown systemd[1]: Starting Update APT News...
Feb 27 11:27:27 brown systemd[1]: Started Firmware update daemon.
Feb 27 11:27:27 brown systemd[1]: Starting Update the local ESM caches...
Feb 27 11:27:27 brown fwupdmgr[2459622]: (fwupdmgr:2459622): Fwupd-DEBUG: 11:27:27.743: Emitting ::status-changed() [idle]
Feb 27 11:27:27 brown fwupdmgr[2459622]: Updating lvfs
Feb 27 11:27:27 brown fwupdmgr[2459622]: (fwupdmgr:2459622): Fwupd-DEBUG: 11:27:27.750: downloading https://cdn.fwupd.org/downloads/firmware.xml.gz.jcat
Feb 27 11:27:27 brown fwupdmgr[2459622]: (fwupdmgr:2459622): Fwupd-DEBUG: 11:27:27.751: Emitting ::status-changed() [downloading]
Feb 27 11:27:27 brown fwupdmgr[2459622]: Downloading…: 0%
Feb 27 11:27:27 brown fwupdmgr[2459622]: (fwupdmgr:2459622): Fwupd-DEBUG: 11:27:27.751: Emitting ::status-changed() [idle]
Feb 27 11:27:27 brown systemd[1]: fwupd-refresh.service: Main process exited, code=exited, status=1/FAILURE
Feb 27 11:27:27 brown systemd[1]: fwupd-refresh.service: Failed with result 'exit-code'.
Feb 27 11:27:27 brown systemd[1]: Failed to start Refresh fwupd metadata and update motd.
Feb 27 11:27:27 brown systemd[1]: apt-news.service: Deactivated successfully.
Feb 27 11:27:27 brown systemd[1]: Finished Update APT News.
Feb 27 11:27:28 brown wpa_supplicant[2114]: wlp5s0: Reject scan trigger since one is already pending
Feb 27 11:27:29 brown ModemManager[2147]: <info> [base-manager] couldn't check support for device '/sys/devices/pci0000:00/0000:00:01.2/0000:02:00.0/0000:03:04.0/0000:05:00.0': not supported by any plugin
Feb 27 11:27:29 brown ModemManager[2147]: <info> [base-manager] couldn't check support for device '/sys/devices/pci0000:00/0000:00:01.2/0000:02:00.0/0000:03:05.0/0000:06:00.0': not supported by any plugin
Feb 27 11:27:30 brown wpa_supplicant[2114]: wlp5s0: CTRL-EVENT-REGDOM-CHANGE init=DRIVER type=COUNTRY alpha2=EU
Feb 27 11:27:30 brown NetworkManager[2048]: <info> [1677497250.4717] device (enp6s0): carrier: link connected
Feb 27 11:27:30 brown NetworkManager[2048]: <info> [1677497250.4718] device (enp6s0): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')
Feb 27 11:27:30 brown NetworkManager[2048]: <info> [1677497250.4722] policy: auto-activating connection 'Wired connection 1' (a7e4e975-d8bd-3f26-9ee4-e201b1c20ca8)
Feb 27 11:27:30 brown NetworkManager[2048]: <info> [1677497250.4724] device (enp6s0): Activation: starting connection 'Wired connection 1' (a7e4e975-d8bd-3f26-9ee4-e201b1c20ca8)
Feb 27 11:27:30 brown NetworkManager[2048]: <info> [1677497250.4725] device (enp6s0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Feb 27 11:27:30 brown NetworkManager[2048]: <info> [1677497250.4726] manager: NetworkManager state is now CONNECTING
Feb 27 11:27:30 brown NetworkManager[2048]: <info> [1677497250.4727] device (enp6s0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Feb 27 11:27:30 brown NetworkManager[2048]: <info> [1677497250.4729] device (enp6s0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Feb 27 11:27:30 brown NetworkManager[2048]: <info> [1677497250.4731] dhcp4 (enp6s0): activation: beginning transaction (timeout in 45 seconds)

The service will be in a failed state, until fwupd-refresh.timer kicks in, which can take up to 12h to happen.

As I have alerts on my machine to detect failed systemd units, this ends up triggering every time the machine is hibernated. Arguably, the alert should be bound by the 12h fwupd-refresh.timer (and only trigger after 12h of being continuously in a fail state, but it seems that addressing this race condition, would still be valid.

One possibility, is to leverage systemd [Service] Restart, and add some retries there, with a couple seconds interval. This should be enough to give time for NetworkManager to get network access working, so fwupd-refresh.service can succeed. Or, we may just add a sleep 60 before /usr/bin/fwupdmgr refresh, same effect.

ProblemType: Bug
DistroRelease: Ubuntu 22.04
Package: fwupd 1.7.9-1~22.04.1 [modified: lib/systemd/system/fwupd-refresh.service]
ProcVersionSignature: Ubuntu 5.15.0-60.66-generic 5.15.78
Uname: Linux 5.15.0-60-generic x86_64
NonfreeKernelModules: nvidia_modeset nvidia
ApportVersion: 2.20.11-0ubuntu82.3
Architecture: amd64
CasperMD5CheckResult: pass
CurrentDesktop: Budgie:GNOME
Date: Mon Feb 27 12:08:54 2023
InstallationDate: Installed on 2023-02-11 (15 days ago)
InstallationMedia: Ubuntu-MATE 22.04.1 LTS "Jammy Jellyfish" - Release amd64 (20220809.1)
SourcePackage: fwupd
UpgradeStatus: No upgrade log present (probably fresh install)

[Mario Limonciello (superm1)]

Can you please bring this bug report upstream for discussion?

I think we want a general solution not a Ubuntu specific one.

[Mario Limonciello (superm1)]

BTW - fwupd already uses network-online.target for this unit. One could probably argue this is a systemd bug.

> [Unit]
> Description=Refresh fwupd metadata and update motd
> Documentation=man:fwupdmgr(1)
> After=network-online.target
>
> [Service]
> Type=oneshot
> CacheDirectory=fwupdmgr
> StandardError=null
> @user@
> RestrictAddressFamilies=AF_NETLINK AF_UNIX AF_INET AF_INET6
> SystemCallFilter=~@mount
> ProtectKernelModules=yes
> ProtectControlGroups=yes
> RestrictRealtime=yes
> SuccessExitStatus=2
> ExecStart=@bindir@/fwupdmgr refresh

[Fabio Ornellas (fabio-ornellas)]

https://github.com/fwupd/fwupd/issues/5590

[Fabio Ornellas (fabio-ornellas)]

> BTW - fwupd already uses network-online.target for this unit. One could probably argue this is a systemd bug.

Where? /usr/lib/systemd/system/fwupd-refresh.service only has After=network.target. Perhaps that'd be the fix.

[Mario Limonciello (superm1)]

> Where? /usr/lib/systemd/system/fwupd-refresh.service only has After=network.target. Perhaps that'd be the fix.

Ah... this was fixed in upstream already in 1.8.5 release.
https://github.com/fwupd/fwupd/commit/fe5d93f7d2712f3b708e562a5f7e9be897e04d1d

[Mario Limonciello (superm1)]

Please apply that locally, reload your units and see if it's enough to fix the issue. If it's not then we'll need a second fix that I just opened a PR for probably.

[Mario Limonciello (superm1)]

I've uploaded a 1.9.16 fwupd and 0.3.18 libxmlb (build-dependency for fwpud 1.9.16) to the archive for an SRU team member to review. It should fall under https://launchpad.net/~superm1/+archive/ubuntu/uefi/+packages

I've got build logs and a diff of the uploads posted at this PPA as well:
https://launchpad.net/~superm1/+archive/ubuntu/uefi/+packages