On Tue, Jun 16, 2020 at 06:30:24PM -0400, Stefan Berger wrote:
> I am upgrading libtpms's TPM 2 to support RSA 3072 keys (increase context
> size to 2680 bytes) and wanted to test an upgrade from previous version
> (0.7.2) which only supports RSA 2048 keys to this newer version (git
> master). I tried to run this with clevis setting up automatic decryption via
> TPM 2, but it doesn't work and it seems the issue is due to a stall of
> /dev/tpmr0 that doesn't respond anymore.
>
>
> So here's a simple sequence with added 'set -x' into clevis-encrypt-tpm2 and
> clevis-decrypt-tpm2:
>
> All good in the encryption part:
>
> [root@localhost ~]# echo hi | clevis encrypt tpm2 '{"key":"rsa"}' >
> hi-rsa3072.jwe
> + case "$TPM2TOOLS_VERSION" in
> + tpm2_createprimary -Q -C o -g sha256 -G rsa -c
> /tmp/tmp.cqg0DMjuL4/primary.context
> + set +x
> + case "$TPM2TOOLS_VERSION" in
> + tpm2_create -Q -g sha256 -C /tmp/tmp.cqg0DMjuL4/primary.context -u
> /tmp/tmp.cqg0DMjuL4/jwk.pub -r /tmp/tmp.cqg0DMjuL4/jwk.priv -a
> 'fixedtpm|fixedparent|noda|adminwithpolicy|userwithauth' -i-
> + set +x
>
> The decryption part stalls:
>
> [root@localhost ~]# clevis decrypt < hi-rsa3072.jwe 2>&1 | tee strace.log
> + case "$TPM2TOOLS_VERSION" in
> + tpm2_createprimary -Q -C o -g sha256 -G rsa -c
> /tmp/tmp.9W2U5Fw8HX/primary.context
> + set +x
> + case "$TPM2TOOLS_VERSION" in
> + tpm2_load -Q -C /tmp/tmp.9W2U5Fw8HX/primary.context -u
> /tmp/tmp.9W2U5Fw8HX/jwk.pub -r /tmp/tmp.9W2U5Fw8HX/jwk.priv -c
> /tmp/tmp.9W2U5Fw8HX/load.context -V
> INFO on line: "362" in file: "lib/files.c": Assuming tpm context file
> INFO on line: "293" in file: "lib/files.c": load: TPMS_CONTEXT->savedHandle:
> 0x80000000
> ^Z
> [1]+ Stopped clevis decrypt < hi-rsa3072.jwe 2>&1 | tee
> strace.log
>
>
> Note: I put the tool in the background using ctrl-Z and now I can run this
> stalled command and it works!
>
> [root@localhost ~]# tpm2_load -Q -C /tmp/tmp.9W2U5Fw8HX/primary.context -u
> /tmp/tmp.9W2U5Fw8HX/jwk.pub -r /tmp/tmp.9W2U5Fw8HX/jwk.priv -c load.context
> -V
> INFO on line: "362" in file: "lib/files.c": Assuming tpm context file
> INFO on line: "293" in file: "lib/files.c": load: TPMS_CONTEXT->savedHandle:
> 0x80000000
> INFO on line: "190" in file: "lib/files.c": Save TPMS_CONTEXT->savedHandle:
> 0x80000000
>
>
> I know that the above is stalled because I had strace'd it:
>
> openat(AT_FDCWD, "/dev/tpmrm0", O_RDWR|O_NONBLOCK) = 3
>
> [...]
>
> write(3, "\200\1\0\0\0;\0\0\1v@\0\0\7@\0\0\7\0
> \316)s\332fV_\177\326\303\221#"..., 59) = 59
> poll([{fd=3, events=POLLIN}], 1, -1) = 1 ([{fd=3, revents=POLLIN}])
> read(3, "\200\1\0\0\0000\0\0\0\0\2\0\0\0\0
> \303cQ\225\0\235F\4-\225:y\353\254\220\247"..., 4096) = 48
> openat(AT_FDCWD, "/tmp/tmp.9WItRVOByv/primary.context", O_RDONLY) = 4
> fstat(4, {st_mode=S_IFREG|0644, st_size=3036, ...}) = 0
> brk(NULL) = 0x55fc8d415000
> brk(0x55fc8d436000) = 0x55fc8d436000
> read(4, "\272\334\300\336\0\0\0\1@\0\0\1\200\0\0\0\0\0\0\0\0\0\0B\v\302\0\0\0\0\nr"...,
> 4096) = 3036
> lseek(4, -3036, SEEK_CUR) = 0
> write(2, "INFO on line: \"362\" in file: \"li"..., 44INFO on line: "362" in
> file: "lib/files.c": ) = 44
> write(2, "Assuming tpm context file", 25Assuming tpm context file) = 25
> write(2, "\n", 1
> ) = 1
> read(4, "\272\334\300\336\0\0\0\1@\0\0\1\200\0\0\0\0\0\0\0\0\0\0B\v\302\0\0\0\0\nr"...,
> 4096) = 3036
> write(2, "INFO on line: \"293\" in file: \"li"..., 44INFO on line: "293" in
> file: "lib/files.c": ) = 44
> write(2, "load: TPMS_CONTEXT->savedHandle:"..., 43load:
> TPMS_CONTEXT->savedHandle: 0x80000000) = 43
> write(2, "\n", 1
> ) = 1
> write(3,
> "\200\1\0\0\n\216\0\0\1a\0\0\0\0\0\0\0B\200\0\0\0@\0\0\1\nr\0@]\234"...,
> 2702) = 2702
> poll([{fd=3, events=POLLIN}], 1, -1) = 1 ([{fd=3, revents=POLLIN}])
> read(3, "\200\1\0\0\0\16\0\0\0\0\200\377\377\377", 4096) = 14
> close(4) = 0
> getpid() = 1591
> getpid() = 1591
> write(3, "\200\2\0\0\1{\0\0\1W\200\377\377\377\0\0\0I\2\0\0\0\0
> \203\33\326qO\214\r\0"..., 379) = 379
> poll([{fd=3, events=POLLIN}], 1, -1
>
> It's stuck polling on /dev/tpmrm0.
>
> Any ideas?
>
>
> Stefan
>
>
Tadeusz,
Could this possibly be something to do with partial reads?
/Jarkko
