[Touch-packages] [Bug 2008699] Re: fwupd-refresh.service always fails after hibernate
> 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 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]: [1677497247.0438] device (wlp5s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external') Feb 27 11:27:27 brown kernel: r8169 :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]: [1677497247.2354] device (p2p-dev-wlp5s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external') Feb 27 11:27:27 brown NetworkManager[2048]: [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]: [1677497247.2943] device (wlp5s0): supplicant interface state: internal-starting -> disconnected Feb 27 11:27:27 brown NetworkManager[2048]: [1677497247.2943] device (p2p-dev-wlp5s0): state change: unavailable -> unmanaged (reason 'removed', sys-iface-state: 'removed') Feb 27 11:27:27 brown NetworkManager[2048]: [1677497247.2947] Wi-Fi P2P device controlled by interface wlp5s0 created Feb 27 11:27:27 brown NetworkManager[2048]: [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]: [1677497247.2951] device (p2p-dev-wlp5s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external') Feb 27 11:27:27 brown NetworkManager[2048]: [1677497247.2953] device (wlp5s0): state change: unavailable -> disconnected (reason 'supplicant-available', sys-iface-state: 'managed') Feb 27 11:27:27 brown NetworkManager[2048]: [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]: [base-manager] couldn't check support for device
[Touch-packages] [Bug 2008699] Re: fwupd-refresh.service always fails after hibernate
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]: [1677497247.0438] device (wlp5s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external') Feb 27 11:27:27 brown kernel: r8169 :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]: [1677497247.2354] device (p2p-dev-wlp5s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external') Feb 27 11:27:27 brown NetworkManager[2048]: [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]: [1677497247.2943] device (wlp5s0): supplicant interface state: internal-starting -> disconnected Feb 27 11:27:27 brown NetworkManager[2048]: [1677497247.2943] device (p2p-dev-wlp5s0): state change: unavailable -> unmanaged (reason 'removed', sys-iface-state: 'removed') Feb 27 11:27:27 brown NetworkManager[2048]: [1677497247.2947] Wi-Fi P2P device controlled by interface wlp5s0 created Feb 27 11:27:27 brown NetworkManager[2048]: [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]: [1677497247.2951] device (p2p-dev-wlp5s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external') Feb 27 11:27:27 brown NetworkManager[2048]: [1677497247.2953] device (wlp5s0): state change: unavailable -> disconnected (reason 'supplicant-available', sys-iface-state: 'managed') Feb 27 11:27:27 brown NetworkManager[2048]: [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]: [base-manager] couldn't check support for device '/sys/devices/pci:00/:00:01.2/:02:00.0/:03:04.0/:05:00.0': not supported by any plugin Feb 27 11:27:29
