`systemd-creds encrypt --with-key=tpm2` takes over two hours

[sudoforge]

systemd version the issue has been seen with

253

Used distribution

Arch Linux

Linux kernel version used

6.4.2-arch1-1

CPU architectures issue was seen on

x86_64

Component

systemd

Expected behaviour you didn't see

I excepted systemd-creds to encrypt the provided plaintext secret, and output the encrypted string.

Unexpected behaviour you saw

systemd-creds hangs indefinitely if a file is provided on the command line, or after input is terminated with C-d if input is provided via the standard input.

Steps to reproduce the problem

To simplify reproduction, we'll create a file that contains content we want to encrypt.

$ TMPFILE=$(mktemp) && echo "foobar" > "$TMPFILE"
$ systemd-creds encrypt --with-key=tpm2 "$TMPFILE" -
<no output, command hangs>

Additional program output to the terminal or log subsystem illustrating the issue

➜ sudo SYSTEMD_LOG_LEVEL=debug systemd-creds encrypt --with-key=tpm2 /tmp/tmp.JIC2YaG7kI -
Place your right index finger on the fingerprint reader
varlink: Setting state idle-client
/run/systemd/userdb/io.systemd.DynamicUser: Sending message: {"method":"io.systemd.UserDatabase.GetGroupRecord","parameters":{"gid":1000,"service":"io.systemd.DynamicUser"}}
/run/systemd/userdb/io.systemd.DynamicUser: Changing state idle-client → awaiting-reply
/run/systemd/userdb/io.systemd.DynamicUser: New incoming message: {"error":"io.systemd.UserDatabase.NoRecordFound","parameters":{}}
/run/systemd/userdb/io.systemd.DynamicUser: Changing state awaiting-reply → processing-reply
Got lookup error: io.systemd.UserDatabase.NoRecordFound
/run/systemd/userdb/io.systemd.DynamicUser: Changing state processing-reply → idle-client
varlink: Setting state idle-client
/run/systemd/userdb/io.systemd.DynamicUser: Sending message: {"method":"io.systemd.UserDatabase.GetMemberships","parameters":{"groupName":"sudoforge","service":"io.systemd.DynamicUser"},"more":true}
/run/systemd/userdb/io.systemd.DynamicUser: Changing state idle-client → awaiting-reply-more
/run/systemd/userdb/io.systemd.DynamicUser: New incoming message: {"error":"io.systemd.UserDatabase.NoRecordFound","parameters":{}}
/run/systemd/userdb/io.systemd.DynamicUser: Changing state awaiting-reply-more → processing-reply
Got lookup error: io.systemd.UserDatabase.NoRecordFound
/run/systemd/userdb/io.systemd.DynamicUser: Changing state processing-reply → idle-client
No credential name specified, not embedding credential name in encrypted data. (Disable this warning with --name=)
Including timestamp 'Sun 2023-07-09 12:15:01 PDT' in encrypted credential.
Using TPM2 TCTI driver 'device' with device '/dev/tpmrm0'.
Loaded TCTI module 'tcti-device' (TCTI module for communication with Linux kernel interface.) [Version 2]
TPM successfully started up.
Creating primary key on TPM.

[sudoforge]

I decided to just let the command sit. A primary key was finally generated after 9m 12s, and now it is hanging on creating an authentication session:

➜ sudo SYSTEMD_LOG_LEVEL=debug systemd-creds encrypt --with-key=tpm2 /tmp/tmp.JIC2YaG7kI -
No credential name specified, not embedding credential name in encrypted data. (Disable this warning with --name=)
Including timestamp 'Sun 2023-07-09 12:28:18 PDT' in encrypted credential.
Using TPM2 TCTI driver 'device' with device '/dev/tpmrm0'.
Loaded TCTI module 'tcti-device' (TCTI module for communication with Linux kernel interface.) [Version 2]
TPM successfully started up.
Creating primary key on TPM.
Successfully created ECC primary key on TPM.
Generating primary key on TPM2 took 9min 12.615s.
Starting HMAC encryption session.
Starting authentication session.

[sudoforge]

The above session actually concluded successfully... after two hours and change:

➜ sudo SYSTEMD_LOG_LEVEL=debug systemd-creds encrypt --with-key=tpm2 /tmp/tmp.JIC2YaG7kI -
No credential name specified, not embedding credential name in encrypted data. (Disable this warning with --name=)
Including timestamp 'Sun 2023-07-09 12:28:18 PDT' in encrypted credential.
Using TPM2 TCTI driver 'device' with device '/dev/tpmrm0'.
Loaded TCTI module 'tcti-device' (TCTI module for communication with Linux kernel interface.) [Version 2]
TPM successfully started up.
Creating primary key on TPM.
Successfully created ECC primary key on TPM.
Generating primary key on TPM2 took 9min 12.615s.
Starting HMAC encryption session.
Starting authentication session.
TPM2 PCR bank sha1 has fewer than 24 PCR bits enabled, ignoring.
PCR 7 value: REDACTED
TPM2 device supports SHA256 PCR bank and SHA256 PCRs are valid, yay!
Configuring hash-based PCR policy.
Acquiring policy digest.
Session policy digest: REDACTED
Added 32 bytes of TPM2 entropy to the kernel random pool in 10min 41.709117s.
Generating secret key data.
Creating HMAC key.
Marshalling private and public part of HMAC key.
Completed TPM2 key sealing in 2h 19min 49.045916s.
Input of 4 bytes grew to output of 518 bytes (+12850%).
<encrypted secret output redacted>

[poettering]

hmm, seems your tpm is terrible and generating entropy.

Added 32 bytes of TPM2 entropy to the kernel random pool in 10min 41.709117s.

what kind of tpm is this?

[poettering]

if you call tpm2_getrandom --hex 16 from the shell, is that also so terribly slow?

[poettering]

(smells like a driver/firmware/hw bug)

[sudoforge]

tpm2_getrandom --hex 16 took about 8s the first time, but is hanging for 5m+ at this point.

smells like a driver/firmware/hw bug

yep, agreed. it's new behavior, so could be a kernel bug or hardware.

what kind of tpm is this?

whatever is in the framework laptop. it's worked fine (without this looooooong delay) until yesterday. i looked through recent updates and decided systemd was the most likely culprit (if it wasn't a kernel/software bug). i'll close this and debug a bit more -- the issue clearly isn't systemd.