systemd-cryptsetup times out (?) before TPM device is found

[LaserEyess]

systemd version the issue has been seen with

systemd 251 (251.6-2-arch)

Used distribution

Arch Linux

Linux kernel version used

6.0.1-arch2-1

CPU architectures issue was seen on

x86_64

Component

systemd-cryptsetup

Expected behaviour you didn't see

systemd-cryptsetup unlocks my drive with the TPM

Unexpected behaviour you saw

systemd-cryptsetup waits for the TPM, but it doesn't appear fast enough, so it fails back to password unlocking. However, in the debugging logs, it finds the TPM and successfully unlocks the drive, and still waits for a password.

Steps to reproduce the problem

1. enroll a disk with a TPM2 key
2. put tpm2-device=auto in your kernel cmdlineTokens:

Not really sure what else is going on

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

boot log https://0x0.st/ox1r.txt

# Excerpt from `cryptsetup luksInfo`
Tokens:
  0: systemd-tpm2
	tpm2-pcrs:  7
	tpm2-bank:  sha256
	tpm2-primary-alg:  ecc
	tpm2-blob:  00 9e 00 20 d3 c9 fb 2f 75 8f ff b4 30 c1 b0 a9
	           74 1e 44 a0 46 43 25 ac 49 63 a7 5b c2 27 6e d2
	           0a 56 d3 26 00 10 91 38 d1 89 c7 68 a7 23 8b e1
	           22 69 b5 5b f2 f0 63 70 d8 d0 c9 e9 16 7d 0e a1
	           d3 47 5f 14 be bc 43 95 47 99 14 7a 9c f0 91 d7
	           d1 89 9d 42 8a 47 3f 32 ae a9 fd c6 dd e5 11 43
	           65 35 45 1d 81 48 97 13 2b ba c8 62 91 ac 0f c9
	           80 79 e3 25 c5 5e 37 ff 77 27 d6 b5 bf 2f 48 d1
	           b9 e7 ab 54 8a ba 75 3a ef 6f 8d 6f d8 01 05 3f
	           69 b4 dd 25 36 62 ac fe 0f aa e3 2c e8 1b 3d 66
	           00 4e 00 08 00 0b 00 00 00 12 00 20 2b ca 34 a3
	           d6 48 da 42 4e 92 06 7f 0d 81 b8 7d 23 49 06 04
	           84 2c fd 96 75 f3 81 8c ce c3 6b 36 00 10 00 20
	           60 e4 7b 18 0d 1c 99 ce ce b0 94 03 c8 a9 dc 76
	           af c6 d7 0d 0a 08 0c 79 db 29 1f c1 03 9f fc 23
	tpm2-policy-hash:
	           2b ca 34 a3 d6 48 da 42 4e 92 06 7f 0d 81 b8 7d
	           23 49 06 04 84 2c fd 96 75 f3 81 8c ce c3 6b 36
	tpm2-pin: false
	Keyslot:    1

[poettering]

Please provides logs, otherwise this is simply not actionable

[LaserEyess]

What other logs do you need? Udev? That log should be with `systemd.log_level=debug`. I can reproduce this 100% so please let me know what is useful.

…

On Tue, Nov 1, 2022, 07:37 Lennart Poettering ***@***.***> wrote: Please provides logs, otherwise this is simply not actionable — Reply to this email directly, view it on GitHub <#25099 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AD6QHHMKFMI7RQW3HGE44ZTWGD6JFANCNFSM6AAAAAARLUUH2Q> . You are receiving this because you authored the thread.Message ID: ***@***.***>

[poettering]

ah, now seeing the link to the logs

[poettering]

Oct 21 21:50:53 charlotte systemd-cryptsetup[520]: TPM2 operation failed, falling back to traditional unlocking: Success

That is seriously strange. I don't see how that could ever happen... Is this reproducible in 252?

[LaserEyess]

I can try it in 252. I don't have access to the machine right now but should be able to do this by tonight or tomorrow morning.

…

On Tue, Nov 1, 2022, 08:11 Lennart Poettering ***@***.***> wrote: Oct 21 21:50:53 charlotte systemd-cryptsetup[520]: TPM2 operation failed, falling back to traditional unlocking: Success That is seriously strange. I don't see how that could ever happen... Is this reproducible in 252? — Reply to this email directly, view it on GitHub <#25099 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AD6QHHLEQTFLE2MSPRH5OHDWGECGNANCNFSM6AAAAAARLUUH2Q> . You are receiving this because you authored the thread.Message ID: ***@***.***>

[LaserEyess]

This is indeed fixed with 252 afaict