timing problems

[eworm-de]

Hello everyone!

This drove me crazy for some time... I use pam_yubico to authenticate. Every now and then authentication fails. Enabling debug messages I get this:

[pam_yubico.c:parse_cfg(738)] called. [pam_yubico.c:parse_cfg(739)] flags 0 argc 2 [pam_yubico.c:parse_cfg(741)] argv[0]=mode=challenge-response [pam_yubico.c:parse_cfg(741)] argv[1]=debug [pam_yubico.c:parse_cfg(742)] id=-1 [pam_yubico.c:parse_cfg(743)] key=(null) [pam_yubico.c:parse_cfg(744)] debug=1 [pam_yubico.c:parse_cfg(745)] alwaysok=0 [pam_yubico.c:parse_cfg(746)] verbose_otp=0 [pam_yubico.c:parse_cfg(747)] try_first_pass=0 [pam_yubico.c:parse_cfg(748)] use_first_pass=0 [pam_yubico.c:parse_cfg(749)] authfile=(null) [pam_yubico.c:parse_cfg(750)] ldapserver=(null) [pam_yubico.c:parse_cfg(751)] ldap_uri=(null) [pam_yubico.c:parse_cfg(752)] ldapdn=(null) [pam_yubico.c:parse_cfg(753)] user_attr=(null) [pam_yubico.c:parse_cfg(754)] yubi_attr=(null) [pam_yubico.c:parse_cfg(755)] yubi_attr_prefix=(null) [pam_yubico.c:parse_cfg(756)] url=(null) [pam_yubico.c:parse_cfg(757)] capath=(null) [pam_yubico.c:parse_cfg(758)] token_id_length=12 [pam_yubico.c:parse_cfg(759)] mode=chresp [pam_yubico.c:parse_cfg(760)] chalresp_path=(null) [pam_yubico.c:pam_sm_authenticate(799)] get user returned: root [util.c:get_user_challenge_file(218)] Failed to read serial number (serial-api-visible disabled?). [pam_yubico.c:do_challenge_response(495)] Loading challenge from file /root/.yubico/challenge [pam_yubico.c:do_challenge_response(511)] Cannot open file: /root/.yubico/challenge (No such file or directory) [pam_yubico.c:do_challenge_response(657)] Yubikey core error: timeout [pam_yubico.c:do_challenge_response(666)] Challenge response failed: No such file or directory

I wrote some example code, you can grab it here: http://www.eworm.de/download/linux/yk_test.c

Just compile with: $ gcc -o yk_test yk_test.c -lykpers-1

Then run it: $ ./yk_test Serial number: 1234567 (0) Serial number: 1234567 (1) [...] Serial number: 1234567 (36) yk_get_serial failed

This runs in loop just reading and printing the serial number. Last number is just a counter.

Adding a usleep(10) in _ykusb_write() "fixes" the issue for me. Ok, it's more of a workaround: http://www.eworm.de/download/linux/yk_usleep.c

This should not be necessary and I have no idea why it happens. Looks like this is a race condition that only happens on fast systems (i7 Ivy Bridge here). Additionally a Yubikey Neo does not suffer the problem.

Any ideas?

[klali]

for completeness (or whatever) what version is the key (keys?) with problem?

/klas

[eworm-de]

I have two Yubico Black Firmware 2.3.3 that fail. Yubico Neo Firmware 3.1.2 is fine.

[eworm-de]

BTW, here is another report of the same problem: http://forum.yubico.com/viewtopic.php?f=23&t=1115

Searching for Dell Lattitude E6530 shows this is an i7 Ivy Bridge system as well.

[sh1v4]

Same problem here with a macbook pro (core i7) and yubikey nano used in challenge response mode both for login and screen unlock. The Yubikey appears to hang in random "timeout" errors even when it's repeatedly queried for version via ykinfo.

[klali]

@sh1v4 did you try this with the test programs @eworm-de pointed at? does his workaround work for you?

and I assume you run osX on that macbook? and if so, what is the exact error message?

/klas

[eworm-de]

Uh, I just noticed I posted a broken link in my comment above... Should have been: http://www.eworm.de/download/linux/yk_usleep.patch

I pushed a branch 'timing' to my forked project, that contains the fix as well.

For me it works perfectly reliable with the patch.

[klali]

So since I don't have hardware readily available to reproduce...

Did you track from what call the timeout is thrown when it happens? is it in _ykusb_write() or _ykusb_read() ? Did you try to increase the timeout (last parameter) on the libusb_control_transfer() call in the functions?

/klas

[eworm-de]

If I remember correctly the timeout happens in ykusbread(). Looks like Yubikey is still busy processing whatever ykusbwrite() told it to do.

I will have to check changing timeout in libusb_control_transfer(). To be honest I did not bother after I had a workaround.

[eworm-de]

No, increasing the timeout value in libusb_control_transfer() does not help. This is nanoseconds, no? Tried values up to 5000, nothing changed.

In contrast even a usleep(1) seems to be sufficient to fix the problem.

Just curious.... yk_wait_for_key_status() is called before reading the answer from Yubikey. I would expect it to report the key is not ready yet, delaying the read.

[klali]

yeah.. the timeout error is returned from yk_wait_for_key_status() if the yubikey doesn't trigger the expected result in time..

If you're familiar enough with gdb it'd be helpful with a stacktrace from a break at end of yk_wait_for_key_status() function.

/klas

[eworm-de]

Thanks a lot!

[klali]

So to give some more context here..

Apparently the YubiKey might need a couple of hundred microseconds to get itself sorted on a write. Traditionally (I have no idea what timeframe I'm talking about here, but 2007-2008 is reasonable) a computer pushed about 1 usb packet every millisecond, with a newer computer we're seeing something on the order of 3 packets every millisecond. So the host needs to a wait bit after each write.