Credential generation and assertion is blocking till timeout
LDVG opened this issue · 0 comments
LDVG commented
Discussed in #757
Originally posted by VedaviBalaji December 15, 2023
I am having this issue where the fido_dev_make_cred and fido_dev_get_assert sometimes waits till timeout to return. I looked at the DEBG log and there is no transaction for ~timeout secs but it returns a success. This however only happens sometimes but most of the time the call returns after the user touches the key.
I set the timeout right before I call the assert or make-cred.
libfido2::fido_dev_set_timeout(device, 20000);
libfido2::fido_dev_get_assert(device, assert, pin);
FIDO_DEBUG=1
14:07:32.928 fido_dev_authkey_tx: dev=0x60000177e9a0
14:07:32.928 fido_tx: dev=0x60000177e9a0, cmd=0x10
14:07:32.928 fido_tx: buf=0x6000126745e0, len=6
14:07:32.928 0000: 06 a2 01 02 02 02
14:07:32.930 fido_dev_authkey_rx: dev=0x60000177e9a0, authkey=0x600003087d40, ms=19998
14:07:32.930 fido_rx: dev=0x60000177e9a0, cmd=0x10, ms=19998
14:07:32.932 rx_preamble: buf=0x30aa61fd0, len=64
14:07:32.932 0000: f5 15 a6 1d 90 00 51 00 a1 01 a5 01 02 03 38 18
14:07:32.932 0016: 20 01 21 58 20 41 00 5a 6e 82 ca 89 4f 81 96 1b
14:07:32.932 0032: 1e 69 c7 56 fb 39 65 6e 88 81 63 7c d5 01 96 c3
14:07:32.932 0048: 90 33 27 b3 a0 22 58 20 46 c9 8c 6e 5e f9 bd e3
14:07:32.932 rx: payload_len=81
14:07:32.934 rx: buf=0x30aa61fd0, len=64
14:07:32.934 0000: f5 15 a6 1d 00 7f 61 27 98 56 dd e3 c8 7e e6 40
14:07:32.934 0016: 0e 87 a3 5a 6f fb 71 b8 2d 60 73 ee 1e 00 00 00
14:07:32.934 0032: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
14:07:32.934 0048: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
14:07:32.934 fido_rx: buf=0x7ff3bcf45800, len=81
14:07:32.934 0000: 00 a1 01 a5 01 02 03 38 18 20 01 21 58 20 41 00
14:07:32.934 0016: 5a 6e 82 ca 89 4f 81 96 1b 1e 69 c7 56 fb 39 65
14:07:32.934 0032: 6e 88 81 63 7c d5 01 96 c3 90 33 27 b3 a0 22 58
14:07:32.934 0048: 20 46 c9 8c 6e 5e f9 bd e3 7f 61 27 98 56 dd e3
14:07:32.934 0064: c8 7e e6 40 0e 87 a3 5a 6f fb 71 b8 2d 60 73 ee
14:07:32.935 0080: 1e
14:07:32.935 fido_tx: dev=0x60000177e9a0, cmd=0x10
14:07:32.935 fido_tx: buf=0x600000bb2b80, len=120
14:07:32.935 0000: 06 a4 01 02 02 05 03 a5 01 02 03 38 18 20 01 21
14:07:32.935 0016: 58 20 f3 f8 85 28 af 60 79 46 c3 8e c4 ef c8 5a
14:07:32.936 0032: 18 ac 64 99 c5 f7 2b eb 54 9f 18 0a 86 69 95 1a
14:07:32.936 0048: 72 68 22 58 20 a7 83 91 fa af 7f 42 87 45 80 f9
14:07:32.936 0064: 58 96 b6 d4 31 61 9b 72 16 1b 65 c0 5c ce 36 19
14:07:32.936 0080: fe 2c a9 ba 94 06 58 20 8f 09 23 e2 e3 2d c8 ae
14:07:32.936 0096: dd f1 a6 eb a7 12 09 71 8a 46 6b 44 14 c1 37 3c
14:07:32.936 0112: ed 1d c3 56 f3 86 9b 52
14:07:32.942 fido_rx: dev=0x60000177e9a0, cmd=0x10, ms=19992
14:07:33.020 rx_preamble: buf=0x30aa61f70, len=64
14:07:33.020 0000: f5 15 a6 1d 90 00 35 00 a1 02 58 30 6c bd a0 61
14:07:33.020 0016: a4 12 81 05 a6 cf 80 8b 10 dc eb 60 af e2 0a 3a
14:07:33.020 0032: 36 0f 70 09 25 88 33 43 0a 92 10 bc aa f8 52 ce
14:07:33.020 0048: b0 4b fe c4 50 2c b5 12 a0 ac ee 58 00 00 00 00
14:07:33.020 rx: payload_len=53
14:07:33.021 fido_rx: buf=0x7ff34d09b000, len=53
14:07:33.021 0000: 00 a1 02 58 30 6c bd a0 61 a4 12 81 05 a6 cf 80
14:07:33.021 0016: 8b 10 dc eb 60 af e2 0a 3a 36 0f 70 09 25 88 33
14:07:33.021 0032: 43 0a 92 10 bc aa f8 52 ce b0 4b fe c4 50 2c b5
14:07:33.021 0048: 12 a0 ac ee 58
14:07:33.021 fido_tx: dev=0x60000177e9a0, cmd=0x10
14:07:33.021 fido_tx: buf=0x7ff35d7681e0, len=357
14:07:33.021 0000: 02 a5 01 75 64 65 76 2d 30 30 38 30 32 30 39 37
14:07:33.021 0016: 2e 6f 6b 74 61 2e 63 6f 6d 02 58 20 65 ca 13 e1
14:07:33.021 0032: d3 5c 72 41 cc be 59 b5 fc 65 2d fa a9 c6 78 f5
14:07:33.021 0048: ec fd 7a 44 04 b1 6d c7 a7 76 75 28 03 83 a2 62
14:07:33.021 0064: 69 64 58 40 33 58 4b e2 86 83 4b 37 b7 09 0a f9
14:07:33.022 0080: a8 21 72 74 20 30 3d 7d 80 b6 e8 6f bb 61 ef 3c
14:07:33.022 0096: f5 f9 61 e1 be c5 56 07 bf 6d 52 f5 4b 6e 27 08
14:07:33.022 0112: 87 0b b4 d7 7f c5 a9 77 a1 f8 42 95 f4 8d a8 86
14:07:33.022 0128: ed 41 36 0e 64 74 79 70 65 6a 70 75 62 6c 69 63
14:07:33.022 0144: 2d 6b 65 79 a2 62 69 64 58 40 4e 19 65 cc dd 88
14:07:33.022 0160: 5a b9 bd 31 d9 a0 42 ca 22 82 b8 72 9f d3 30 7e
14:07:33.022 0176: 24 d4 51 85 e0 ce e3 6e 00 ff 7f f6 6f fe 38 92
14:07:33.022 0192: 3a ec c6 54 73 5e 61 c6 50 d3 a6 fc a6 9b 92 d4
14:07:33.022 0208: 59 a0 17 56 6c 71 08 93 5f 49 64 74 79 70 65 6a
14:07:33.022 0224: 70 75 62 6c 69 63 2d 6b 65 79 a2 62 69 64 58 40
14:07:33.022 0240: 7f 81 3d d7 c3 e0 0e 5f 3a 12 67 b2 90 3a 7e e4
14:07:33.022 0256: b3 0e 98 79 1f c9 17 66 6d 14 14 18 64 2d 1d a2
14:07:33.022 0272: 89 b5 9b af 4b 70 8c 8a b5 77 3c d2 c0 71 a1 6a
14:07:33.022 0288: 3e 33 cc c1 d3 69 2a 46 52 74 83 55 bc 91 b7 fa
14:07:33.022 0304: 64 74 79 70 65 6a 70 75 62 6c 69 63 2d 6b 65 79
14:07:33.022 0320: 06 58 20 b5 d9 3b 35 e7 db 10 91 2a dc 91 66 98
14:07:33.023 0336: 31 e2 e9 92 78 24 8e 4d 89 d6 2e 37 03 06 f5 6b
14:07:33.023 0352: 0b 8f 5b 07 02
14:07:33.036 fido_rx: dev=0x60000177e9a0, cmd=0x10, ms=19906
14:07:33.730 rx_preamble: buf=0x30aa620c0, len=64
14:07:33.731 0000: f5 15 a6 1d 90 00 cb 00 a3 01 a2 62 69 64 58 40
14:07:33.731 0016: 4e 19 65 cc dd 88 5a b9 bd 31 d9 a0 42 ca 22 82
14:07:33.731 0032: b8 72 9f d3 30 7e 24 d4 51 85 e0 ce e3 6e 00 ff
14:07:33.731 0048: 7f f6 6f fe 38 92 3a ec c6 54 73 5e 61 c6 50 d3
14:07:33.731 rx: payload_len=203
14:07:33.734 rx: buf=0x30aa620c0, len=64
14:07:33.736 0000: f5 15 a6 1d 00 a6 fc a6 9b 92 d4 59 a0 17 56 6c
14:07:33.736 0016: 71 08 93 5f 49 64 74 79 70 65 6a 70 75 62 6c 69
14:07:33.737 0032: 63 2d 6b 65 79 02 58 25 e8 4f 1c 50 42 51 69 ea
14:07:33.737 0048: 3f 8a 05 b6 12 3f b0 68 67 19 f0 b1 05 9c 6f 28
14:07:33.737 rx: buf=0x30aa620c0, len=64
14:07:33.737 0000: f5 15 a6 1d 01 f0 e7 ab 32 31 79 1a 64 05 00 00
14:07:33.737 0016: 00 0a 03 58 47 30 45 02 21 00 bb 53 1b 0f 02 da
14:07:33.738 0032: 4c 39 ed 97 31 ea 99 d4 93 d2 92 50 e5 ee ae 19
14:07:33.738 0048: 3a 84 ac ca 24 d1 94 49 95 de 02 20 53 02 75 bf
14:07:52.950 rx: buf=0x30aa620c0, len=64
14:07:52.951 0000: f5 15 a6 1d 02 5a a8 39 88 39 7c ab 7e 6f 97 4b
14:07:52.951 0016: d2 23 db ce 88 ed 76 8b f4 7b b3 5b 45 48 46 dd
14:07:52.951 0032: bb 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
14:07:52.952 0048: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
14:07:52.952 fido_rx: buf=0x7ff3bbadd200, len=203
14:07:52.952 0000: 00 a3 01 a2 62 69 64 58 40 4e 19 65 cc dd 88 5a
14:07:52.952 0016: b9 bd 31 d9 a0 42 ca 22 82 b8 72 9f d3 30 7e 24
14:07:52.953 0032: d4 51 85 e0 ce e3 6e 00 ff 7f f6 6f fe 38 92 3a
14:07:52.953 0048: ec c6 54 73 5e 61 c6 50 d3 a6 fc a6 9b 92 d4 59
14:07:52.953 0064: a0 17 56 6c 71 08 93 5f 49 64 74 79 70 65 6a 70
14:07:52.953 0080: 75 62 6c 69 63 2d 6b 65 79 02 58 25 e8 4f 1c 50
14:07:52.953 0096: 42 51 69 ea 3f 8a 05 b6 12 3f b0 68 67 19 f0 b1
14:07:52.954 0112: 05 9c 6f 28 f0 e7 ab 32 31 79 1a 64 05 00 00 00
14:07:52.954 0128: 0a 03 58 47 30 45 02 21 00 bb 53 1b 0f 02 da 4c
14:07:52.954 0144: 39 ed 97 31 ea 99 d4 93 d2 92 50 e5 ee ae 19 3a
14:07:52.954 0160: 84 ac ca 24 d1 94 49 95 de 02 20 53 02 75 bf 5a
14:07:52.954 0176: a8 39 88 39 7c ab 7e 6f 97 4b d2 23 db ce 88 ed
14:07:52.954 0192: 76 8b f4 7b b3 5b 45 48 46 dd bb
14:07:52.954 adjust_assert_count: cbor_type
14:07:52.954 adjust_assert_count: cbor_type
14:07:52.954 adjust_assert_count: cbor_type
14:07:52.954 cbor_decode_assert_authdata: buf=0x600002ae8180, len=37
You can see that there is no transaction for around 20 secs here. I believe the rx means response, and the authenticator takes around 19+secs to respond to the user touch.
_14:07:33.738_ 0048: 3a 84 ac ca 24 d1 94 49 95 de 02 20 53 02 75 bf
_14:07:52.950_ rx: buf=0x30aa620c0, len=64
Is there a reason why it sometimes blocks for the entire timeout for it to respond? I haven't checked what happens if no timeout is given however, my use case needs the timeout to prevent the calls from blocking indefinitely.