Credential generation and assertion is blocking till timeout

[VedaviBalaji]

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.

[LDVG]

Hi,

libfido2 should not make you wait for the timeout to be reached. You should receive the response as soon as the authenticator has replied. Note that we do not communicate the timeout to the authenticator. May I ask a) what version of libfido2 you're using; b) what operating system you're using; and c) what authenticator you're using (fido2-token -I may be helpful)? Additionally, are there any particular circumstances in which you see this behavior more often than others?

Thanks.

[VedaviBalaji]

If I am not wrong, I think this is where the wait seems to happen https://github.com/Yubico/libfido2/blob/main/src/io.c#L191.
Which in turn points to

libfido2/src/hid_hidapi.c

Line 211 in de45438

return hid_read_timeout(ctx->handle, buf, len, ms);

. The timeout is sent to this hid API and it looks like only last few transaction response is taking time.

[LDVG]

Wrt to circumstances, I am not entirely sure what happens but when it does happen

Can you reproduce this issue by running our assert example?

$ fido2-token -L
/dev/hidraw7: vendor=0x1050, product=0x0406 (Yubico YubiKey FIDO+CCID)
$ ./cred -k pubkey -i cred_id /dev/hidraw7
$ FIDO_DEBUG=1 ./assert -T 20 -a cred_id pubkey /dev/hidraw7
...

usually there is a "typing" sound from the authenticator, almost like an input.

Could you elaborate on this? When does this happen? What is making the sound? (The YubiKey should have no means to do so.)

Which in turn points to libfido2/src/hid_hidapi.c

Have you built libfido2 yourself from source? The HIDAPI backend is normally not used on MacOS, see instead

libfido2/src/hid_osx.c

Line 546 in de45438

CFRunLoopRunInMode(ctx->loop_id, (double)ms/1000.0, true);

[VedaviBalaji]

It does not happen consistently, so I am not able to reproduce it readily. However, I was able to repro it and get libfido2 logs. Essentially, I added few logs to the source and found that the CFRunLoopInMode is the one not returning properly. Here are the device and logs

 20:41:39.847   - TEST: rx_frame before io.read
 20:41:39.847   - TEST: Before CFRunLoopRunInMode: device: YubiKey OTP+FIDO+CCID
 20:41:39.847   - TEST: Before CFRunLoopRunInMode: ms 18131
 20:41:39.849   - TEST: After CFRunLoopRunInMode result 4
 20:41:39.849   - TEST: rx_frame after io.read
 20:41:39.849   - rx: buf=0x70000838cdf8, len=64
 20:41:39.849   - 0000: 2a 49 d8 f2 0e 7c dc f2 5d af e5 be 4d b0 8e 96
 20:41:39.849   - 0016: 9d 7f 1e 4e b7 e1 de fc 31 83 62 6a 8f 3f 4a f3
 20:41:39.849   - 0032: 33 cc c0 20 4c f4 05 6e b8 fb 3c 70 ae 6d 91 ac
 20:41:39.849   - 0048: 8a 56 c9 17 cc 0a ef ae 00 e2 09 70 42 7d c1 d2
 20:41:39.849   - TEST: rx_frame before io.read
 20:41:39.849   - TEST: Before CFRunLoopRunInMode: device: YubiKey OTP+FIDO+CCID
 20:41:39.850   - TEST: Before CFRunLoopRunInMode: ms 18130
 20:41:57.981   - TEST: After CFRunLoopRunInMode result 3
 20:41:57.981   - TEST: rx_frame after io.read
 20:41:57.981   - rx: buf=0x70000838cdf8, len=64
 20:41:57.981   - 0000: 2a 49 d8 f2 0f da 65 bb a1 23 78 7f ab 35 32 11
 20:41:57.982   - 0016: 20 a7 e1 b1 8f 9d 7e 91 27 20 31 2b fa 4b 2e 15
 20:41:57.982   - 0032: 03 2d 18 2f fb 84 03 28 23 73 a3 77 ec 2c 2a 1a
 20:41:57.982   - 0048: 2f 93 1c 82 15 dc ac 28 9b 2d 89 72 8e 2c b8 d6

See attached file for full logs.
TouchResponseDelayLog.txt

[LDVG]

We believe to have been able to reproduce your issue and have a potential fix. Would you be able to test if #762 solves your issue? Thanks!

FYI: I opened #763 to track this bug.

[VedaviBalaji]

Hello, the fix seems to be working, I am unable to reproduce it after trying it couple of times.

[VedaviBalaji]

I have another qs -

• can fido_dev_cancel be called from different thread to cancel the make_cred and get_assert calls? I see in this discussion that it may lead to undefined behavior, if that still holds true for both fido2 and u2f devices, is there any way to cancel if user decides to not proceed with the operation?

[LDVG]

Hello, the fix seems to be working, I am unable to reproduce it after trying it couple of times.

Thank you for checking.

can fido_dev_cancel be called from different thread to cancel the make_cred and get_assert calls?

No, the discussion in #637 is still relevant. The only safe way is described there. For MacOS, also see the discussion in #650.

For the future, please try to have one topic per discussion: this helps other users more easily discover solutions to questions that have already been answered.