Open Bug 1794006 Opened 3 years ago Updated 3 years ago

Firefox Linux startup is slow due to being blocked for 30s or more waiting for /dev/tpmrm0

Categories

(Core :: Widget: Gtk, defect)

Product:
Core
Component:
Widget: Gtk
Version:
Firefox 105
Type:
defect

Tracking

()

Status:
UNCONFIRMED

People

(Reporter: jamie.pate, Unassigned)

Details

Attachments

(2 files)

firefox-tpm2-load.log.gz
244.28 KB, application/gzip
Details
Results from https://github.com/crocs-muni/tpm2-algtest (see also https://github.com/crocs-muni/tpm2-algtest/pull/22 )
193.65 KB, application/zip
Details

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:105.0) Gecko/20100101 Firefox/105.0

Steps to reproduce:

After enabling TPM2 on my laptop the startup time for firefox skyrocketed (30s)

Actual results:

openat(AT_FDCWD, "/dev/tpmrm0", O_RDWR|O_NONBLOCK) = 82
write(82, "\200\1\0\0\0\f\0\0\1{\0\10", 12) = 12
poll([{fd=82, events=POLLIN}], 1, 1000) = 1 ([{fd=82, revents=POLLIN}])
read(82, "\200\1\0\0\0\24\0\0\0\0", 10) = 10
poll([{fd=82, events=POLLIN}], 1, 1000) = 1 ([{fd=82, revents=POLLIN}])
read(82, "\0\10\361\v\323\315q\321\322d", 10) = 10
futex(0x7f1629c208e8, FUTEX_WAKE_PRIVATE, 2147483647) = 0
futex(0x7f1629c208dc, FUTEX_WAKE_PRIVATE, 2147483647) = 0
futex(0x7f1629c208d4, FUTEX_WAKE_PRIVATE, 2147483647) = 0
futex(0x7f1629c1ddbc, FUTEX_WAKE_PRIVATE, 2147483647) = 0
futex(0x7f1629c20784, FUTEX_WAKE_PRIVATE, 2147483647) = 0
futex(0x7f1629c2075c, FUTEX_WAKE_PRIVATE, 2147483647) = 0
futex(0x7f1629c20750, FUTEX_WAKE_PRIVATE, 2147483647) = 0
futex(0x7f1629c208cc, FUTEX_WAKE_PRIVATE, 2147483647) = 0
futex(0x7f1629c20888, FUTEX_WAKE_PRIVATE, 2147483647) = 0
futex(0x7f1629c20880, FUTEX_WAKE_PRIVATE, 2147483647) = 0
futex(0x7f1629c20878, FUTEX_WAKE_PRIVATE, 2147483647) = 0
futex(0x7f1629c20998, FUTEX_WAKE_PRIVATE, 2147483647) = 0
futex(0x7f1629c208c0, FUTEX_WAKE_PRIVATE, 2147483647) = 0
futex(0x7f1629c208b8, FUTEX_WAKE_PRIVATE, 2147483647) = 0
write(82, "\200\1\0\0\0\26\0\0\1z\0\0\0\0\0\0\0\1\0\0\0\177", 22) = 22
poll([{fd=82, events=POLLIN}], 1, -1) = 1 ([{fd=82, revents=POLLIN}])
read(82, "\200\1\0\0\0\205\0\0\0\0", 10) = 10
poll([{fd=82, events=POLLIN}], 1, -1) = 1 ([{fd=82, revents=POLLIN}])
read(82, "\0\0\0\0\0\0\0\0\23\0\1\0\0\0\t\0\4\0\0\0\4\0\5\0\0\1\4\0\6\0\0\0"..., 123) = 123
write(82, "\200\1\0\0\0\26\0\0\1z\0\0\0\6\0\0\1\0\0\0\0\177", 22) = 22
poll([{fd=82, events=POLLIN}], 1, -1) = 1 ([{fd=82, revents=POLLIN}])
read(82, "\200\1\0\0\2\v\0\0\0\0", 10) = 10
poll([{fd=82, events=POLLIN}], 1, -1) = 1 ([{fd=82, revents=POLLIN}])
read(82, "\1\0\0\0\6\0\0\0?\0\0\1\0002.0\0\0\0\1\1\0\0\0\0\0\0\1\2\0\0\0"..., 513) = 513
write(82, "\200\1\0\0\0\26\0\0\1\212\0\1\0\20\0\20\4\0\0\0\0\0", 22) = 22
poll([{fd=82, events=POLLIN}], 1, -1) = 1 ([{fd=82, revents=POLLIN}])
read(82, "\200\1\0\0\0\n\0\0\0\0", 10) = 10
write(82, "\200\1\0\0\0\26\0\0\1\212\0\1\0\20\0\20\10\0\0\0\0\0", 22) = 22
poll([{fd=82, events=POLLIN}], 1, -1) = 1 ([{fd=82, revents=POLLIN}])
read(82, "\200\1\0\0\0\n\0\0\0\0", 10) = 10
write(82, "\200\1\0\0\0\26\0\0\1\212\0\1\0\20\0\20\f\0\0\0\0\0", 22) = 22
poll([{fd=82, events=POLLIN}], 1, -1) = 1 ([{fd=82, revents=POLLIN}])
read(82, "\200\1\0\0\0\n\0\0\1\304", 10) = 10
write(82, "\200\1\0\0\0\26\0\0\1\212\0\1\0\20\0\20\20\0\0\0\0\0", 22) = 22
poll([{fd=82, events=POLLIN}], 1, -1) = 1 ([{fd=82, revents=POLLIN}])
read(82, "\200\1\0\0\0\n\0\0\1\304", 10) = 10
write(82, "\200\1\0\0\0\24\0\0\1\212\0#\0\20\0\20\0\1\0\20", 20) = 20
poll([{fd=82, events=POLLIN}], 1, -1) = 1 ([{fd=82, revents=POLLIN}])
read(82, "\200\1\0\0\0\n\0\0\1\346", 10) = 10
write(82, "\200\1\0\0\0\24\0\0\1\212\0#\0\20\0\20\0\2\0\20", 20) = 20
poll([{fd=82, events=POLLIN}], 1, -1) = 1 ([{fd=82, revents=POLLIN}])
read(82, "\200\1\0\0\0\n\0\0\1\346", 10) = 10
write(82, "\200\1\0\0\0\24\0\0\1\212\0#\0\20\0\20\0\3\0\20", 20) = 20
poll([{fd=82, events=POLLIN}], 1, -1) = 1 ([{fd=82, revents=POLLIN}])
read(82, "\200\1\0\0\0\n\0\0\0\0", 10) = 10
write(82, "\200\1\0\0\0\24\0\0\1\212\0#\0\20\0\20\0\4\0\20", 20) = 20
poll([{fd=82, events=POLLIN}], 1, -1) = 1 ([{fd=82, revents=POLLIN}])
read(82, "\200\1\0\0\0\n\0\0\1\346", 10) = 10
write(82, "\200\1\0\0\0\24\0\0\1\212\0#\0\20\0\20\0\5\0\20", 20) = 20
poll([{fd=82, events=POLLIN}], 1, -1) = 1 ([{fd=82, revents=POLLIN}])
read(82, "\200\1\0\0\0\n\0\0\1\346", 10) = 10
lseek(79, 16384, SEEK_SET) = 16384
read(79, "\r\0\0\0\1\17\206\0\17\206\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 4096
write(82, "\200\2\0\0\0C\0\0\0011@\0\0\1\0\0\0\t@\0\0\t\0\0\0\0\0\0\4\0\0\0"..., 67) = 67
poll([{fd=82, events=POLLIN}], 1,

Expected results:

Firefox startup should not be blocked by tpm resource manager

System is oryp4 (system76 oryx pro 4)
Linux 5.19.0-76051900-generic
Distributor ID: Pop
Description: Pop!_OS 22.04 LTS
Release: 22.04
Codename: jammy

I checked lsof for /dev/tpmrm0 and shut down all other processes that were using it (teams and chrome) and still have the startup issue.

Full log with timestamps from strace firefox until the interactive window appears.

More system info:
CPU: Intel i7-8750H (12) @ 4.100GHz
Host bridge: Intel Corporation 8th Gen Core Processor Host Bridge/DRAM Registers (rev 07)

tpm2_getcap properties-fixed

TPM2_PT_FAMILY_INDICATOR:
raw: 0x322E3000
value: "2.0"
TPM2_PT_LEVEL:
raw: 0
TPM2_PT_REVISION:
raw: 0x74
value: 1.16
TPM2_PT_DAY_OF_YEAR:
raw: 0x109
TPM2_PT_YEAR:
raw: 0x7E0
TPM2_PT_MANUFACTURER:
raw: 0x49465800
value: "IFX"
TPM2_PT_VENDOR_STRING_1:
raw: 0x534C4239
value: "SLB9"
TPM2_PT_VENDOR_STRING_2:
raw: 0x36363500
value: "665"
TPM2_PT_VENDOR_STRING_3:
raw: 0x0
value: ""
TPM2_PT_VENDOR_STRING_4:
raw: 0x0
value: ""
TPM2_PT_VENDOR_TPM_TYPE:
raw: 0x0
TPM2_PT_FIRMWARE_VERSION_1:
raw: 0x5003F
TPM2_PT_FIRMWARE_VERSION_2:
raw: 0xC4800

tpm2_getcap properties-variable
TPM2_PT_PERMANENT:
ownerAuthSet: 0
endorsementAuthSet: 0
lockoutAuthSet: 1
reserved1: 0
disableClear: 0
inLockout: 0
tpmGeneratedEPS: 0
reserved2: 0
TPM2_PT_STARTUP_CLEAR:
phEnable: 1
shEnable: 1
ehEnable: 1
phEnableNV: 1
reserved1: 0
orderly: 0
TPM2_PT_HR_NV_INDEX: 0x6
TPM2_PT_HR_LOADED: 0x0
TPM2_PT_HR_LOADED_AVAIL: 0x3
TPM2_PT_HR_ACTIVE: 0x0
TPM2_PT_HR_ACTIVE_AVAIL: 0x40
TPM2_PT_HR_TRANSIENT_AVAIL: 0x3
TPM2_PT_HR_PERSISTENT: 0x3
TPM2_PT_HR_PERSISTENT_AVAIL: 0xE
TPM2_PT_NV_COUNTERS: 0x2
TPM2_PT_NV_COUNTERS_AVAIL: 0xC
TPM2_PT_ALGORITHM_SET: 0x0
TPM2_PT_LOADED_CURVES: 0x2
TPM2_PT_LOCKOUT_COUNTER: 0x0
TPM2_PT_MAX_AUTH_FAIL: 0x1F
TPM2_PT_LOCKOUT_INTERVAL: 0x258
TPM2_PT_LOCKOUT_RECOVERY: 0x15180
TPM2_PT_AUDIT_COUNTER_0: 0x0
TPM2_PT_AUDIT_COUNTER_1: 0x0

Summary: Firefox startup is blocked waiting for /dev/tpmrm0 → Firefox Linux startup is slow due to being blocked for 30s or more waiting for /dev/tpmrm0

Hi, We tried to reproduce this issue on our end using Ubuntu 20.04 and we cant seem to reproduce it, Unfortunately we do not have the POP os environment but I will set the component for it and maybe one of our developers can take a look and might be able to reproduce this issue on their end.

Component: Untriaged → Widget: Gtk
Product: Firefox → Core

To me it smells like my tpm is bad, so likely this is incredibly hard to reproduce :(

Upon further inspection I noticed this file opened directly before:
Oct 06 10:49:02 openat(AT_FDCWD, "/opt/forticlient/tpm2_pkcs11.sqlite3", O_RDONLY|O_NOFOLLOW|O_CLOEXEC) = 92
/opt/forticlient/tpm2_pkcs11.sqlite3 looks like there is an addon from forticlient being injected..

Oct 06 10:49:02 openat(AT_FDCWD, "/opt/forticlient/tpm2/lib/libtpm2_pkcs11.so", O_RDONLY|O_CLOEXEC) = 92

I will open an issue with forticlient since it seems like their code is causing this.

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

Attachment

General

Creator:
Created:
Updated:
Size: