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.
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.
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.
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?
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.
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=?'
krinkodot22: 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?
> 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.
*** Bug 1685815 has been marked as a duplicate of this bug. ***
*** Bug 1692066 has been marked as a duplicate of this bug. ***
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.
Created attachment 1547877 [details] Untrimmed boot log of a failed offline update.
Created attachment 1547878 [details] Untrimmed boot log of a successful offline update.
fwupd-1.2.6-1.fc29 has been submitted as an update to Fedora 29. https://bodhi.fedoraproject.org/updates/FEDORA-2019-5bd45146e1
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
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
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.
> having fwupd just being able to bork my kernel upgrade feels shaky at the core I don't think that happened.
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.
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.
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.
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.
Peter, that's a different bug.
Oh, sorry, you are right. I overlooked that google just matched one of the comments -_- I will create another bug report.