https://github.com/fwupd/fwupd/issues/5590
** Bug watch added: github.com/fwupd/fwupd/issues #5590 https://github.com/fwupd/fwupd/issues/5590 -- You received this bug notification because you are a member of Ubuntu Touch seeded packages, which is subscribed to systemd in Ubuntu. https://bugs.launchpad.net/bugs/2008699 Title: fwupd-refresh.service always fails after hibernate Status in fwupd package in Ubuntu: New Status in systemd package in Ubuntu: New Bug description: 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) To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/fwupd/+bug/2008699/+subscriptions -- Mailing list: https://launchpad.net/~touch-packages Post to : touch-packages@lists.launchpad.net Unsubscribe : https://launchpad.net/~touch-packages More help : https://help.launchpad.net/ListHelp
