Bug 1685471 - Fails to install offline updates due to fwupd time-out
Summary: Fails to install offline updates due to fwupd time-out
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: fwupd
Version: 29
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Richard Hughes
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
: 1685815 1692066 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-03-05 10:05 UTC by Tim Waugh
Modified: 2019-05-10 09:00 UTC (History)
14 users (show)

Fixed In Version: fwupd-1.2.6-1.fc29
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-03-31 03:00:41 UTC


Attachments (Terms of Use)
Section of the system log during an offline-update boot that failed. The section reaches the end of the log for that boot. (13.57 KB, text/plain)
2019-03-07 19:47 UTC, krinkodot22
no flags Details
Untrimmed boot log of a failed offline update. (69.46 KB, text/plain)
2019-03-26 02:42 UTC, krinkodot22
no flags Details
Untrimmed boot log of a successful offline update. (483.01 KB, text/plain)
2019-03-26 02:56 UTC, krinkodot22
no flags Details

Description Tim Waugh 2019-03-05 10:05:54 UTC
Description of problem:
When rebooting to install offline updates, the updates are aborted about half-way through.

This had been working without issue until the last week or so.

Version-Release number of selected component (if applicable):
fwupd-1.2.5-1.fc29.x86_64
PackageKit-1.1.12-2.fc29.x86_64

How reproducible:
Often.

Steps to Reproduce:
1.With updates to apply, Power Off with 'install updates' checked
2.On next boot, examine journal (journalctl -b -1)

Actual results:
Mar 05 09:53:46 river pk-offline-update[1019]: status install
Mar 05 09:53:46 river pk-offline-update[1019]: package installing        kernel-devel-4.20.13-200.fc29.x86_64 (updates)
Mar 05 09:53:46 river pk-offline-update[1019]: percentage 52%
Mar 05 09:53:46 river pk-offline-update[1019]: sent msg to plymouth 'Installing Updates - 52%'
Mar 05 09:53:51 river pk-offline-update[1019]: percentage 53%
Mar 05 09:53:51 river pk-offline-update[1019]: sent msg to plymouth 'Installing Updates - 53%'
Mar 05 09:53:52 river pk-offline-update[1019]: percentage 54%
Mar 05 09:53:52 river pk-offline-update[1019]: sent msg to plymouth 'Installing Updates - 54%'
Mar 05 09:53:53 river pk-offline-update[1019]: percentage 55%
Mar 05 09:53:53 river pk-offline-update[1019]: sent msg to plymouth 'Installing Updates - 55%'
Mar 05 09:53:54 river pk-offline-update[1019]: status update
Mar 05 09:53:58 river dbus-daemon[1025]: [system] Failed to activate service 'org.freedesktop.fwupd': timed out (service_start_timeout=25000ms)
Mar 05 09:53:58 river fwupdmgr[1017]: Failed to connect to daemon: Error calling StartServiceByName for org.freedesktop.fwupd: GDBus.Error:org.freedesktop.DBus.Error.TimedOut: Failed to activate service 'org.freedesktop.fwupd': timed out (service_start_timeout=25000ms)
Mar 05 09:53:58 river systemd[1]: fwupd-offline-update.service: Main process exited, code=exited, status=1/FAILURE
Mar 05 09:53:58 river systemd[1]: fwupd-offline-update.service: Failed with result 'exit-code'.
Mar 05 09:53:58 river systemd[1]: fwupd-offline-update.service: Triggering OnFailure= dependencies.

Expected results:
Successful offline update.

Comment 1 krinkodot22 2019-03-07 19:46:25 UTC
The same issue has been affecting me recently, as well. When an offline update boot fails, the computer reboots and starts up without applying any updates. Upon logging in, Gnome Software doesn't show a notification for any errors that occurred, though it does have the ability to do so.

Updating the system via dnf or pkcon on the command line works.

I'll attach a section of the log from a failed offline update boot.

Comment 2 krinkodot22 2019-03-07 19:47:58 UTC
Created attachment 1541966 [details]
Section of the system log during an offline-update boot that failed. The section reaches the end of the log for that boot.

Comment 3 Kalev Lember 2019-03-08 09:39:01 UTC
Looks like an fwupd issue. Reassigning.

zbyszek, you've fixed some issue in the offline update systemd services, do you know if fwupd should do something different to not trigger a reboot while packagekit offline update service is in the middle of an update?

Comment 4 Richard Hughes 2019-03-08 10:02:17 UTC
so, it looks like:

[Unit]
Description=Updates device firmware whilst offline
Documentation=man:fwupdmgr
OnFailure=reboot.target
ConditionPathExists=/var/lib/fwupd/pending.db

i.e. systemd runs reboot.target if the @bindir@/fwupdmgr program exits with an error...

So really there are three bugs here:

1. fwupd fails to start for some reason
2. We run fwupd-offline-update when not strictly required
3. systemd reboots rather than continuing the other offline updates services

For part 1: can anyone affected reproduce fwupd not loading in the running session? i.e. "fwupdmgr get-updates" would return with "Error calling StartServiceByName for org.freedesktop.fwupd" -- or does anyone have any journal logs from the offline update that show why fwupd failed to load

For parts 2 and 3 I think we need to copy the fixes from PackageKit for the new logic in the systemd offine updates logic. See https://github.com/hughsie/fwupd/pull/1078 for the discussion about that.

Comment 5 Tim Waugh 2019-03-08 11:06:27 UTC
Running "fwupdmgr get-updates" from a user session works fine. But I have this in my logs from before I tried that:

Mar 07 09:18:35 river dbus-daemon[1078]: [system] Activating via systemd: service name='org.freedesktop.fwupd' unit='fwupd.service' requested by ':1.440' (uid=1000 pid=8219 comm="/usr/bin/gnome-software --gapplication-service " label="unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023")
Mar 07 09:18:35 river systemd[1]: Starting Firmware update daemon...
Mar 07 09:18:35 river dbus-daemon[1078]: [system] Activating via systemd: service name='com.intel.tss2.Tabrmd' unit='tpm2-abrmd.service' requested by ':1.558' (uid=0 pid=8550 comm="/usr/bin/tpm2_pcrlist " label="system_u:system_r:fwupd_t:s0")
Mar 07 09:18:35 river systemd[1]: Starting TPM2 Access Broker and Resource Management Daemon...
Mar 07 09:18:35 river audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=tpm2-abrmd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Mar 07 09:18:35 river dbus-daemon[1078]: [system] Successfully activated service 'com.intel.tss2.Tabrmd'
Mar 07 09:18:35 river systemd[1]: Started TPM2 Access Broker and Resource Management Daemon.
Mar 07 09:18:35 river audit[1078]: USER_AVC pid=1078 uid=81 auid=4294967295 ses=4294967295 subj=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 msg='avc:  denied  { send_msg } for msgtype=method_return dest=:1.558 spid=8554 tpid=8550 scontext=system_u:system_r:tabrmd_t:s0 tcontext=system_u:system_r:fwupd_t:s0 tclass=dbus permissive=0 exe="/usr/bin/dbus-daemon" sauid=81 hostname=? addr=? terminal=?'
Mar 07 09:18:35 river gnome-shell[7886]: GNOME Shell started at Thu Mar 07 2019 09:18:32 GMT+0000 (GMT)

followed 25s later by

Mar 07 09:19:00 river dbus-daemon[1078]: [system] Failed to activate service 'org.freedesktop.fwupd': timed out (service_start_timeout=25000ms)
Mar 07 09:19:00 river gnome-software[8219]: not GsPlugin error g-dbus-error-quark:20: Error calling StartServiceByName for org.freedesktop.fwupd: GDBus.Error:org.freedesktop.DBus.Error.TimedOut: Failed to activate service 'org.freedesktop.fwupd': timed out (service_start_timeout=25000ms)
Mar 07 09:19:00 river gnome-software[8219]: not GsPlugin error g-dbus-error-quark:20: Error calling StartServiceByName for org.freedesktop.fwupd: GDBus.Error:org.freedesktop.DBus.Error.TimedOut: Failed to activate service 'org.freedesktop.fwupd': timed out (service_start_timeout=25000ms)
Mar 07 09:19:00 river gnome-software[8219]: can't reliably fixup error from domain g-dbus-error-quark
Mar 07 09:19:00 river gnome-software[8219]: not handling error failed for action get-updates-historical: Error calling StartServiceByName for org.freedesktop.fwupd: GDBus.Error:org.freedesktop.DBus.Error.TimedOut: Failed to activate service 'org.freedesktop.fwupd': timed out (service_start_timeout=25000ms)
Mar 07 09:19:00 river gnome-software[8219]: not GsPlugin error g-dbus-error-quark:20: Error calling StartServiceByName for org.freedesktop.fwupd: GDBus.Error:org.freedesktop.DBus.Error.TimedOut: Failed to activate service 'org.freedesktop.fwupd': timed out (service_start_timeout=25000ms)
Mar 07 09:19:00 river gnome-software[8219]: not handling error failed for action refresh: Error calling StartServiceByName for org.freedesktop.fwupd: GDBus.Error:org.freedesktop.DBus.Error.TimedOut: Failed to activate service 'org.freedesktop.fwupd': timed out (service_start_timeout=25000ms)


That seems to be the same cause for the offline update to fail as well. Looking in the journal for the actual failure during an offline update I see this, 24s before the error I posted in the original description:

Mar 05 09:53:34 river audit[1025]: USER_AVC pid=1025 uid=81 auid=4294967295 ses=4294967295 subj=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 msg='avc:  denied  { send_msg } for msgtype=method_return dest=:1.12 spid=1104 tpid=1101 scontext=system_u:system_r:tabrmd_t:s0 tcontext=system_u:system_r:fwupd_t:s0 tclass=dbus permissive=0 exe="/usr/bin/dbus-daemon" sauid=81 hostname=? addr=? terminal=?'

Comment 6 Zbigniew Jędrzejewski-Szmek 2019-03-08 11:34:28 UTC
krinkodot22@hotmail.com: please attach the full log, i.e. including the earlier part from the boot start.

Hmm, why is system_u:system_r:fwupd_t:s0 communicating with system_u:system_r:tabrmd_t:s0 at all? Should it be doing that, or is it some dbus context mixup?

Comment 7 Richard Hughes 2019-03-08 11:51:40 UTC
> why is system_u:system_r:fwupd_t:s0 communicating with system_u:system_r:tabrmd_t:s0 at all

fwupd reads the TPM measurements at startup.

Comment 8 Ondrej Holy 2019-03-12 10:05:55 UTC
*** Bug 1685815 has been marked as a duplicate of this bug. ***

Comment 9 Zbigniew Jędrzejewski-Szmek 2019-03-25 14:42:28 UTC
*** Bug 1692066 has been marked as a duplicate of this bug. ***

Comment 10 krinkodot22 2019-03-26 02:41:37 UTC
Sorry for the delay. Attaching the untrimmed version of my previous log now.

Also, I tried running an offline update earlier today, and to my surprise, it worked. I'll attach the log from that boot as well.

Comment 11 krinkodot22 2019-03-26 02:42:53 UTC
Created attachment 1547877 [details]
Untrimmed boot log of a failed offline update.

Comment 12 krinkodot22 2019-03-26 02:56:57 UTC
Created attachment 1547878 [details]
Untrimmed boot log of a successful offline update.

Comment 13 Fedora Update System 2019-03-26 11:41:31 UTC
fwupd-1.2.6-1.fc29 has been submitted as an update to Fedora 29. https://bodhi.fedoraproject.org/updates/FEDORA-2019-5bd45146e1

Comment 14 Fedora Update System 2019-03-27 04:34:38 UTC
fwupd-1.2.6-1.fc29 has been pushed to the Fedora 29 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2019-5bd45146e1

Comment 15 mattias.eriksson 2019-03-28 08:31:28 UTC
I just had the same experience, but on a f30 system with  fwupd-1.2.6-1.fc30.x86_64. 
systemctl status fwupd says:
fwupd[17549]: Failed to load engine: Failed to create table: table approved_firmware already exists

Comment 16 mattias.eriksson 2019-03-28 09:04:45 UTC
Additional info about the table_approved. This seemed to be fixed for me by just removing the pending.db and start up fwupd. However, the more serious issue here was that due to this failed upgrade my new kernel packages was not propperly installed, so when I did a reboot I got an error prompt throwing me in to maintnence mode. Now, I run a alpha version so I'm prepared for things to go wrong a little now and then, so I was able to fix this by booting an older kernel and reinstall the latest kernel packages. But having fwupd just being able to bork my kernel upgrade feels shaky at the core. fwupd failing should affect firmware upgrades, not the rest of the system... or is there any interaction in between the fwupd and the rest of the system that is so crucial that it is worth this risk?
If this would have happend to my father in law, on his stable system, it would have meant that he would have to travel back and forth to me which is a total of two days just traveling... so basically, this must not happen on a stable system.

Comment 17 Richard Hughes 2019-03-28 10:30:28 UTC
> having fwupd just being able to bork my kernel upgrade feels shaky at the core

I don't think that happened.

Comment 18 mattias.eriksson 2019-03-28 10:35:13 UTC
Ok, it might me drawing the wrong conclusions. But I did and offline update, got an error about it failing due to fwupd. Fixed fwupd and rebooted, started on the new kernel and it failed. I then reinstalled the kernel and everything works again. But hopefully you are right and it is just coincidental.

Comment 19 krinkodot22 2019-03-30 17:52:38 UTC
I tried running offline updates with and without the fwupd testing update applied (with a different update each time), and it succeeded both times.

I confirmed that the version of fwupd I used without the testing update applied is the same version that I had installed during the bad boot that I posted the log of earlier.

Either the fwupd problem is intermittent, or there is/was something else causing the offline update failures.

Comment 20 Fedora Update System 2019-03-31 03:00:41 UTC
fwupd-1.2.6-1.fc29 has been pushed to the Fedora 29 stable repository. If problems still persist, please make note of it in this bug report.

Comment 21 Peter Hostačný 2019-05-09 22:39:09 UTC
I am still having this issue on fwupd-1.2.6-1.fc29

$ fwupdmgr get-updates
Failed to connect to daemon: Error calling StartServiceByName for org.freedesktop.fwupd: GDBus.Error:org.freedesktop.DBus.Error.TimedOut: Failed to activate service 'org.freedesktop.fwupd': timed out (service_start_timeout=25000ms)

$ sudo dnf install fwupd
Last metadata expiration check: 0:03:43 ago on Fri 10 May 2019 00:33:29 CEST.
Package fwupd-1.2.6-1.fc29.x86_64 is already installed.


$ systemctl status fwupd
● fwupd.service - Firmware update daemon
   Loaded: loaded (/usr/lib/systemd/system/fwupd.service; static; vendor preset: disabled)
   Active: failed (Result: exit-code) since Fri 2019-05-10 00:29:52 CEST; 53s ago
     Docs: https://fwupd.org/
  Process: 3625 ExecStart=/usr/libexec/fwupd/fwupd (code=exited, status=1/FAILURE)
 Main PID: 3625 (code=exited, status=1/FAILURE)

May 10 00:29:52 xxxx systemd[1]: Starting Firmware update daemon...
May 10 00:29:52 xxxx fwupd[3625]: Failed to load engine: Failed to create table: table approved_firmware already exists
May 10 00:29:52 xxxx systemd[1]: fwupd.service: Main process exited, code=exited, status=1/FAILURE
May 10 00:29:52 xxxx systemd[1]: fwupd.service: Failed with result 'exit-code'.
May 10 00:29:52 xxxx systemd[1]: Failed to start Firmware update daemon.

Comment 22 Richard Hughes 2019-05-10 08:47:26 UTC
Peter, that's a different bug.

Comment 23 Peter Hostačný 2019-05-10 09:00:55 UTC
Oh, sorry, you are right. I overlooked that google just matched one of the comments -_- I will create another bug report.


Note You need to log in before you can comment on or make changes to this bug.