Bug 1185362

Summary: fwupd fails to start due to missing dependencies causing a timeout
Product: [openSUSE] openSUSE Tumbleweed Reporter: Jon Brightwell <jon>
Component: OtherAssignee: Matthias Gerstner <matthias.gerstner>
Status: RESOLVED FIXED QA Contact: E-mail List <qa-bugs>
Severity: Normal    
Priority: P5 - None CC: dimstar, fkrueger
Version: CurrentFlags: matthias.gerstner: needinfo? (dimstar)
Target Milestone: ---   
Hardware: Other   
OS: Other   
Whiteboard:
Found By: --- Services Priority:
Business Priority: Blocker: ---
Marketing QA Status: --- IT Deployment: ---

Description Jon Brightwell 2021-04-27 15:58:19 UTC
First hand error is:

>fwupdmgr --verbose
(fwupdmgr:8079): GLib-DEBUG: 16:29:05.448: setenv()/putenv() are not thread-safe and should not be used after threads are created
Failed to connect to daemon: Error calling StartServiceByName for org.freedesktop.fwupd: Failed to activate service 'org.freedesktop.fwupd': timed out (service_start_timeout=25000ms)



After some investigation it does actually run but takes a long time to start.

>/usr/libexec/fwupd/fwupd --verbose
<snip>
ERROR:esys:src/tss2-esys/esys_context.c:69:Esys_Initialize() Initialize default tcti. ErrorCode (0x000a000a) 
<snip>


Library is installed

> zypper info libtss2-esys0
Information for package libtss2-esys0:
--------------------------------------
Repository     : Main Repository (OSS)
Name           : libtss2-esys0
Version        : 3.0.3-1.4
Arch           : x86_64
Vendor         : openSUSE
Installed Size : 562.6 KiB
Installed      : Yes (automatically)
Status         : up-to-date
Source package : tpm2-0-tss-3.0.3-1.4.src
Summary        : TPM2 Enhanced System API (ESAPI)


installing additional components get's us a step further.

>zypper in tpm2-0-tss tpm2.0-abrmd

>journalctl -u tpm2-abrmd.service 
-- Logs begin at Wed 2020-01-08 09:10:54 GMT, end at Tue 2021-04-27 16:51:12 BST. --
Apr 27 16:49:30 mudkip.farm systemd[1]: /usr/lib/systemd/system/tpm2-abrmd.service:12: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting al>
Apr 27 16:49:30 mudkip.farm systemd[1]: Condition check resulted in TPM2 Access Broker and Resource Management Daemon being skipped.

>fwupd

15:51:12:0366 FIXME                failed to allocate dbus proxy object: Error calling StartServiceByName for com.intel.tss2.Tabrmd: Failed to activate service 'com.intel.tss2.Tabrmd': timed out (service_start_timeout=25000ms)


Looks like there's 2 issues here? Those missing dependencies and then those dependencies need fixing?
In both cases, /usr/libexec/fwupd/fwupd does actually end up running ok (missing features) but running it via systemd causes it to timeout.
Comment 1 Frank Krüger 2021-04-27 19:09:17 UTC
(In reply to Jon Brightwell from comment #0)
> First hand error is:
> 
> >fwupdmgr --verbose
> (fwupdmgr:8079): GLib-DEBUG: 16:29:05.448: setenv()/putenv() are not
> thread-safe and should not be used after threads are created
> Failed to connect to daemon: Error calling StartServiceByName for
> org.freedesktop.fwupd: Failed to activate service 'org.freedesktop.fwupd':
> timed out (service_start_timeout=25000ms)
> 
> 
> 
> After some investigation it does actually run but takes a long time to start.
> 
> >/usr/libexec/fwupd/fwupd --verbose
> <snip>
> ERROR:esys:src/tss2-esys/esys_context.c:69:Esys_Initialize() Initialize
> default tcti. ErrorCode (0x000a000a) 
> <snip>
I can confirm your observation that there seems to be a missing dependency. In fact, after instaling tpm2.0-abrmd-2.3.3-1.5.x86_64, which pulls in other packages, the aforementioned error message was gone (which is harmless I guess). Nevertheless, fwupd has always been working properly.

Have you tried 'sudo systemctl start/stop or restart fwupd.service' after installing tpm2-0-tss and tpm2.0-abrmd? Does 'sudo zypper dup --recommends' pulls in additional packages that solve your problem?
Comment 2 Jon Brightwell 2021-04-27 21:32:34 UTC
Yep.

I can't make it passed 

15:51:12:0366 FIXME                failed to allocate dbus proxy object: Error calling StartServiceByName for com.intel.tss2.Tabrmd: Failed to activate service 'com.intel.tss2.Tabrmd': timed out (service_start_timeout=25000ms)




```
mudkip:/home/moozaad # systemctl status fwupd.service 
● fwupd.service - Firmware update daemon
     Loaded: loaded (/usr/lib/systemd/system/fwupd.service; static)
     Active: failed (Result: timeout) since Tue 2021-04-27 22:29:55 BST; 15s ago
       Docs: https://fwupd.org/
    Process: 8861 ExecStart=/usr/libexec/fwupd/fwupd (code=killed, signal=TERM)
   Main PID: 8861 (code=killed, signal=TERM)
        CPU: 107ms

Apr 27 22:28:25 mudkip.farm systemd[1]: Starting Firmware update daemon...
Apr 27 22:28:50 mudkip.farm fwupd[8861]: 21:28:50:0917 FIXME                failed to allocate dbus proxy object: Error calling StartServiceByName for com.intel.tss2.Tabrmd: Failed to activate service 'com.intel.tss2.Tabrmd': tim>
Apr 27 22:29:55 mudkip.farm systemd[1]: fwupd.service: start operation timed out. Terminating.
Apr 27 22:29:55 mudkip.farm systemd[1]: fwupd.service: Failed with result 'timeout'.
Apr 27 22:29:55 mudkip.farm systemd[1]: Failed to start Firmware update daemon.
      
mudkip:/home/moozaad # systemctl status tpm2-abrmd.service 
● tpm2-abrmd.service - TPM2 Access Broker and Resource Management Daemon
     Loaded: loaded (/usr/lib/systemd/system/tpm2-abrmd.service; disabled; vendor preset: disabled)
     Active: inactive (dead)

Apr 27 22:28:25 mudkip.farm systemd[1]: /usr/lib/systemd/system/tpm2-abrmd.service:12: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting al>
Apr 27 22:28:25 mudkip.farm systemd[1]: Condition check resulted in TPM2 Access Broker and Resource Management Daemon being skipped.
Apr 27 22:30:48 mudkip.farm systemd[1]: /usr/lib/systemd/system/tpm2-abrmd.service:12: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting al>
```

As I said it's really 2 issues. Probably needs another ticket.
Comment 3 Frank Krüger 2021-04-27 21:41:38 UTC
Sorry, but just to be sure, is TPM 2.0 enabled in your BIOS?
Comment 4 Jon Brightwell 2021-04-28 11:53:01 UTC
I thought it was but no kernel module is loading (lsmod | grep tpm). I can't actually see my BIOS due to a bug with my monitor firmware.

However, all of the above should detect that and fail elegantly.
Comment 5 Frank Krüger 2021-04-28 18:05:13 UTC
(In reply to Jon Brightwell from comment #4)
> I thought it was but no kernel module is loading (lsmod | grep tpm). 
It's build in (cf. 'modinfo tpm')
Comment 6 Jon Brightwell 2021-04-28 18:21:34 UTC
dmesg says no tpm (bypassed), so I'll go with that.
Comment 7 Dominique Leuenberger 2021-04-29 13:58:59 UTC
There are indeed probably more than one issue, but it seems to boil down to fwupd 'just' being the messenger


One of the libraries/plugins used by fwupd happens to do a possible callout to
  dbus: com.intel.tss2.Tabrmd
but said library is missing the dependency 

In fact, the library calling out to com.intel.tss.Tabrmd is: /usr/lib64/libtss2-tcti-tabrmd.so.0.0.0

This library should ensure the dbus service it wants to talk to is present
=> > osc maintainer libtss2-tcti-tabrmd0
Defined in package: security/tpm2.0-abrmd 
  bugowner of libtss2-tcti-tabrmd0 : 
   -

  maintainer of libtss2-tcti-tabrmd0 : 
==>   mgerstner


Apr 27 22:28:25 mudkip.farm systemd[1]: Condition check resulted in TPM2 Access Broker and Resource Management Daemon being skipped.

This in turn seems to be another issue why the service refuses to come up on your machine, even after having the service now present. The conditions from the service is:

# This condition is needed when using the device TCTI. If the
# TCP mssim is used then the condition should be commented out.
ConditionPathExistsGlob=/dev/tpm*
In Joe's case, /dev/tpm* likely does not exist

That comment already gives me a very bad feeling: the user is supposed to change the condition depending on what he needs!?!
Comment 8 Jon Brightwell 2021-04-29 22:25:12 UTC
(In reply to Dominique Leuenberger from comment #7)
> # This condition is needed when using the device TCTI. If the
> # TCP mssim is used then the condition should be commented out.
> ConditionPathExistsGlob=/dev/tpm*
> In Joe's case, /dev/tpm* likely does not exist


Correct
Comment 9 Matthias Gerstner 2021-04-30 06:55:00 UTC
Hi there. I wonder why fwupd involves the tpm2 stack at all? Where is this
dependency coming from?

libtss2-tcti-tabrmd is simply a backend library for the tpm2-0-tss package
that allows to talk to the abrmd, if it is running. But even if the daemon is
installed it doesn't mean that it will work, because it can only run in tpm2
hardware is present or if tpm2 emulation is setup.

I will have a look into fwupd to try to find out where this hook towards
tss2 is coming from.
Comment 10 Matthias Gerstner 2021-04-30 10:05:19 UTC
So fwupd seems to contain some plugin that supports reading firmware
information from TPM chips or something of the likes. This probably only
triggers when /dev/tpm0 is available. It looks like the plugin builds and
links against the tpm2-0-tss libraries directly. The fwupd package has a
dependency towards libtss2-esys.so.

This is just a generic library, however. It attempts to use different backens
like using the /dev/tmp0 directly (libtss2-tcti-device0), a simulator
(libtss2-tcti-mssim0, libtss2-tcti-swtpm0) or the resource manager daemon
(libtss2-tcti-tabrmd0). So the effect that installing tpm2.0-abrmd gets you a
step further is just coincidence. Installing libtss2-tcti-device0 would have
helped more probably.

I guess just assuming that the tpm2 stack is available and/or operational is
not right, just because some /dev/tpm0 device is sitting around.

I *could* add a recommends in libtss2-tcti-tabrmd0 towards tpm2.0-abrmd but I
don't think this will fix the root cause issue here.
Comment 11 Jon Brightwell 2021-05-01 14:15:52 UTC
Side note, it all works as expected once I enabled AMD's fTPM.

Same deps missing and used.

# fwupdmgr get-devices
<runs correctly>

# journalctl -u tpm2-abrmd.service 

May 01 15:11:07 mudkip.farm systemd[1]: /usr/lib/systemd/system/tpm2-abrmd.service:12: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting al>
May 01 15:11:27 mudkip.farm systemd[1]: /usr/lib/systemd/system/tpm2-abrmd.service:12: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting al>
May 01 15:11:27 mudkip.farm systemd[1]: Starting TPM2 Access Broker and Resource Management Daemon...
May 01 15:11:27 mudkip.farm tpm2-abrmd[5842]: tcti_conf before: "device:/dev/tpm0"
May 01 15:11:27 mudkip.farm tpm2-abrmd[5842]: tcti_conf after: "device:/dev/tpm0"
May 01 15:11:27 mudkip.farm systemd[1]: Started TPM2 Access Broker and Resource Management Daemon.
Comment 12 Matthias Gerstner 2021-05-10 07:41:05 UTC
@dimstar: Please see comment 10. I think the error handling in fwupd is lacking. Failure to communicate with the tpm should not be a hard error IMO. Do you want to look further into this?
Comment 13 Matthias Gerstner 2021-07-05 07:40:39 UTC
The tcti-device-tss is now Required due to bug 1187077. So the desire
expressed in this bug is now fulfilled. Although I still think fwupd is
behaving wrongly here.