Ok, I have more info now.
1. Adding `-vv` to the Exec line in fwupd.service and posting the new
log will probably not help. The problem is that fwupd takes 20 minutes
to start.
2. There is something rotten in what fwupd is doing. During the 20
minute startup pause the syslog is replete with the DPCD accesses
failures reported from nouveau. As soon as the 20 minutes are over, so
are the DPCD accesses failures
3. Right now I am trying to run fwupd -vv from console and capture the
output to a file. This is much harder than expected. Simple shell
redirection (sudo /usr/libexec/fwupd/fwupd -vv >somelogfile.log) does
not work while it should ("sudo ls -l >otherfile.log" works). I hate it
when programs invent their own ways how to do console output and/or
logging, complicating catching bugs like this. This might be another
reason why I think adding `-vv` to the Exec line in fwupd.service would
not work. I don't trust fwupd to play nice and send this logging info to
syslog.
4. Rebooting the computer can take up to 20 minutes because the kernel waits
for the wonky and unkillable fwupd process to finish. I have no idea how a
process that takes nonzero CPU time all the time can't die.
Right now I think that while the fwupd process is doing this mystery stuff, the
kernel is even unable to finish shutting down.
--
You received this bug notification because you are a member of Kernel
Packages, which is subscribed to linux in Ubuntu.
https://bugs.launchpad.net/bugs/2098668
Title:
fwupd daemon hangs for a while during TPM access
Status in fwupd package in Ubuntu:
New
Status in linux package in Ubuntu:
New
Bug description:
I was reviewing logs while trying to find evidence of an unrelated
issue and found that fwupd.service fails to start due to a timeout.
The logs below contain only the failure, I could not find the startup:
2025-02-16T00:03:39.859015+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[1]: fwupd.service: Failed with result 'timeout'.
2025-02-16T00:03:39.859180+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[1]: Failed to start fwupd.service - Firmware update daemon.
2025-02-16T00:03:39.859258+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[1]: fwupd.service: Consumed 1min 3.456s CPU time.
Here is another, probably incomplete instance. I attached the complete
section of the log so maybe you can glean out what I missed. Here it
is:
2025-02-16T00:03:58.952797+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[1]: Starting fwupd.service - Firmware update daemon...
2025-02-16T00:06:59.072774+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[1]: fwupd.service: start operation timed out. Terminating.
2025-02-16T00:09:59.072836+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[1]: fwupd.service: State 'stop-sigterm' timed out. Killing.
2025-02-16T00:09:59.073019+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[1]: fwupd.service: Killing process 1192141 (fwupd) with signal S
2025-02-16T00:10:48.774997+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[1]: fwupd.service: Failed with result 'timeout'.
2025-02-16T00:10:48.775165+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[1]: Failed to start fwupd.service - Firmware update daemon.
2025-02-16T00:10:48.775230+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[1]: fwupd.service: Consumed 1min 3.020s CPU time.
There is another service called snap.firmware-updater.firmware-
notifier.service that fails to start and is repeatedly trying to
restart. My gut says it fails because it needs fwupd.service to be
running. Here are some of the logs:
2025-02-16T00:00:11.588457+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[2477]: Started snap.firmware-updater.firmware-notifier.service -
Service for snap application firmware-updater.firmware-notifier.
2025-02-16T00:00:11.669261+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
kernel: audit: type=1400 audit(1739660411.667:15250): apparmor="DENIED"
operation="open" class="file" profile="snap.firmware-updater.firmware-notifier"
name="/proc/sys/vm/max_map_count" pid=1191308 comm="firmware-notifi"
requested_mask="r" denied_mask="r" fsuid=1000 ouid=0
2025-02-16T00:00:11.672348+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
dbus-daemon[1184]: [system] Activating via systemd: service
name='org.freedesktop.fwupd' unit='fwupd.service' requested by ':1.19925'
(uid=1000 pid=1191308 comm="/snap/firmware-updater/167/bin/firmware-notifier"
label="snap.firmware-updater.firmware-notifier (enforce)")
2025-02-16T00:00:36.677585+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191308]: Unhandled exception:
2025-02-16T00:00:36.677686+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191308]:
org.freedesktop.DBus.Error.TimedOut: Failed to activate service
'org.freedesktop.fwupd': timed out (service_start_timeout=25000ms)
2025-02-16T00:00:36.677704+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191308]: #0 DBusClient._callMethod
(package:dbus/src/dbus_client.dart:1130)
2025-02-16T00:00:36.677717+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191308]: <asynchronous suspension>
2025-02-16T00:00:36.677730+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191308]: #1 DBusClient.callMethod
(package:dbus/src/dbus_client.dart:621)
2025-02-16T00:00:36.677743+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191308]: <asynchronous suspension>
2025-02-16T00:00:36.677754+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191308]: #2
DBusRemoteObject.getAllProperties (package:dbus/src/dbus_remote_object.dart:142)
2025-02-16T00:00:36.677774+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191308]: <asynchronous suspension>
2025-02-16T00:00:36.677786+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191308]: #3 FwupdClient.connect
(package:fwupd/src/fwupd_client.dart:133)
2025-02-16T00:00:36.677799+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191308]: <asynchronous suspension>
2025-02-16T00:00:36.677809+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191308]: #4 getUpdates
(package:firmware_notifier/firmware_notifier.dart:10)
2025-02-16T00:00:36.677826+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191308]: <asynchronous suspension>
2025-02-16T00:00:36.677836+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191308]: #5 main
(file:///build/firmware-updater/parts/firmware-notifier/build/apps/firmware_notifier/bin/firmware_notifier.dart:7)
2025-02-16T00:00:36.677848+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191308]: <asynchronous suspension>
2025-02-16T00:00:36.678149+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[2477]: snap.firmware-updater.firmware-notifier.service: Main process
exited, code=exited, status=255/EXCEPTION
2025-02-16T00:00:36.678230+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[2477]: snap.firmware-updater.firmware-notifier.service: Failed with
result 'exit-code'.
2025-02-16T00:00:36.822693+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[2477]: snap.firmware-updater.firmware-notifier.service: Scheduled
restart job, restart counter is at 14969.
2025-02-16T00:00:36.837572+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[2477]: Started snap.firmware-updater.firmware-notifier.service -
Service for snap application firmware-updater.firmware-notifier.
2025-02-16T00:00:36.918257+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
kernel: audit: type=1400 audit(1739660436.917:15251): apparmor="DENIED"
operation="open" class="file" profile="snap.firmware-updater.firmware-notifier"
name="/proc/sys/vm/max_map_count" pid=1191382 comm="firmware-notifi"
requested_mask="r" denied_mask="r" fsuid=1000 ouid=0
2025-02-16T00:00:36.921046+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
dbus-daemon[1184]: [system] Activating via systemd: service
name='org.freedesktop.fwupd' unit='fwupd.service' requested by ':1.19926'
(uid=1000 pid=1191382 comm="/snap/firmware-updater/167/bin/firmware-notifier"
label="snap.firmware-updater.firmware-notifier (enforce)")
2025-02-16T00:01:01.932464+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191382]: Unhandled exception:
2025-02-16T00:01:01.932575+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191382]:
org.freedesktop.DBus.Error.TimedOut: Failed to activate service
'org.freedesktop.fwupd': timed out (service_start_timeout=25000ms)
2025-02-16T00:01:01.932599+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191382]: #0 DBusClient._callMethod
(package:dbus/src/dbus_client.dart:1130)
2025-02-16T00:01:01.932612+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191382]: <asynchronous suspension>
2025-02-16T00:01:01.932631+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191382]: #1 DBusClient.callMethod
(package:dbus/src/dbus_client.dart:621)
2025-02-16T00:01:01.932644+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191382]: <asynchronous suspension>
2025-02-16T00:01:01.932655+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191382]: #2
DBusRemoteObject.getAllProperties (package:dbus/src/dbus_remote_object.dart:142)
2025-02-16T00:01:01.932668+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191382]: <asynchronous suspension>
2025-02-16T00:01:01.932679+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191382]: #3 FwupdClient.connect
(package:fwupd/src/fwupd_client.dart:133)
2025-02-16T00:01:01.932692+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191382]: <asynchronous suspension>
2025-02-16T00:01:01.932703+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191382]: #4 getUpdates
(package:firmware_notifier/firmware_notifier.dart:10)
2025-02-16T00:01:01.932718+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191382]: <asynchronous suspension>
2025-02-16T00:01:01.932729+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191382]: #5 main
(file:///build/firmware-updater/parts/firmware-notifier/build/apps/firmware_notifier/bin/firmware_notifier.dart:7)
2025-02-16T00:01:01.932741+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191382]: <asynchronous suspension>
2025-02-16T00:01:01.933936+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[2477]: snap.firmware-updater.firmware-notifier.service: Main process
exited, code=exited, status=255/EXCEPTION
2025-02-16T00:01:01.934014+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[2477]: snap.firmware-updater.firmware-notifier.service: Failed with
result 'exit-code'.
2025-02-16T00:01:02.072709+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[2477]: snap.firmware-updater.firmware-notifier.service: Scheduled
restart job, restart counter is at 14970.
2025-02-16T00:01:02.083553+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[2477]: Started snap.firmware-updater.firmware-notifier.service -
Service for snap application firmware-updater.firmware-notifier.
2025-02-16T00:01:02.167251+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
kernel: audit: type=1400 audit(1739660462.166:15252): apparmor="DENIED"
operation="open" class="file" profile="snap.firmware-updater.firmware-notifier"
name="/proc/sys/vm/max_map_count" pid=1191451 comm="firmware-notifi"
requested_mask="r" denied_mask="r" fsuid=1000 ouid=0
2025-02-16T00:01:02.169670+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
dbus-daemon[1184]: [system] Activating via systemd: service
name='org.freedesktop.fwupd' unit='fwupd.service' requested by ':1.19927'
(uid=1000 pid=1191451 comm="/snap/firmware-updater/167/bin/firmware-notifier"
label="snap.firmware-updater.firmware-notifier (enforce)")
2025-02-16T00:01:17.342552+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
NetworkManager[1299]: <info> [1739660477.3421] dhcp6 (eno1): state changed new
lease, address=2a02:ab04:23b:7d00::f1
2025-02-16T00:01:17.343437+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
dbus-daemon[1184]: [system] Activating via systemd: service
name='org.freedesktop.nm_dispatcher'
unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.14' (uid=0
pid=1299 comm="/usr/sbin/NetworkManager --no-daemon" label="unconfined")
2025-02-16T00:01:17.365889+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[1]: Starting NetworkManager-dispatcher.service - Network Manager Script
Dispatcher Service...
2025-02-16T00:01:17.371061+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
dbus-daemon[1184]: [system] Successfully activated service
'org.freedesktop.nm_dispatcher'
2025-02-16T00:01:17.371210+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[1]: Started NetworkManager-dispatcher.service - Network Manager Script
Dispatcher Service.
2025-02-16T00:01:27.179156+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191451]: Unhandled exception:
2025-02-16T00:01:27.179283+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191451]:
org.freedesktop.DBus.Error.TimedOut: Failed to activate service
'org.freedesktop.fwupd': timed out (service_start_timeout=25000ms)
2025-02-16T00:01:27.179300+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191451]: #0 DBusClient._callMethod
(package:dbus/src/dbus_client.dart:1130)
2025-02-16T00:01:27.179315+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191451]: <asynchronous suspension>
2025-02-16T00:01:27.179330+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191451]: #1 DBusClient.callMethod
(package:dbus/src/dbus_client.dart:621)
2025-02-16T00:01:27.179344+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191451]: <asynchronous suspension>
2025-02-16T00:01:27.179355+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191451]: #2
DBusRemoteObject.getAllProperties (package:dbus/src/dbus_remote_object.dart:142)
2025-02-16T00:01:27.179368+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191451]: <asynchronous suspension>
2025-02-16T00:01:27.179379+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191451]: #3 FwupdClient.connect
(package:fwupd/src/fwupd_client.dart:133)
2025-02-16T00:01:27.179392+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191451]: <asynchronous suspension>
2025-02-16T00:01:27.179403+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191451]: #4 getUpdates
(package:firmware_notifier/firmware_notifier.dart:10)
2025-02-16T00:01:27.179418+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191451]: <asynchronous suspension>
2025-02-16T00:01:27.179430+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191451]: #5 main
(file:///build/firmware-updater/parts/firmware-notifier/build/apps/firmware_notifier/bin/firmware_notifier.dart:7)
2025-02-16T00:01:27.179442+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
firmware-updater.firmware-notifier[1191451]: <asynchronous suspension>
2025-02-16T00:01:27.180555+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[2477]: snap.firmware-updater.firmware-notifier.service: Main process
exited, code=exited, status=255/EXCEPTION
2025-02-16T00:01:27.180667+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[2477]: snap.firmware-updater.firmware-notifier.service: Failed with
result 'exit-code'.
2025-02-16T00:01:27.322698+01:00 user-ASUS-TUF-Gaming-A15-FA507NU-FA507NU
systemd[2477]: snap.firmware-updater.firmware-notifier.service: Scheduled
restart job, restart counter is at 14971.
ProblemType: Bug
DistroRelease: Ubuntu 24.04
Package: fwupd 1.9.27-0ubuntu1~24.04.1
ProcVersionSignature: Ubuntu 6.8.0-53.55-generic 6.8.12
Uname: Linux 6.8.0-53-generic x86_64
ApportVersion: 2.28.1-0ubuntu3.3
Architecture: amd64
CasperMD5CheckResult: pass
CurrentDesktop: ubuntu:GNOME
Date: Mon Feb 17 13:32:34 2025
InstallationDate: Installed on 2024-02-14 (369 days ago)
InstallationMedia: Ubuntu 22.04.3 LTS "Jammy Jellyfish" - Release amd64
(20230807.2)
ProcEnviron:
PATH=(custom, no user)
SHELL=/bin/bash
TERM=xterm-256color
XDG_RUNTIME_DIR=<set>
SourcePackage: fwupd
UpgradeStatus: Upgraded to noble on 2025-01-30 (18 days ago)
modified.conffile..etc.fwupd.daemon.conf: [deleted]
modified.conffile..etc.fwupd.fwupd.conf: [inaccessible: [Errno 13] Permission
denied: '/etc/fwupd/fwupd.conf']
modified.conffile..etc.fwupd.msr.conf: [deleted]
modified.conffile..etc.fwupd.redfish.conf: [deleted]
modified.conffile..etc.fwupd.thunderbolt.conf: [deleted]
modified.conffile..etc.fwupd.uefi_capsule.conf: [deleted]
To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/fwupd/+bug/2098668/+subscriptions
--
Mailing list: https://launchpad.net/~kernel-packages
Post to : kernel-packages@lists.launchpad.net
Unsubscribe : https://launchpad.net/~kernel-packages
More help : https://help.launchpad.net/ListHelp
