GDM login takes two minutes for U2F cue to appear on device after password entry

[Strykar]

What version of pam-u2f are you using?

pam-u2f 1.3.0

Official Extra repository on Arch Linux

What operating system are you using?

Arch

libfido2 1.14.0

What authenticator are you using?

$ fido2-token -I /dev/hidraw7
proto: 0x02
major: 0x01
minor: 0x00
build: 0x01
caps: 0x05 (wink, cbor, msg)
version strings: U2F_V2, FIDO_2_0, FIDO_2_1_PRE
extension strings: credBlob, credProtect, hmac-secret
transport strings: usb
algorithms: es256 (public-key), eddsa (public-key)
aaguid: e1a9618350164f24b55be3ae23614cc6
options: rk, up, uv, noplat, uvToken, credMgmt, bioEnroll, clientPin, platConfig, setMinPINLength, userVerificationMgmtPreview
fwversion: 0x1
maxmsgsiz: 2048
maxcredcntlst: 20
maxcredlen: 98
maxlargeblob: 1024
maxrpids in minpinlen: 10
minpinlen: 4
pin protocols: 1
pin retries: 7
pin change required: false
uv retries: 5
sensor type: 1 (touch)
max samples: 12

Problem description

When pam-u2f is configured with the device for 2FA with password, it takes two full minutes after entering the password for the device to ask me to touch it to authorize. I enabled debug and logged to a file, but there are no timestamps:

$ grep u2f /etc/pam.d/gdm-password 
auth  required  pam_u2f.so nouserok origin=pam://r912 appid=pam://r912 debug debug_file=/var/log/pam_u2f_gdm.log

$ cat /var/log/pam_u2f_gdm.log 
debug(pam_u2f): pam-u2f.c:95 (parse_cfg): called.
debug(pam_u2f): pam-u2f.c:96 (parse_cfg): flags 0 argc 5
debug(pam_u2f): pam-u2f.c:98 (parse_cfg): argv[0]=nouserok
debug(pam_u2f): pam-u2f.c:98 (parse_cfg): argv[1]=origin=pam://r912
debug(pam_u2f): pam-u2f.c:98 (parse_cfg): argv[2]=appid=pam://r912
debug(pam_u2f): pam-u2f.c:98 (parse_cfg): argv[3]=debug
debug(pam_u2f): pam-u2f.c:98 (parse_cfg): argv[4]=debug_file=/var/log/pam_u2f_gdm.log
debug(pam_u2f): pam-u2f.c:100 (parse_cfg): max_devices=0
debug(pam_u2f): pam-u2f.c:101 (parse_cfg): debug=1
debug(pam_u2f): pam-u2f.c:102 (parse_cfg): interactive=0
debug(pam_u2f): pam-u2f.c:103 (parse_cfg): cue=0
debug(pam_u2f): pam-u2f.c:104 (parse_cfg): nodetect=0
debug(pam_u2f): pam-u2f.c:105 (parse_cfg): userpresence=-1
debug(pam_u2f): pam-u2f.c:106 (parse_cfg): userverification=-1
debug(pam_u2f): pam-u2f.c:107 (parse_cfg): pinverification=-1
debug(pam_u2f): pam-u2f.c:108 (parse_cfg): manual=0
debug(pam_u2f): pam-u2f.c:109 (parse_cfg): nouserok=1
debug(pam_u2f): pam-u2f.c:110 (parse_cfg): openasuser=0
debug(pam_u2f): pam-u2f.c:111 (parse_cfg): alwaysok=0
debug(pam_u2f): pam-u2f.c:112 (parse_cfg): sshformat=0
debug(pam_u2f): pam-u2f.c:113 (parse_cfg): expand=0
debug(pam_u2f): pam-u2f.c:114 (parse_cfg): authfile=(null)
debug(pam_u2f): pam-u2f.c:115 (parse_cfg): authpending_file=(null)
debug(pam_u2f): pam-u2f.c:117 (parse_cfg): origin=pam://r912
debug(pam_u2f): pam-u2f.c:118 (parse_cfg): appid=pam://r912
debug(pam_u2f): pam-u2f.c:119 (parse_cfg): prompt=(null)
debug(pam_u2f): pam-u2f.c:227 (pam_sm_authenticate): Maximum devices number not set. Using default (24)
debug(pam_u2f): pam-u2f.c:250 (pam_sm_authenticate): Requesting authentication for user strykar
debug(pam_u2f): pam-u2f.c:261 (pam_sm_authenticate): Found user strykar
debug(pam_u2f): pam-u2f.c:262 (pam_sm_authenticate): Home directory for strykar is /home/strykar
debug(pam_u2f): pam-u2f.c:141 (resolve_authfile_path): Variable XDG_CONFIG_HOME is not set, using default
debug(pam_u2f): pam-u2f.c:288 (pam_sm_authenticate): Using authentication file /home/strykar/.config/Yubico/u2f_keys
debug(pam_u2f): pam-u2f.c:294 (pam_sm_authenticate): Dropping privileges
debug(pam_u2f): pam-u2f.c:300 (pam_sm_authenticate): Switched to uid 1000
debug(pam_u2f): util.c:227 (parse_native_format): Read 507 bytes
debug(pam_u2f): util.c:231 (parse_native_format): Matched user: strykar
debug(pam_u2f): util.c:254 (parse_native_format): KeyHandle for device number 1: XXXXX
debug(pam_u2f): util.c:256 (parse_native_format): publicKey for device number 1: XXXXX
debug(pam_u2f): util.c:258 (parse_native_format): COSE type for device number 1: es256
debug(pam_u2f): util.c:260 (parse_native_format): Attributes for device number 1: +presence
debug(pam_u2f): util.c:254 (parse_native_format): KeyHandle for device number 2: XXXXX
debug(pam_u2f): util.c:256 (parse_native_format): publicKey for device number 2: XXXXX
debug(pam_u2f): util.c:258 (parse_native_format): COSE type for device number 2: es256
debug(pam_u2f): util.c:260 (parse_native_format): Attributes for device number 2: +presence
debug(pam_u2f): util.c:753 (get_devices_from_authfile): Found 2 device(s) for user strykar
debug(pam_u2f): pam-u2f.c:310 (pam_sm_authenticate): Restored privileges
debug(pam_u2f): pam-u2f.c:360 (pam_sm_authenticate): Touch request notifications will be emitted via '/var/run/user/0/pam-u2f-authpending'
debug(pam_u2f): pam-u2f.c:369 (pam_sm_authenticate): Unable to emit 'authentication started' notification: No such file or directory
debug(pam_u2f): util.c:1172 (do_authentication): Device max index is 2
debug(pam_u2f): util.c:1188 (do_authentication): Attempting authentication with device number 1
debug(pam_u2f): util.c:991 (prepare_assert): Key handle: XXXXX
debug(pam_u2f): util.c:797 (get_authenticators): Working with 2 authenticator(s)
debug(pam_u2f): util.c:800 (get_authenticators): Checking whether key exists in authenticator 0
debug(pam_u2f): util.c:808 (get_authenticators): Authenticator path: /dev/hidraw3
debug(pam_u2f): util.c:835 (get_authenticators): Key not found in authenticator 0
debug(pam_u2f): util.c:800 (get_authenticators): Checking whether key exists in authenticator 1
debug(pam_u2f): util.c:808 (get_authenticators): Authenticator path: /dev/hidraw7
debug(pam_u2f): util.c:832 (get_authenticators): Found key in authenticator 1
debug(pam_u2f): pam-u2f.c:426 (pam_sm_authenticate): done. [Success]

Device is an AuthenTrend Technology Inc. ATKey.Pro
Should it be trying to emit via /var/run/user/0/pam-u2f-authpending instead of /var/run/user/1000/pam-u2f-authpending?
Is there a way to timestamp the debug log?

Any pointers to troubleshoot this would be much appreciated!

[Strykar]

So I setup a shell script that rewrote a copy of the debug log with timestamps and the delay does not appear to be in pam-u2f.

gdm-session-worker spends a full minute (snipped log) communicating to the U2F device before okaying login, is this normal?

Jan 10 04:19:04 r912 systemd[1]: Started User Login Management.
Jan 10 04:19:05 r912 systemd[1]: Starting GNOME Display Manager...

Jan 10 04:19:25 r912 gdm-session-worker[2437]: run_manifest: found 2 hid devices
Jan 10 04:19:25 r912 gdm-session-worker[2437]: fido_tx: dev=0x55eb11947fa0, cmd=0x06
Jan 10 04:19:25 r912 gdm-session-worker[2437]: fido_tx: buf=0x55eb11947fa0, len=8

Jan 10 04:20:32 r912 gdm-session-worker[2437]: fido_check_flags: up=2, uv=0
Jan 10 04:20:32 r912 gdm-session-worker[2437]: fido_get_signed_hash: cose_alg=-7
Jan 10 04:20:32 r912 gdm-password][2437]: pam_unix(gdm-password:session): session opened for user strykar(uid=1000) by strykar(uid=0)

Doesn't take that long at all when the same U2F device is used inside terminal / desktop applications.

[LDVG]

Hi,

Is there a way to timestamp the debug log?

Since gdm redirects all output to stderr to the journal, you could try to set debug_file=stderr (in this instance, debug_file=syslog also works but there are some quirks there).

gdm-session-worker spends a full minute (snipped log) communicating to the U2F device before okaying login, is this normal?

It certainly should not take that long, provided you've touched the device/provided user presence.

Jan 10 04:19:25 r912 gdm-session-worker[2437]: run_manifest: found 2 hid devices

libfido2 seems to think you have two authenticators plugged in to your machine. Is this correct?

After enumerating the authenticators, we try the first in the list (log annotated):

# CTAPHID_INIT
Jan 10 04:19:25 r912 gdm-session-worker[2437]: fido_tx: dev=0x55eb11947fa0, cmd=0x06
Jan 10 04:19:25 r912 gdm-session-worker[2437]: fido_tx: buf=0x55eb11947fa0, len=8
Jan 10 04:19:25 r912 gdm-session-worker[2437]: 0000: f8 18 5d 60 7c 74 ac ea
Jan 10 04:19:25 r912 gdm-session-worker[2437]: fido_rx: dev=0x55eb11947fa0, cmd=0x06, ms=-1
Jan 10 04:19:25 r912 gdm-session-worker[2437]: rx_preamble: buf=0x7ffc8ac9d230, len=64
Jan 10 04:19:25 r912 gdm-session-worker[2437]: rx: payload_len=17
Jan 10 04:19:25 r912 gdm-session-worker[2437]: fido_rx: buf=0x55eb11947fa8, len=17

# CTAPHID_CBOR, authenticatorGetInfo
Jan 10 04:19:25 r912 gdm-session-worker[2437]: fido_dev_get_cbor_info_tx: dev=0x55eb11947fa0
Jan 10 04:19:25 r912 gdm-session-worker[2437]: fido_tx: dev=0x55eb11947fa0, cmd=0x10
Jan 10 04:19:25 r912 gdm-session-worker[2437]: fido_tx: buf=0x7ffc8ac9d347, len=1
Jan 10 04:19:25 r912 gdm-session-worker[2437]: fido_dev_get_cbor_info_rx: dev=0x55eb11947fa0, ci=0x55eb119469e0, ms=-1
Jan 10 04:19:25 r912 gdm-session-worker[2437]: fido_rx: dev=0x55eb11947fa0, cmd=0x10, ms=-1
Jan 10 04:19:25 r912 gdm-session-worker[2437]: rx_preamble: buf=0x7ffc8ac9d200, len=64
Jan 10 04:19:25 r912 gdm-session-worker[2437]: rx: payload_len=75
Jan 10 04:19:25 r912 gdm-session-worker[2437]: rx: buf=0x7ffc8ac9d200, len=64
Jan 10 04:19:25 r912 gdm-session-worker[2437]: fido_rx: buf=0x55eb11945ed0, len=75
Jan 10 04:19:25 r912 gdm-session-worker[2437]: fido_dev_open_rx: FIDO_MAXMSG=2048, maxmsgsiz=0

# CTAPHID_CBOR, authenticatorGetAssertion
Jan 10 04:19:25 r912 gdm-session-worker[2437]: fido_tx: dev=0x55eb11947fa0, cmd=0x10
Jan 10 04:19:25 r912 gdm-session-worker[2437]: fido_tx: buf=0x55eb118fe6e0, len=175

# We start waiting for a response
Jan 10 04:19:25 r912 gdm-session-worker[2437]: fido_rx: dev=0x55eb11947fa0, cmd=0x10, ms=-1

# Authenticator takes a full minute to reply
Jan 10 04:20:25 r912 gdm-session-worker[2437]: rx_preamble: buf=0x7ffc8ac9d150, len=64
Jan 10 04:20:25 r912 gdm-session-worker[2437]: rx: payload_len=1
Jan 10 04:20:25 r912 gdm-session-worker[2437]: fido_rx: buf=0x55eb11945ed0, len=1

# Authenticator replies with CTAP2_ERR_OPERATION_DENIED
Jan 10 04:20:25 r912 gdm-session-worker[2437]: cbor_parse_reply: blob[0]=0x27
Jan 10 04:20:25 r912 gdm-session-worker[2437]: fido_dev_get_assert_rx: adjust_assert_count

Would you mind providing a log with the debug_file setting as provided above so that we get all output in one place and timestamped? It'd be additionally helpful to see the full payload as logged from libfido2 (feel free to use a second authfile containing dummy credentials registered for just this purpose).

Thanks!

[Strykar]

It certainly should not take that long, provided you've touched the device/provided user presence.

My observation is that any delay is only before the device starts flashing (asking me to touch it).
Once I confirm presence via touch, login is instant, no delays.

libfido2 seems to think you have two authenticators plugged in to your machine. Is this correct?

This is correct, I have another device which is also capable of U2F / FIDO.
I will try without the second device connected and also try relocating this current device to a USB port directly connected to the motherboard, currently its connected via a USB2 port provided by my keyboard's 2-port hub.

Would you mind providing a log with the debug_file setting as provided above

The only delay appears to be how long the FIDO conversation is taking, here's the full log.

[LDVG]

Thank you for the updates. This second log also suggests that this other device is taking a full minute to respond to the request. Does the problem persist if you unplug it entirely?

It appears to be returning CTAP2_ERR_OPERATION_DENIED for our so-called pre-flight request where we silently try to probe for the presence of the credential you're authenticating with. It seems to me that despite the UP=false setting, it's timing out while waiting for you to interact with it (given the repeatable nature of the seemingly exact one minute delay to the response).

Do you mind sharing the make and model of this second authenticator? fido2-token -I may also be useful.

[Strykar]

Thank you for your prompt responses.

UPDATE: Unplugging the second U2F device fixes the issue!

Login / presence is all instantaneous.
See new fast debug log.

I think the reason could be is that the second device cannot confirm presence unless unlocked via its own screen PIN.

$ fido2-token -L
/dev/hidraw12: vendor=0x1209, product=0x53c1 (SatoshiLabs TREZOR)
/dev/hidraw6: vendor=0x31bb, product=0x0622 (AuthenTrend Technology Inc. ATKey.Pro-01XXXXXXX)

$ fido2-token -I /dev/hidraw12
proto: 0x02
major: 0x02
minor: 0x00
build: 0x00
caps: 0x04 (nowink, cbor, msg)
version strings: U2F_V2, FIDO_2_0
extension strings: hmac-secret
aaguid: d6d0bdc362eec4dbde8d7a656e4a4487
options: rk, up, uv
fwversion: 0x0
maxmsgsiz: 0
maxcredcntlst: 10
maxcredlen: 1024
maxlargeblob: 0
pin protocols: 1
pin retries: undefined
pin change required: false
uv retries: undefined

The second device is a Trezor Model T, which I was hoping would function as a secondary U2F and could stay connected all the time.

How do I troubleshoot this issue now?

[LDVG]

If you are able, could you please test if this patch makes any difference:

diff --git a/util.c b/util.c
index f3ea20f..cb18e18 100644
--- a/util.c
+++ b/util.c
@@ -849,7 +849,7 @@ static int get_authenticators(const cfg_t *cfg, const fido_dev_info_t *devlist,
 
 static void init_opts(struct opts *opts) {
   opts->up = FIDO_OPT_FALSE;
-  opts->uv = FIDO_OPT_OMIT;
+  opts->uv = FIDO_OPT_FALSE;
   opts->pin = FIDO_OPT_FALSE;
 }
 

(Please take precautions to not lock yourself out of your system accidentally.)

[Strykar]

Sadly it does not, takes the same amount of time.
New util.c debug log.

Slightly unrelated, but if you have access to a YubiKey Bio, would you mind posting the options string from the output of fido2-token -I?

[LDVG]

Sadly it does not, takes the same amount of time.

Unfortunately, your authenticator does not appear to be behaving according to the specification and at this point there is little we can do to work around it. I'd open up a support ticket with the vendor to see if they either have the ability to update their firmware or otherwise configuring your authenticator to be compliant with the specification.

The alternative is to introduce an option to have the user touch the authenticator they wish to use when there's multiple ones plugged in (instead of using the pre-flight concept). Unfortunately, this would then always require at least two touches by the user if they have more than one authenticator plugged in: one to select the authenticator, one to actually authenticate.

(aside: the latter could potentially be worked around using threads to attempt authentication in parallel, but there's a lot of extra complexity that would come with that.)

Slightly unrelated, but if you have access to a YubiKey Bio, would you mind posting the options string from the output of fido2-token -I?

Not at hand at the moment, any particular feature you were wondering about?

[Strykar]

Unfortunately, your authenticator does not appear to be behaving according to the specification and at this point there is little we can do to work around it. I'd open up a support ticket with the vendor to see if they either have the ability to update their firmware or otherwise configuring your authenticator to be compliant with the specification.

Thank you for helping troubleshoot this, that was quick!!
To be clear, you are saying the issue is with the Trezor device correct?

Trezor is a mature open source hardware with source hosted at Github.
If you would please summarize in just a few words what your patch does and how it shows Trezor is non-compliant to which bits of the spec, it would help move this along a lot faster at Trezor's end.

Not at hand at the moment, any particular feature you were wondering about?

Not specifically, I was wondering if it had all or more than these listed by the ATKeyPro: options: rk, up, uv, noplat, uvToken, credMgmt, bioEnroll, clientPin, platConfig, setMinPINLength, userVerificationMgmtPreview?

I would've happily bought a Yubikey Bio, but that huge form factor does not work for my use case.
I sincerely hope Yubikey does a small side mounted fingerprint sensor like the ATKeyPro.

[LDVG]

To be clear, you are saying the issue is with the Trezor device correct?

Yes, there's little we can do to workaround this. While the CTAP 2.0 specification is not entirely straight-forward on the matter: I would expect a request which has set user presence (UP) to false and user verification (UV) to false to not require any user interaction. This pre-flight process is what pam-u2f uses to determine which authenticator to use before performing the actual authentication ceremony.

If you would please summarize in just a few words what your patch does and how it shows Trezor is non-compliant to which bits of the spec, it would help move this along a lot faster at Trezor's end.

The patch itself should probably not be necessary, I was just curious if the device would behave any different if UV=false was also set.

Not specifically, I was wondering if it had all or more than these listed by the ATKeyPro: options: rk, up, uv, noplat, uvToken, credMgmt, bioEnroll, clientPin, platConfig, setMinPINLength, userVerificationMgmtPreview?

I don't recognise platConfig (nor does the specification?), but the YubiKey Bio supports the others (or their CTAP 2.1 equivalents), and (from the top of my head) also largeBlobs.

I sincerely hope Yubikey does a small side mounted fingerprint sensor like the ATKeyPro.

I'll forward this for you.

Thanks.

[Strykar]

@LDVG I tested by unlocking the Trezor via its on-screen PIN during the bootloader / before OS boot. Again, there is no delay, its an issue of its behavior when the screen is locked and I will take it up with the Trezor folks.

One question regarding backup U2F keys that did pop up is; in spite of being unlocked, the Trezor never offered to touch / unlock via GDM, only the ATKey flashed. Both are added to Yubico's config attached to the same user on one line.
Is that the standard behavior if more than one key is plugged in?
Would the Trezor offer to auth if the ATKey were not plugged in?

[LDVG]

One question regarding backup U2F keys that did pop up is; in spite of being unlocked, the Trezor never offered to touch / unlock via GDM, only the ATKey flashed. Both are added to Yubico's config attached to the same user on one line.
Is that the standard behavior if more than one key is plugged in?
Would the Trezor offer to auth if the ATKey were not plugged in?

We test each credential in the authfile sequentially. You should be offered to authenticate with it if:

• the ATKey is unplugged; or
• you ignore the ATKey request for user presence and let it timeout.

But the behavior of the Trezor might require it to be unlocked for it to work (?).

I just recalled one additional detail of the config: You can disable the pre-flights using nodetect. In this case, pam-u2f will test all credentials with all authenticators plugged in, which is a bit less ergonomic but perhaps more usable for you.

[Strykar]

@LDVG Please take a minute to read the Trezor dev's comment - trezor/trezor-firmware#3486 (comment)

While I understand (and support) their motivation to not expose capabilities by default, the fact that it does not even indicate to the user at all that it is failing auth for a key it has is clearly out of spec and perhaps usability.

What is bewildering is this latest development, where I finally logged in to the Trezor once before GDM loaded, and since then, there is no lag, even if the Trezor is locked and connected. Almost as if u2f-pam or something is aware of its existence or unwillingness to auth by default. The secondary key lights up within seconds of entering the password now.
Here is the latest log.

What do you make of this? I have not even needed to try nodetect due to this unintentional fix?
Would you please point me to the code that would need to be rewritten to enable concurrent querying of devices?

[LDVG]

@LDVG Please take a minute to read the Trezor dev's comment - trezor/trezor-firmware#3486 (comment)

While I understand (and support) their motivation to not expose capabilities by default, the fact that it does not even indicate to the user at all that it is failing auth for a key it has is clearly out of spec and perhaps usability.

Thanks for letting me know.

What do you make of this? I have not even needed to try nodetect due to this unintentional fix?

There's sadly not much I can say about it, there's nothing magic in pam-u2f that keeps track of this. The "login"/"unlock" of the Trezor is entirely proprietary and a layer on top of all (?) of Trezor's applications, including the application governed by the CTAP specification.

Would you please point me to the code that would need to be rewritten to enable concurrent querying of devices?

Sure -- but like I mentioned previously: it's no trivial change, and riddled with other caveats.