tpm2 failure on multiple sessions and sign loop

[nikolkam]

I have two test programs running on a same computer.

1. Opens a session with a token and does one sign operation using a private key inside it and sleeps indefinitely, holding a session without closing
2. Opens a session with the same token and does repeated sign operation on infinite loop with one session

I start program 1 and then program 2 and let it keep running. When it reaches around 65k (around 16 bytes maximum number), sign operation using the token starts failing and does not recover unless I close every program holding a session or I run tpm2 flushcontext --saved-session. It seems like it fails inside StartAuthSession and fails to read from a tpm device. The error was reproducable on both vm and physical machines so I don't feel like it's a hardware issue. Is there any known limitation/bugs with tpm that I'm not aware of?

Here is a trace log of trying to do sign operation on a vm with failed state of tpm.

debug:tcti:src/tss2-tcti/tctildr-nodl.c:142:tctildr_get_default() Attempting to connect using standard TCTI: Access to /dev/tpmrm0 
trace:tcti:src/tss2-tcti/tctildr.c:63:tcti_from_init() Initializing TCTI for config: /dev/tpmrm0 
debug:tcti:src/tss2-tcti/tcti-device.c:448:Tss2_Tcti_Device_Init() Trying to open specified TCTI device file /dev/tpmrm0 
trace:tcti:src/tss2-tcti/tcti-device.c:455:Tss2_Tcti_Device_Init() Successfully opened specified TCTI device file /dev/tpmrm0 
debug:tcti:src/tss2-tcti/tcti-device.c:460:Tss2_Tcti_Device_Init() Probe device for partial response read support 
debug:tcti:src/util/io.c:97:write_all() writing 12 bytes starting at 0x7ffd2c953b34 to fd 4 
debug:tcti:src/util/io.c:108:write_all() wrote 12 bytes to fd 4 
debug:tcti:src/tss2-tcti/tcti-device.c:472:Tss2_Tcti_Device_Init() Command sent, reading header 
debug:tcti:src/tss2-tcti/tcti-device.c:491:Tss2_Tcti_Device_Init() Header read, reading rest of response 
debug:tcti:src/tss2-tcti/tcti-device.c:522:Tss2_Tcti_Device_Init() Read the rest - partial read supported 
debug:tcti:src/tss2-tcti/tctildr.c:100:tcti_from_init() Initialized TCTI for config: /dev/tpmrm0 
trace:esys:src/tss2-esys/api/Esys_GetCapability.c:159:Esys_GetCapability_Async() context=0x55d38ee552d0, capability=0, property=1,propertyCount=7f 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 22 byte command buffer: (size=22): 
0000: 8001000000160000017a000000000000  .........z......
0010: 00010000007f                      ......
debug:tcti:src/util/io.c:97:write_all() writing 22 bytes starting at 0x55d38ee568e0 to fd 4 
debug:tcti:src/util/io.c:108:write_all() wrote 22 bytes to fd 4 
trace:esys:src/tss2-esys/api/Esys_GetCapability.c:247:Esys_GetCapability_Finish() context=0x55d38ee552d0, moreData=0x7ffd2c95375f, capabilityData=0x7ffd2c953760 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
debug:tcti:src/tss2-tcti/tcti-device.c:202:tcti_device_receive() Partial read - received header 
debug:tcti:src/tss2-tcti/tcti-device.c:215:tcti_device_receive() Partial read - received response size 163. 
debug:tcti:src/tss2-tcti/tcti-device.c:273:tcti_device_receive() Response Received (size=163): 
0000: 8001000000a300000000000000000000  ................
0010: 00001800010000000900040000000400  ................
0020: 05000001040006000000020007000004  ................
0030: 0400080000030c000a00000006000b00  ................
0040: 000004000c0000000400140000010100  ................
0050: 15000002010016000001010017000002  ................
0060: 01001800000501001900000401001a00  ................
0070: 00010100220000040400230000000900  ....".....#.....
0080: 25000000080040000002020041000002  %.....@.....A...
0090: 02004200000202004300000202004400  ..B.....C.....D.
00a0: 000202                            ...
trace:tcti:src/tss2-tcti/tcti-common.c:139:header_unmarshal() Parsing header from buffer: 0x55d38ee568e0 
debug:tcti:src/tss2-tcti/tcti-device.c:287:tcti_device_receive() Size from header 163 bytes read 163 
trace:esys:src/tss2-esys/esys_iutil.c:1404:iesys_check_response() No auths to verify 
trace:esys:src/tss2-esys/api/Esys_GetCapability.c:159:Esys_GetCapability_Async() context=0x55d38ee552d0, capability=6, property=100,propertyCount=7f 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 22 byte command buffer: (size=22): 
0000: 8001000000160000017a000000060000  .........z......
0010: 01000000007f                      ......
debug:tcti:src/util/io.c:97:write_all() writing 22 bytes starting at 0x55d38ee568e0 to fd 4 
debug:tcti:src/util/io.c:108:write_all() wrote 22 bytes to fd 4 
trace:esys:src/tss2-esys/api/Esys_GetCapability.c:247:Esys_GetCapability_Finish() context=0x55d38ee552d0, moreData=0x7ffd2c95372f, capabilityData=0x7ffd2c953730 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
debug:tcti:src/tss2-tcti/tcti-device.c:202:tcti_device_receive() Partial read - received header 
debug:tcti:src/tss2-tcti/tcti-device.c:215:tcti_device_receive() Partial read - received response size 523. 
debug:tcti:src/tss2-tcti/tcti-device.c:273:tcti_device_receive() Response Received (size=523): 
0000: 80010000020b00000000000000000600  ................
0010: 00003f00000100322e30000000010100  ..?....2.0......
0020: 00000000000102000000740000010300  ..........t.....
0030: 00012e00000104000007de000001054d  ...............M
0040: 53465400000106496f54200000010753  SFT....IoT.....S
0050: 6f667400000108776172650000010920  oft....ware.....
0060: 54504d0000010a000000010000010b20  TPM.............
0070: 1501130000010c001548220000010d00  .........H".....
0080: 0004000000010e000000030000010f00  ................
0090: 00000200000110000000030000011100  ................
00a0: 00004000000112000000180000011300  ..@.............
00b0: 000003000001140000ffff0000011600  ................
00c0: 00000000000117000008000000011800  ................
00d0: 00000600000119000010000000011a00  ................
00e0: 00000b0000011b000000060000011c00  ................
00f0: 0001000000011d000000ff0000011e00  ................
0100: 0010000000011f000010000000012000  ................
0110: 00003000000121000005f00000012200  ..0...!.......".
0120: 00013400000123000000000000012400  ..4...#.......$.
0130: 00000000000125000000000000012600  ......%.......&.
0140: 00000000000127000000000000012800  ......'.......(.
0150: 000080000001290000006a0000012a00  ......)...j...*.
0160: 0000690000012b000000010000020000  ..i...+.........
0170: 000400000002010000000e0000020200  ................
0180: 00000200000203000000000000020400  ................
0190: 00000300000205000000010000020600  ................
01a0: 00003f00000207000000030000020800  ..?.............
01b0: 00000200000209000000040000020a00  ................
01c0: 0000000000020b000000200000020c00  ................
01d0: 0000000000020d000000030000020e00  ................
01e0: 0000000000020f000000030000021000  ................
01f0: 0003e800000211000003e80000021300  ................
0200: 0000000000021400000000            ...........
trace:tcti:src/tss2-tcti/tcti-common.c:139:header_unmarshal() Parsing header from buffer: 0x55d38ee568e0 
debug:tcti:src/tss2-tcti/tcti-device.c:287:tcti_device_receive() Size from header 523 bytes read 523 
trace:esys:src/tss2-esys/esys_iutil.c:1404:iesys_check_response() No auths to verify 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:143:Esys_TestParms_Async() context=0x55d38ee552d0, parameters=0x7ffd2c9537b0 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 22 byte command buffer: (size=22): 
0000: 8001000000160000018a000100100010  ................
0010: 040000000000                      ......
debug:tcti:src/util/io.c:97:write_all() writing 22 bytes starting at 0x55d38ee568e0 to fd 4 
debug:tcti:src/util/io.c:108:write_all() wrote 22 bytes to fd 4 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:225:Esys_TestParms_Finish() context=0x55d38ee552d0 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
debug:tcti:src/tss2-tcti/tcti-device.c:202:tcti_device_receive() Partial read - received header 
debug:tcti:src/tss2-tcti/tcti-device.c:215:tcti_device_receive() Partial read - received response size 10. 
trace:esys:src/tss2-esys/esys_iutil.c:1404:iesys_check_response() No auths to verify 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:143:Esys_TestParms_Async() context=0x55d38ee552d0, parameters=0x7ffd2c9537b0 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 22 byte command buffer: (size=22): 
0000: 8001000000160000018a000100100010  ................
0010: 080000000000                      ......
debug:tcti:src/util/io.c:97:write_all() writing 22 bytes starting at 0x55d38ee568e0 to fd 4 
debug:tcti:src/util/io.c:108:write_all() wrote 22 bytes to fd 4 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:225:Esys_TestParms_Finish() context=0x55d38ee552d0 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
debug:tcti:src/tss2-tcti/tcti-device.c:202:tcti_device_receive() Partial read - received header 
debug:tcti:src/tss2-tcti/tcti-device.c:215:tcti_device_receive() Partial read - received response size 10. 
trace:esys:src/tss2-esys/esys_iutil.c:1404:iesys_check_response() No auths to verify 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:143:Esys_TestParms_Async() context=0x55d38ee552d0, parameters=0x7ffd2c9537b0 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 22 byte command buffer: (size=22): 
0000: 8001000000160000018a000100100010  ................
0010: 0c0000000000                      ......
debug:tcti:src/util/io.c:97:write_all() writing 22 bytes starting at 0x55d38ee568e0 to fd 4 
debug:tcti:src/util/io.c:108:write_all() wrote 22 bytes to fd 4 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:225:Esys_TestParms_Finish() context=0x55d38ee552d0 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
debug:tcti:src/tss2-tcti/tcti-device.c:202:tcti_device_receive() Partial read - received header 
debug:tcti:src/tss2-tcti/tcti-device.c:215:tcti_device_receive() Partial read - received response size 10. 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:143:Esys_TestParms_Async() context=0x55d38ee552d0, parameters=0x7ffd2c9537b0 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 22 byte command buffer: (size=22): 
0000: 8001000000160000018a000100100010  ................
0010: 100000000000                      ......
debug:tcti:src/util/io.c:97:write_all() writing 22 bytes starting at 0x55d38ee568e0 to fd 4 
debug:tcti:src/util/io.c:108:write_all() wrote 22 bytes to fd 4 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:225:Esys_TestParms_Finish() context=0x55d38ee552d0 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
debug:tcti:src/tss2-tcti/tcti-device.c:202:tcti_device_receive() Partial read - received header 
debug:tcti:src/tss2-tcti/tcti-device.c:215:tcti_device_receive() Partial read - received response size 10. 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:143:Esys_TestParms_Async() context=0x55d38ee552d0, parameters=0x7ffd2c9537b0 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 20 byte command buffer: (size=20): 
0000: 8001000000140000018a002300100010  ...........#....
0010: 00010010                          ....
debug:tcti:src/util/io.c:97:write_all() writing 20 bytes starting at 0x55d38ee568e0 to fd 4 
debug:tcti:src/util/io.c:108:write_all() wrote 20 bytes to fd 4 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:225:Esys_TestParms_Finish() context=0x55d38ee552d0 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
debug:tcti:src/tss2-tcti/tcti-device.c:202:tcti_device_receive() Partial read - received header 
debug:tcti:src/tss2-tcti/tcti-device.c:215:tcti_device_receive() Partial read - received response size 10. 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:143:Esys_TestParms_Async() context=0x55d38ee552d0, parameters=0x7ffd2c9537b0 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 20 byte command buffer: (size=20): 
0000: 8001000000140000018a002300100010  ...........#....
0010: 00020010                          ....
debug:tcti:src/util/io.c:97:write_all() writing 20 bytes starting at 0x55d38ee568e0 to fd 4 
debug:tcti:src/util/io.c:108:write_all() wrote 20 bytes to fd 4 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:225:Esys_TestParms_Finish() context=0x55d38ee552d0 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
debug:tcti:src/tss2-tcti/tcti-device.c:202:tcti_device_receive() Partial read - received header 
debug:tcti:src/tss2-tcti/tcti-device.c:215:tcti_device_receive() Partial read - received response size 10. 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:143:Esys_TestParms_Async() context=0x55d38ee552d0, parameters=0x7ffd2c9537b0 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 20 byte command buffer: (size=20): 
0000: 8001000000140000018a002300100010  ...........#....
0010: 00030010                          ....
debug:tcti:src/util/io.c:97:write_all() writing 20 bytes starting at 0x55d38ee568e0 to fd 4 
debug:tcti:src/util/io.c:108:write_all() wrote 20 bytes to fd 4 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:225:Esys_TestParms_Finish() context=0x55d38ee552d0 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
debug:tcti:src/tss2-tcti/tcti-device.c:202:tcti_device_receive() Partial read - received header 
debug:tcti:src/tss2-tcti/tcti-device.c:215:tcti_device_receive() Partial read - received response size 10. 
trace:esys:src/tss2-esys/esys_iutil.c:1404:iesys_check_response() No auths to verify 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:143:Esys_TestParms_Async() context=0x55d38ee552d0, parameters=0x7ffd2c9537b0 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 20 byte command buffer: (size=20): 
0000: 8001000000140000018a002300100010  ...........#....
0010: 00040010                          ....
debug:tcti:src/util/io.c:97:write_all() writing 20 bytes starting at 0x55d38ee568e0 to fd 4 
debug:tcti:src/util/io.c:108:write_all() wrote 20 bytes to fd 4 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:225:Esys_TestParms_Finish() context=0x55d38ee552d0 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
debug:tcti:src/tss2-tcti/tcti-device.c:202:tcti_device_receive() Partial read - received header 
debug:tcti:src/tss2-tcti/tcti-device.c:215:tcti_device_receive() Partial read - received response size 10. 
trace:esys:src/tss2-esys/esys_iutil.c:1404:iesys_check_response() No auths to verify 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:143:Esys_TestParms_Async() context=0x55d38ee552d0, parameters=0x7ffd2c9537b0 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 20 byte command buffer: (size=20): 
0000: 8001000000140000018a002300100010  ...........#....
0010: 00050010                          ....
debug:tcti:src/util/io.c:97:write_all() writing 20 bytes starting at 0x55d38ee568e0 to fd 4 
debug:tcti:src/util/io.c:108:write_all() wrote 20 bytes to fd 4 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:225:Esys_TestParms_Finish() context=0x55d38ee552d0 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
debug:tcti:src/tss2-tcti/tcti-device.c:202:tcti_device_receive() Partial read - received header 
debug:tcti:src/tss2-tcti/tcti-device.c:215:tcti_device_receive() Partial read - received response size 10. 
trace:esys:src/tss2-esys/api/Esys_CreatePrimary.c:192:Esys_CreatePrimary_Async() context=0x55d38ee552d0, primaryHandle=101, inSensitive=0x7ffd2c953880,inPublic=0x7ffd2c9539d0, outsideInfo=0x7ffd2c9537a0, creationPCR=0x7ffd2c9537f0 
trace:esys_crypto:src/tss2-esys/esys_crypto.c:34:iesys_crypto_hash_get_digest_size() call: hashAlg=11 size=0x7ffd2c953408 
trace:esys_crypto:src/tss2-esys/esys_crypto.c:59:iesys_crypto_hash_get_digest_size() return: *size=32 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 67 byte command buffer: (size=67): 
0000: 80020000004300000131400000010000  .....C...1@.....
0010: 00094000000900000000000004000000  ..@.............
0020: 00001a0001000b000300720000000600  ..........r.....
0030: 80004300100800000000000000000000  ..C.............
0040: 000000                            ...
debug:tcti:src/util/io.c:97:write_all() writing 67 bytes starting at 0x55d38ee568e0 to fd 4 
debug:tcti:src/util/io.c:108:write_all() wrote 67 bytes to fd 4 
trace:esys:src/tss2-esys/api/Esys_CreatePrimary.c:314:Esys_CreatePrimary_Finish() context=0x55d38ee552d0, objectHandle=0x7ffd2c95377c, outPublic=0x7ffd2c953780,creationData=0x7ffd2c953788, creationHash=0x7ffd2c953790, creationTicket=0x7ffd2c953798 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
debug:tcti:src/tss2-tcti/tcti-device.c:202:tcti_device_receive() Partial read - received header 
debug:tcti:src/tss2-tcti/tcti-device.c:215:tcti_device_receive() Partial read - received response size 474. 
debug:tcti:src/tss2-tcti/tcti-device.c:273:tcti_device_receive() Response Received (size=474): 
0000: 8002000001da0000000080ffffff0000  ................
0010: 01c3011a0001000b0003007200000006  ...........r....
0020: 0080004300100800000000000100de28  ...C...........(
0030: 4b3f05087a1649fad20aa6f444be6723  K?..z.I.....D.g#
0040: 3e004a34c5106b2e0eba8b20f52b27d3  >.J4..k......+'.
0050: 43c730ffc26d53e2214afc67dbc2ae95  C.0..mS.!J.g....
0060: 8c62bc468a1c6302d14f1586e9799c9b  .b.F..c..O...y..
0070: d91edbd417da026bb9a880aeb5e4e073  .......k.......s
0080: 7851adb2581bc24ce7026110545eaa31  xQ..X..L..a.T^.1
0090: 97759055bbe59e58aed034dc0fb423c5  .u.U...X..4...#.
00a0: 44d4167a4375ff8ecb73f374bf37bcb5  D..zCu...s.t.7..
00b0: 132de8a9d0291205589725dfc6f913df  .-...)..X.%.....
00c0: ddaea873e562c234f39096030975429d  ...s.b.4.....uB.
00d0: f4dd52b2e893c451f081cfd932266825  ..R....Q....2&h%
00e0: 27fe51ee26f2cf25bc04a0a5e4e7fcf4  '.Q.&..%........
00f0: 9ec35652a7d065ecba756868f4b901bd  ..VR..e..uhh....
0100: 5dec9552aa84ee69e7315ab0bafcfce1  ]..R...i.1Z.....
0110: 1c396ee26e1181ec9ffb3a88871ef288  .9n.n.....:.....
0120: 3788c98ad02ed3b6ec859c8704c10037  7..............7
0130: 000000000020e3b0c44298fc1c149afb  .........B......
0140: f4c8996fb92427ae41e4649b934ca495  ...o.$'.A.d..L..
0150: 991b7852b85501001000044000000100  ..xR.U.....@....
0160: 0440000001000000205da041bac0ee31  .@.......].A...1
0170: 35aebb0cadfba497c6a1877fae832dd3  5.............-.
0180: d1f8f7a871b825e85480214000000100  ....q.%.T.!@....
0190: 209fdac4e9bf045f77211070a4a75ee7  ......._w!.p..^.
01a0: 6287d01a06d51cdcbf8bbfad0a6745e6  b............gE.
01b0: cb0022000b4cb04c72e14b5f6f9e1d69  .."..L.Lr.K_o..i
01c0: 18bed56c8f45568e91a6d1c086a7c49d  ...l.EV.........
01d0: 595eb766d90000010000              Y^.f......
trace:tcti:src/tss2-tcti/tcti-common.c:139:header_unmarshal() Parsing header from buffer: 0x55d38ee568e0 
debug:tcti:src/tss2-tcti/tcti-device.c:287:tcti_device_receive() Size from header 474 bytes read 474 
trace:esys_crypto:src/tss2-esys/esys_crypto_ossl.c:189:iesys_cryptossl_hash_start() call: context=0x7ffd2c9532e8 hashAlg=11 
trace:esys_crypto:src/tss2-esys/esys_crypto.c:34:iesys_crypto_hash_get_digest_size() call: hashAlg=11 size=0x55d38ee59820 
trace:esys_crypto:src/tss2-esys/esys_crypto.c:59:iesys_crypto_hash_get_digest_size() return: *size=32 
trace:esys_crypto:src/tss2-esys/esys_crypto_ossl.c:244:iesys_cryptossl_hash_update() called for context 0x55d38ee59800, buffer 0x7ffd2c9532f0 and size 282 
trace:esys_crypto:src/tss2-esys/esys_crypto_ossl.c:255:iesys_cryptossl_hash_update() Updating hash with (size=282): 
0000: 0001000b000300720000000600800043  .......r.......C
0010: 00100800000000000100de284b3f0508  ...........(K?..
0020: 7a1649fad20aa6f444be67233e004a34  z.I.....D.g#>.J4
0030: c5106b2e0eba8b20f52b27d343c730ff  ..k......+'.C.0.
0040: c26d53e2214afc67dbc2ae958c62bc46  .mS.!J.g.....b.F
0050: 8a1c6302d14f1586e9799c9bd91edbd4  ..c..O...y......
0060: 17da026bb9a880aeb5e4e0737851adb2  ...k.......sxQ..
0070: 581bc24ce7026110545eaa3197759055  X..L..a.T^.1.u.U
0080: bbe59e58aed034dc0fb423c544d4167a  ...X..4...#.D..z
0090: 4375ff8ecb73f374bf37bcb5132de8a9  Cu...s.t.7...-..
00a0: d0291205589725dfc6f913dfddaea873  .)..X.%........s
00b0: e562c234f39096030975429df4dd52b2  .b.4.....uB...R.
00c0: e893c451f081cfd93226682527fe51ee  ...Q....2&h%'.Q.
00d0: 26f2cf25bc04a0a5e4e7fcf49ec35652  &..%..........VR
00e0: a7d065ecba756868f4b901bd5dec9552  ..e..uhh....]..R
00f0: aa84ee69e7315ab0bafcfce11c396ee2  ...i.1Z......9n.
0100: 6e1181ec9ffb3a88871ef2883788c98a  n.....:.....7...
0110: d02ed3b6ec859c8704c1              ..........
trace:esys_crypto:src/tss2-esys/esys_crypto_ossl.c:285:iesys_cryptossl_hash_finish() called for context-pointer 0x7ffd2c9532e8, buffer 0x7ffd2c9535a4 and size-pointer 0x7ffd2c9532e0 
trace:esys_crypto:src/tss2-esys/esys_crypto_ossl.c:307:iesys_cryptossl_hash_finish() read hash result (size=32): 
0000: 4cb04c72e14b5f6f9e1d6918bed56c8f  L.Lr.K_o..i...l.
0010: 45568e91a6d1c086a7c49d595eb766d9  EV.........Y^.f.
trace:esys:src/tss2-esys/esys_iutil.c:87:cmp_TPM2B_NAME() call 
trace:esys:src/tss2-esys/esys_iutil.c:29:cmp_UINT16() call 
debug:tcti:src/tss2-tcti/tctildr-nodl.c:142:tctildr_get_default() Attempting to connect using standard TCTI: Access to /dev/tpmrm0 
trace:tcti:src/tss2-tcti/tctildr.c:63:tcti_from_init() Initializing TCTI for config: /dev/tpmrm0 
debug:tcti:src/tss2-tcti/tcti-device.c:448:Tss2_Tcti_Device_Init() Trying to open specified TCTI device file /dev/tpmrm0 
trace:tcti:src/tss2-tcti/tcti-device.c:455:Tss2_Tcti_Device_Init() Successfully opened specified TCTI device file /dev/tpmrm0 
debug:tcti:src/tss2-tcti/tcti-device.c:460:Tss2_Tcti_Device_Init() Probe device for partial response read support 
debug:tcti:src/util/io.c:97:write_all() writing 12 bytes starting at 0x7ffd2c953bc4 to fd 5 
debug:tcti:src/util/io.c:108:write_all() wrote 12 bytes to fd 5 
debug:tcti:src/tss2-tcti/tcti-device.c:472:Tss2_Tcti_Device_Init() Command sent, reading header 
debug:tcti:src/tss2-tcti/tcti-device.c:491:Tss2_Tcti_Device_Init() Header read, reading rest of response 
debug:tcti:src/tss2-tcti/tcti-device.c:522:Tss2_Tcti_Device_Init() Read the rest - partial read supported 
debug:tcti:src/tss2-tcti/tctildr.c:100:tcti_from_init() Initialized TCTI for config: /dev/tpmrm0 
trace:esys:src/tss2-esys/api/Esys_GetCapability.c:159:Esys_GetCapability_Async() context=0x55d38ee604f0, capability=0, property=1,propertyCount=7f 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 22 byte command buffer: (size=22): 
0000: 8001000000160000017a000000000000  .........z......
0010: 00010000007f                      ......
debug:tcti:src/util/io.c:97:write_all() writing 22 bytes starting at 0x55d38ee6abb0 to fd 5 
debug:tcti:src/util/io.c:108:write_all() wrote 22 bytes to fd 5 
trace:esys:src/tss2-esys/api/Esys_GetCapability.c:247:Esys_GetCapability_Finish() context=0x55d38ee604f0, moreData=0x7ffd2c9537ef, capabilityData=0x7ffd2c9537f0 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
debug:tcti:src/tss2-tcti/tcti-device.c:202:tcti_device_receive() Partial read - received header 
debug:tcti:src/tss2-tcti/tcti-device.c:215:tcti_device_receive() Partial read - received response size 163. 
debug:tcti:src/tss2-tcti/tcti-device.c:273:tcti_device_receive() Response Received (size=163): 
0000: 8001000000a300000000000000000000  ................
0010: 00001800010000000900040000000400  ................
0020: 05000001040006000000020007000004  ................
0030: 0400080000030c000a00000006000b00  ................
0040: 000004000c0000000400140000010100  ................
0050: 15000002010016000001010017000002  ................
0060: 01001800000501001900000401001a00  ................
0070: 00010100220000040400230000000900  ....".....#.....
0080: 25000000080040000002020041000002  %.....@.....A...
0090: 02004200000202004300000202004400  ..B.....C.....D.
00a0: 000202                            ...
trace:tcti:src/tss2-tcti/tcti-common.c:139:header_unmarshal() Parsing header from buffer: 0x55d38ee6abb0 
debug:tcti:src/tss2-tcti/tcti-device.c:287:tcti_device_receive() Size from header 163 bytes read 163 
trace:esys:src/tss2-esys/esys_iutil.c:1404:iesys_check_response() No auths to verify 
trace:esys:src/tss2-esys/api/Esys_GetCapability.c:159:Esys_GetCapability_Async() context=0x55d38ee604f0, capability=6, property=100,propertyCount=7f 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 22 byte command buffer: (size=22): 
0000: 8001000000160000017a000000060000  .........z......
0010: 01000000007f                      ......
debug:tcti:src/util/io.c:97:write_all() writing 22 bytes starting at 0x55d38ee6abb0 to fd 5 
debug:tcti:src/util/io.c:108:write_all() wrote 22 bytes to fd 5 
trace:esys:src/tss2-esys/api/Esys_GetCapability.c:247:Esys_GetCapability_Finish() context=0x55d38ee604f0, moreData=0x7ffd2c9537bf, capabilityData=0x7ffd2c9537c0 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
debug:tcti:src/tss2-tcti/tcti-device.c:202:tcti_device_receive() Partial read - received header 
debug:tcti:src/tss2-tcti/tcti-device.c:215:tcti_device_receive() Partial read - received response size 523. 
debug:tcti:src/tss2-tcti/tcti-device.c:273:tcti_device_receive() Response Received (size=523): 
0000: 80010000020b00000000000000000600  ................
0010: 00003f00000100322e30000000010100  ..?....2.0......
0020: 00000000000102000000740000010300  ..........t.....
0030: 00012e00000104000007de000001054d  ...............M
0040: 53465400000106496f54200000010753  SFT....IoT.....S
0050: 6f667400000108776172650000010920  oft....ware.....
0060: 54504d0000010a000000010000010b20  TPM.............
0070: 1501130000010c001548220000010d00  .........H".....
0080: 0004000000010e000000030000010f00  ................
0090: 00000200000110000000030000011100  ................
00a0: 00004000000112000000180000011300  ..@.............
00b0: 000003000001140000ffff0000011600  ................
00c0: 00000000000117000008000000011800  ................
00d0: 00000600000119000010000000011a00  ................
00e0: 00000b0000011b000000060000011c00  ................
00f0: 0001000000011d000000ff0000011e00  ................
0100: 0010000000011f000010000000012000  ................
0110: 00003000000121000005f00000012200  ..0...!.......".
0120: 00013400000123000000000000012400  ..4...#.......$.
0130: 00000000000125000000000000012600  ......%.......&.
0140: 00000000000127000000000000012800  ......'.......(.
0150: 000080000001290000006a0000012a00  ......)...j...*.
0160: 0000690000012b000000010000020000  ..i...+.........
0170: 000400000002010000000e0000020200  ................
0180: 00000200000203000000000000020400  ................
0190: 00000300000205000000010000020600  ................
01a0: 00003f00000207000000030000020800  ..?.............
01b0: 00000200000209000000040000020a00  ................
01c0: 0000000000020b000000200000020c00  ................
01d0: 0000000000020d000000030000020e00  ................
01e0: 0000000000020f000000030000021000  ................
01f0: 0003e800000211000003e80000021300  ................
0200: 0000000000021400000000            ...........
trace:tcti:src/tss2-tcti/tcti-common.c:139:header_unmarshal() Parsing header from buffer: 0x55d38ee6abb0 
debug:tcti:src/tss2-tcti/tcti-device.c:287:tcti_device_receive() Size from header 523 bytes read 523 
trace:esys:src/tss2-esys/esys_iutil.c:1404:iesys_check_response() No auths to verify 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:143:Esys_TestParms_Async() context=0x55d38ee604f0, parameters=0x7ffd2c953840 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 22 byte command buffer: (size=22): 
0000: 8001000000160000018a000100100010  ................
0010: 040000000000                      ......
debug:tcti:src/util/io.c:97:write_all() writing 22 bytes starting at 0x55d38ee6abb0 to fd 5 
debug:tcti:src/util/io.c:108:write_all() wrote 22 bytes to fd 5 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:225:Esys_TestParms_Finish() context=0x55d38ee604f0 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
debug:tcti:src/tss2-tcti/tcti-device.c:202:tcti_device_receive() Partial read - received header 
debug:tcti:src/tss2-tcti/tcti-device.c:215:tcti_device_receive() Partial read - received response size 10. 
trace:esys:src/tss2-esys/esys_iutil.c:1404:iesys_check_response() No auths to verify 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:143:Esys_TestParms_Async() context=0x55d38ee604f0, parameters=0x7ffd2c953840 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 22 byte command buffer: (size=22): 
0000: 8001000000160000018a000100100010  ................
0010: 080000000000                      ......
debug:tcti:src/util/io.c:97:write_all() writing 22 bytes starting at 0x55d38ee6abb0 to fd 5 
debug:tcti:src/util/io.c:108:write_all() wrote 22 bytes to fd 5 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:225:Esys_TestParms_Finish() context=0x55d38ee604f0 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
debug:tcti:src/tss2-tcti/tcti-device.c:202:tcti_device_receive() Partial read - received header 
debug:tcti:src/tss2-tcti/tcti-device.c:215:tcti_device_receive() Partial read - received response size 10. 
trace:esys:src/tss2-esys/esys_iutil.c:1404:iesys_check_response() No auths to verify 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:143:Esys_TestParms_Async() context=0x55d38ee604f0, parameters=0x7ffd2c953840 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 22 byte command buffer: (size=22): 
0000: 8001000000160000018a000100100010  ................
0010: 0c0000000000                      ......
debug:tcti:src/util/io.c:97:write_all() writing 22 bytes starting at 0x55d38ee6abb0 to fd 5 
debug:tcti:src/util/io.c:108:write_all() wrote 22 bytes to fd 5 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:225:Esys_TestParms_Finish() context=0x55d38ee604f0 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
debug:tcti:src/tss2-tcti/tcti-device.c:202:tcti_device_receive() Partial read - received header 
debug:tcti:src/tss2-tcti/tcti-device.c:215:tcti_device_receive() Partial read - received response size 10. 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:143:Esys_TestParms_Async() context=0x55d38ee604f0, parameters=0x7ffd2c953840 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 22 byte command buffer: (size=22): 
0000: 8001000000160000018a000100100010  ................
0010: 100000000000                      ......
debug:tcti:src/util/io.c:97:write_all() writing 22 bytes starting at 0x55d38ee6abb0 to fd 5 
debug:tcti:src/util/io.c:108:write_all() wrote 22 bytes to fd 5 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:225:Esys_TestParms_Finish() context=0x55d38ee604f0 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
debug:tcti:src/tss2-tcti/tcti-device.c:202:tcti_device_receive() Partial read - received header 
debug:tcti:src/tss2-tcti/tcti-device.c:215:tcti_device_receive() Partial read - received response size 10. 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:143:Esys_TestParms_Async() context=0x55d38ee604f0, parameters=0x7ffd2c953840 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 20 byte command buffer: (size=20): 
0000: 8001000000140000018a002300100010  ...........#....
0010: 00010010                          ....
debug:tcti:src/util/io.c:97:write_all() writing 20 bytes starting at 0x55d38ee6abb0 to fd 5 
debug:tcti:src/util/io.c:108:write_all() wrote 20 bytes to fd 5 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:225:Esys_TestParms_Finish() context=0x55d38ee604f0 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
debug:tcti:src/tss2-tcti/tcti-device.c:202:tcti_device_receive() Partial read - received header 
debug:tcti:src/tss2-tcti/tcti-device.c:215:tcti_device_receive() Partial read - received response size 10. 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:143:Esys_TestParms_Async() context=0x55d38ee604f0, parameters=0x7ffd2c953840 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 20 byte command buffer: (size=20): 
0000: 8001000000140000018a002300100010  ...........#....
0010: 00020010                          ....
debug:tcti:src/util/io.c:97:write_all() writing 20 bytes starting at 0x55d38ee6abb0 to fd 5 
debug:tcti:src/util/io.c:108:write_all() wrote 20 bytes to fd 5 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:225:Esys_TestParms_Finish() context=0x55d38ee604f0 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
debug:tcti:src/tss2-tcti/tcti-device.c:202:tcti_device_receive() Partial read - received header 
debug:tcti:src/tss2-tcti/tcti-device.c:215:tcti_device_receive() Partial read - received response size 10. 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:143:Esys_TestParms_Async() context=0x55d38ee604f0, parameters=0x7ffd2c953840 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 20 byte command buffer: (size=20): 
0000: 8001000000140000018a002300100010  ...........#....
0010: 00030010                          ....
debug:tcti:src/util/io.c:97:write_all() writing 20 bytes starting at 0x55d38ee6abb0 to fd 5 
debug:tcti:src/util/io.c:108:write_all() wrote 20 bytes to fd 5 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:225:Esys_TestParms_Finish() context=0x55d38ee604f0 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
debug:tcti:src/tss2-tcti/tcti-device.c:202:tcti_device_receive() Partial read - received header 
debug:tcti:src/tss2-tcti/tcti-device.c:215:tcti_device_receive() Partial read - received response size 10. 
trace:esys:src/tss2-esys/esys_iutil.c:1404:iesys_check_response() No auths to verify 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:143:Esys_TestParms_Async() context=0x55d38ee604f0, parameters=0x7ffd2c953840 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 20 byte command buffer: (size=20): 
0000: 8001000000140000018a002300100010  ...........#....
0010: 00040010                          ....
debug:tcti:src/util/io.c:97:write_all() writing 20 bytes starting at 0x55d38ee6abb0 to fd 5 
debug:tcti:src/util/io.c:108:write_all() wrote 20 bytes to fd 5 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:225:Esys_TestParms_Finish() context=0x55d38ee604f0 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
debug:tcti:src/tss2-tcti/tcti-device.c:202:tcti_device_receive() Partial read - received header 
debug:tcti:src/tss2-tcti/tcti-device.c:215:tcti_device_receive() Partial read - received response size 10. 
trace:esys:src/tss2-esys/esys_iutil.c:1404:iesys_check_response() No auths to verify 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:143:Esys_TestParms_Async() context=0x55d38ee604f0, parameters=0x7ffd2c953840 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 20 byte command buffer: (size=20): 
0000: 8001000000140000018a002300100010  ...........#....
0010: 00050010                          ....
debug:tcti:src/util/io.c:97:write_all() writing 20 bytes starting at 0x55d38ee6abb0 to fd 5 
debug:tcti:src/util/io.c:108:write_all() wrote 20 bytes to fd 5 
trace:esys:src/tss2-esys/api/Esys_TestParms.c:225:Esys_TestParms_Finish() context=0x55d38ee604f0 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
debug:tcti:src/tss2-tcti/tcti-device.c:202:tcti_device_receive() Partial read - received header 
debug:tcti:src/tss2-tcti/tcti-device.c:215:tcti_device_receive() Partial read - received response size 10. 
trace:esys_crypto:src/tss2-esys/esys_crypto.c:34:iesys_crypto_hash_get_digest_size() call: hashAlg=11 size=0x7ffd2c953858 
trace:esys_crypto:src/tss2-esys/esys_crypto.c:59:iesys_crypto_hash_get_digest_size() return: *size=32 
trace:esys:src/tss2-esys/api/Esys_StartAuthSession.c:194:Esys_StartAuthSession_Async() context=0x55d38ee552d0, tpmKey=40418487, bind=40418487,nonceCaller=(nil), sessionType=00, symmetric=0x7ffd2c9539b2,authHash=000b 
trace:esys_crypto:src/tss2-esys/esys_crypto.c:34:iesys_crypto_hash_get_digest_size() call: hashAlg=11 size=0x7ffd2c952bd0 
trace:esys_crypto:src/tss2-esys/esys_crypto.c:59:iesys_crypto_hash_get_digest_size() return: *size=32 
debug:esys:src/tss2-esys/esys_iutil.c:525:iesys_compute_encrypted_salt() IESYS encrypted salt (size=256): 
0000: 8902bfb48d4841011b6d4f105400ba2a  .....HA..mO.T..*
0010: dc4a763e48182db21bdb15ef61527bff  .Jv>H.-.....aR{.
0020: eb62a07e744cc1d22ceb8bd7a108e427  .b.~tL..,......'
0030: 1b519593dae870260720153472628d51  .Q....p&...4rb.Q
0040: ece8c9f698d9ade29c5a7b550c208383  .........Z{U....
0050: 2bb909adfb42aff684042bb4dfa1a192  +....B....+.....
0060: 4f4c93be1a290de8a78e6cf7c949fde7  OL...)....l..I..
0070: 8db032b5e755e9c33023e81fc6b2f60c  ..2..U..0#......
0080: fe044233e75a88b939dd5bbb672fd6af  ..B3.Z..9.[.g/..
0090: facd6991c0d3683e9135a8fd96a15bba  ..i...h>.5....[.
00a0: f41d0ce9d6feda4e71d8aacc358169ff  .......Nq...5.i.
00b0: 7f57389c881e4a23f1df14fdac0ee092  .W8...J#........
00c0: 73d5bbaa9b8544030b063221c2a67f50  s.....D...2!...P
00d0: 950287d41f5d243ceba6e13f8d905cae  .....]$<...?..\.
00e0: b441c77cd22fb2d79c8268b600b03898  .A.|./....h...8.
00f0: 78940452a88966487cea9de75ee02108  x..R..fH|...^.!.
trace:esys_crypto:src/tss2-esys/esys_crypto.c:34:iesys_crypto_hash_get_digest_size() call: hashAlg=11 size=0x7ffd2c953060 
trace:esys_crypto:src/tss2-esys/esys_crypto.c:59:iesys_crypto_hash_get_digest_size() return: *size=32 
debug:tcti:src/tss2-tcti/tcti-device.c:116:tcti_device_transmit() sending 319 byte command buffer: (size=319): 
0000: 80010000013f0000017680ffffff80ff  .....?...v......
0010: ffff00204d283ec97387d29be7f6620f  ....M(>.s.....b.
0020: 223eb2bd417edfdd1010660875ceded5  ">..A~....f.u...
0030: 1b8eec6b01008902bfb48d4841011b6d  ...k.......HA..m
0040: 4f105400ba2adc4a763e48182db21bdb  O.T..*.Jv>H.-...
0050: 15ef61527bffeb62a07e744cc1d22ceb  ..aR{..b.~tL..,.
0060: 8bd7a108e4271b519593dae870260720  .....'.Q....p&..
0070: 153472628d51ece8c9f698d9ade29c5a  .4rb.Q.........Z
0080: 7b550c2083832bb909adfb42aff68404  {U....+....B....
0090: 2bb4dfa1a1924f4c93be1a290de8a78e  +.....OL...)....
00a0: 6cf7c949fde78db032b5e755e9c33023  l..I....2..U..0#
00b0: e81fc6b2f60cfe044233e75a88b939dd  ........B3.Z..9.
00c0: 5bbb672fd6affacd6991c0d3683e9135  [.g/....i...h>.5
00d0: a8fd96a15bbaf41d0ce9d6feda4e71d8  ....[........Nq.
00e0: aacc358169ff7f57389c881e4a23f1df  ..5.i..W8...J#..
00f0: 14fdac0ee09273d5bbaa9b8544030b06  ......s.....D...
0100: 3221c2a67f50950287d41f5d243ceba6  2!...P.....]$<..
0110: e13f8d905caeb441c77cd22fb2d79c82  .?..\..A.|./....
0120: 68b600b0389878940452a88966487cea  h...8.x..R..fH|.
0130: 9de75ee0210800000600800043000b    ..^.!.......C..
debug:tcti:src/util/io.c:97:write_all() writing 319 bytes starting at 0x55d38ee568e0 to fd 4 
debug:tcti:src/util/io.c:108:write_all() wrote 319 bytes to fd 4 
trace:esys:src/tss2-esys/api/Esys_StartAuthSession.c:326:Esys_StartAuthSession_Finish() context=0x55d38ee552d0, sessionHandle=0x7ffd2c9539ac 
debug:tcti:src/tss2-tcti/tcti-device.c:182:tcti_device_receive() Partial read - reading response size 
ERROR:tcti:src/tss2-tcti/tcti-device.c:198:tcti_device_receive() Failed to get response size fd 4, got errno 14: Bad address 
ERROR:esys:src/tss2-esys/api/Esys_StartAuthSession.c:395:Esys_StartAuthSession_Finish() Received a non-TPM Error 
ERROR:esys:src/tss2-esys/api/Esys_StartAuthSession.c:136:Esys_StartAuthSession() Esys Finish ErrorCode (0x000a000a) 
ERROR: Esys_StartAuthSession: tcti:IO failure
ERROR: Could not start Auth Session with the TPM.
ERROR: Error unsealing wrapping key
found token: 1
sign loop
SignInit failed: 5
trace:esys:src/tss2-esys/api/Esys_FlushContext.c:122:Esys_FlushContext_Async() context=0x55d38ee552d0, flushHandle=40418487 
ERROR:esys:src/tss2-esys/esys_iutil.c:1156:iesys_check_sequence_async() Esys called in bad sequence. 
ERROR:esys:src/tss2-esys/api/Esys_FlushContext.c:66:Esys_FlushContext() Error in async function ErrorCode (0x00070007) 
ERROR: Esys_FlushContext: esapi:Function called in the wrong order
sign operation failed after 0 success
/

[JuergenReppSIT]

Since the problem was fixed after tpm2 flushcontext --saved-session there seem to be to many active sessions. You can list them with: tpm2_getcap handles-saved-session or determine the max number with: tpm2_getcap properties-fixed| grep ACTIVE -A 1 But if this number is exceeded the error message should actually be: ERROR:esys:src/tss2-esys/api/Esys_StartAuthSession.c:136:Esys_StartAuthSession() Esys Finish ErrorCode (0x00000905) ERROR: Esys_StartAuthSession(0x905) - tpm:warn(2.0): out of session handles instead of an tcti error. If you could attach your example I could try to reproduce it. You could also check Chapter "30.5 Session Context Management" in the Architecture part of the TPM specification on this topic.

[nikolkam]

@JuergenReppSIT I don't think it's reaching a handle max limit as tpm2_getcap handles-saved-session only shows two handles 0x2000000 and 0x2000001 and the active session max is 64.

Below is the code I use to reproduce the bug. Please initialize a token with some private key for signing and set the PKCS11_LIB_PATH and TOKEN_LABEL in the code. Then start one process with ./<program_name> one and another with no argument. One will do one sign and wait indefinitely and another will perform sign loops until failure. It's quicker to reproduce on physical machines but also happens on my hyper-v ubuntu vm with tpm enabled after around 65k sign attempts. (10~20 min)

#include <cstdint>
#include <iostream>
#include <vector>
#include <cstring>
#include <dlfcn.h>
#include <string.h>
#include <future>
#include "pkcs11.h"

const char* PKCS11_LIB_PATH = "tpm2_pkcs11.so";
const char* TOKEN_LABEL = "token-name";

CK_FUNCTION_LIST_PTR p11;

// Initialize the PKCS11 library
bool init_pkcs11() {
    CK_RV rv;
    CK_C_GetFunctionList pGetFunctionList;
    void* pkcs11lib = dlopen(PKCS11_LIB_PATH, RTLD_LAZY);
    if (!pkcs11lib) {
        std::cerr << "Failed to load library." << std::endl;
        return false;
    }
    pGetFunctionList = (CK_C_GetFunctionList) dlsym(pkcs11lib, "C_GetFunctionList");
    if (!pGetFunctionList) {
        std::cerr << "Failed to get function list." << std::endl;
        return false;
    }
    rv = pGetFunctionList(&p11);
    if (rv != CKR_OK) {
        std::cerr << "Failed to initialize PKCS11. Error: " << rv << std::endl;
        return false;
    }
    rv = p11->C_Initialize(NULL);
    if (rv != CKR_OK) {
        std::cerr << "Error in C_Initialize: " << rv << std::endl;
        return false;
    }
    return true;
}

bool get_key(CK_SESSION_HANDLE *session, CK_OBJECT_HANDLE *key) {
    CK_RV rv;
    CK_SLOT_ID slot;
    CK_ULONG count;

    rv = p11->C_GetSlotList(CK_TRUE, NULL, &count);
    if (rv != CKR_OK || count <= 0) {
        std::cerr << "Failed to get slot list." << std::endl;
        return false;
    }

    std::vector<CK_SLOT_ID> slotList(count);
    rv = p11->C_GetSlotList(CK_TRUE, slotList.data(), &count);
    if (rv != CKR_OK) {
        std::cerr << "Failed to get slot list." << std::endl;
        return false;
    }

    bool foundToken = false;
    for (CK_ULONG i = 0; i < count; i++) {
        CK_TOKEN_INFO tokenInfo;
        rv = p11->C_GetTokenInfo(slotList[i], &tokenInfo);
        if (rv != CKR_OK) {
            printf("Failed to get token info: %lu\n", rv);
            return false;
        }

        if(strncmp(TOKEN_LABEL, reinterpret_cast<const char*>(tokenInfo.label), strlen(TOKEN_LABEL)) == 0) {
            slot = slotList[i];
            printf("found token: %lu\n", slot);
            foundToken = true;
        }
    }

    if (!foundToken) {
        printf("token not found\n");
        p11->C_CloseSession(*session);
        return false;
    }

    rv = p11->C_OpenSession(slot, CKF_SERIAL_SESSION | CKF_RW_SESSION, NULL, NULL, session);
    if (rv != CKR_OK) {
        printf("Failed to open session: %lu\n", rv);
        p11->C_CloseSession(*session);
        return false;
    }

    CK_OBJECT_CLASS keyClass = CKO_PRIVATE_KEY;
    CK_ATTRIBUTE keyTemplate[] = {
        {CKA_CLASS, &keyClass, sizeof(keyClass)}
    };

    rv = p11->C_FindObjectsInit(*session, keyTemplate, 1);
    if (rv != CKR_OK) {
        std::cerr << "FindObjectsInit failed." << std::endl;
        p11->C_CloseSession(*session);
        return false;
    }

    rv = p11->C_FindObjects(*session, key, 1, &count);
    if (rv != CKR_OK || count != 1) {
        std::cerr << "FindObjects failed." << std::endl;
        p11->C_CloseSession(*session);
        return false;
    }

    rv = p11->C_FindObjectsFinal(*session);
    if (rv != CKR_OK) {
        std::cerr << "FindObjectsFinal failed." << std::endl;
        p11->C_CloseSession(*session);
        return false;
    }

    return true;
}

// Function to keep signing a string
void signLoop() {
    CK_SESSION_HANDLE session;
    CK_OBJECT_HANDLE key;

    if (!get_key(&session, &key)) {
        return;
    }

    unsigned char data[] = "Hello World";
    unsigned char signature[256];
    CK_ULONG sigLen = sizeof(signature);

    printf("sign loop\n");
    uint64_t success = 0;
    CK_RV rv;
    while (true) {
        CK_MECHANISM mechanism = {CKM_RSA_PKCS, NULL_PTR, 0};
        rv = p11->C_SignInit(session, &mechanism, key);
        if (rv != CKR_OK) {
            std::cerr << "SignInit failed: "<<rv<< std::endl;
            break;
        }

        rv = p11->C_Sign(session, data, sizeof(data), signature, &sigLen);
        if (rv != CKR_OK) {
            std::cerr << "Sign operation failed: "<<rv<< std::endl;
            break;
        }

        success++;
        if (success % 1000 == 0) {
            printf("success: %lu\n", success);
        }
    }

    printf("sign operation failed after %lu success\n", success);

    p11->C_CloseSession(session);
}

// performs one sign operation and sleeps forever
void one_sign() {
    CK_SESSION_HANDLE session;
    CK_OBJECT_HANDLE key;

    if (!get_key(&session, &key)) {
        return;
    }

    CK_MECHANISM mechanism = {CKM_RSA_PKCS, NULL_PTR, 0};
    CK_RV rv = p11->C_SignInit(session, &mechanism, key);
    if (rv != CKR_OK) {
        std::cerr << "SignInit failed: "<<rv<< std::endl;
        return;
    }

    unsigned char data[] = "Hello World";
    unsigned char signature[256];
    CK_ULONG sigLen = sizeof(signature);
    rv = p11->C_Sign(session, data, sizeof(data), signature, &sigLen);
    if (rv != CKR_OK) {
        std::cerr << "Sign operation failed: "<<rv<< std::endl;
        return;
    }

    printf("sign ok\n");

    // sleep forever
    std::promise<void>().get_future().wait();
}

int main(int argc, char *argv[]) {
    if (!init_pkcs11()) {
        return 0;
    }

    if (argc > 1 && strcmp(argv[1], "one") == 0) {
        one_sign();
    } else {
        signLoop();
    }

    p11->C_Finalize(NULL);
    return 0;
}

[JuergenReppSIT]

@nikolkam Sorry I do not have the environment to compile your c++ application :-( I checked the tcti trace of Esys_StartAuthSession. The handle 0x80ffffff was used for the tpm key and the bind key. But transient last is defined as 0x80fffffe. Could you please attach the tcti part of your trace with the call of Esys_StartAuthSession which did not produce an error? Perhaps it would make sense to check the application with valgrind.

[JuergenReppSIT]

@nikolkam I can reproduce the tcti error if i call Tss2_Sys_StarAuthSession with the tpmKey and bind set to 0x80ffffff for an AMD firmware TPM and an Infineon SLB9670 TPM.

[JuergenReppSIT]

@nikolkam In the meantime I found the time to test your program with tpm2-tss and tpm2-pkcs11. I did use the master branches of both and the tpm2-abrmd resource manager. The error did not occur after about 65k signatures: success: 70000

[JuergenReppSIT]

@nikolkam If i use the kernel resource manager I also get tcti errors with your test example. But they occur quite quickly. The number of sign operations until the error does occur is different. Also the TPM command which causes the failure is not always StartAuthSession. This makes it look like it is a bug in the kernel resource manager (I did use 5.15.0).

[nikolkam]

@JuergenReppSIT
Thank you for taking a look into the issue. Just to make sure, when you use your kernel manger, are you testing on your physical machine? The number of sign operations seems to be different on different environments. On vm it takes me about 65k operations, but on physical machines I remember it was below 1k sign operations. Does the number of sign operation to get to fail state differ each time you execute the program? In our production code, we call tpm2 flushcontext --saved-session to workaround this issue when this happens. But since one of the program holding the tpm2 handle is a browser and we have no control over it, it results in failing browser's cert sign capability. If this issue looks like a lower level kernel issue which cannot be fixed with tpm2 library, do you have any suggestions or better way to work around this issue?

[JuergenReppSIT]

@nikolkam yes i did run the test on a physical machine. Perhaps a workaround could be to use the tpm2-abrmd resource manager (https://github.com/tpm2-software/tpm2-abrmd). Yes the number of sign operations did differ. I will try to create an example as simple as possible without the pkcs11 part to reproduce the error.

[JuergenReppSIT]

@nikolkam I must correct my previous comments.

• 0x80ffffff is a valid tpm handle produced by the resource manager. A tcti IO error occurs if such a handle is used but does not exist.
• With my test case with a physical tpm the tcti io error did always occur after 240 successful signing operations.

I tried to close the session after n successful operations an call get_key again. In this case the error occurred earlier the smallernwas. Did you run your tests with tpm2-abrmd?

[JuergenReppSIT]

@nikolkam The error 0x901 (TPM2_RC_CONTEXT_GAP) in the kernel resource manager did occur in the kernel function tpm2_save_context:

[ 401.923826] tpm tpm0: tpm2_save_context: failed with a TPM error 0x0901
[  401.925049] tpm tpm0: A TPM error (459) occurred flushing context

This error is not returned to tss. This error is described in the Architecture Part of the TPM Spec 30.4. There were no calls of ContextSave from tss. So it seems to be a problem of the kernel resource manager. The error also occurs in the kernel if tpm2-abrmd is used but tpm2-abrmd handles the error.

[nikolkam]

@JuergenReppSIT Sorry for the late reply, I tried to run sign loop test in the abrmd environment and it's working all good. Thank you for the help. Should this issue be reported somewhere else in that case?

[JuergenReppSIT]

@nikolkam Also sorry for late replay. I just sent an e-mail related to this problem to linux-integrity@vger.kernel.org