[Bug 2008699] Re: fwupd-refresh.service always fails after hibernate

Mon Feb 27 13:39:51 UTC 2023

> 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.

-- 
You received this bug notification because you are a member of Ubuntu
Foundations Bugs, 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