Security key option available for user, but always fail with a 500
Describe the bug When testing the MFA option, i tried to register my Yubikey, i get a prompt and touch the key, but then get a none-descriptive "Error has occurred". In the core log, i can see the following.
Webauthn registration error: The user verified bit is not set, and required by policy
A quick google search show that this is a generic error with the library your are using, and doesn't look to me something actionable on our side.
Your documentation currently doesn't talk about Security key in the MFA section : https://docs.defguard.net/admin-and-features/features-and-configuration/wireguard/multi-factor-authentication-mfa-2fa
Note that this happened before and after adding another type of MFA
To Reproduce Steps to reproduce the behavior:
- Install the latest version of core and proxy
- Create a user
- Go through enrollment
- Connect with that user to the core
- Edit the user profile and try to add a Security key
Expected behavior The Security key is added OR the option is not present
Version information
- Defguard Core version: v1.1.0
- Your browser and version [e.g. chrome 99, safari]: Firefox 132.0.1
Screenshots If applicable, add screenshots to help explain your problem.
Additional context Add any other context about the problem here.
@Vaarlion could you change your core log level to debug (DEFGUARD_LOG_LEVEL=debug for example in docker env) and do the registration of the key again and paste the logs? Thank you!
Here is the log in debug when trying to add a security key
nov. 26 17:36:15 SERVER-01 defguard[9430]: 2024-11-26T16:36:15.852586Z DEBUG http_request{method=POST path=/api/v1/auth/webauthn/finish}: tower_http::trace::on_request: started processing request
nov. 26 17:36:15 SERVER-01 defguard[9430]: 2024-11-26T16:36:15.853436Z DEBUG http_request{method=POST path=/api/v1/auth/webauthn/finish}: sqlx::query: summary="SELECT id, user_id, state …" db.statement="\n\nSELECT\n id,\n user_id,\n state \"state: SessionState\",\n created,\n expires,\n webauthn_challenge,\n web3_challenge,\n ip_address,\n device_info\nFROM\n session\nWHERE\n id = $1\n" rows_affected=0 rows_returned=1 elapsed=269.723µs elapsed_secs=0.000269723
nov. 26 17:36:15 SERVER-01 defguard[9430]: 2024-11-26T16:36:15.854081Z DEBUG http_request{method=POST path=/api/v1/auth/webauthn/finish}: sqlx::query: summary="SELECT id, \"username\",\"password_hash\",\"last_name\",\"first_name\",\"email\",\"phone\",\"mfa_enabled\",\"is_active\",\"openid_sub\",\"totp_enabled\",\"email_mfa_enabled\",\"totp_secret\",\"email_mfa_secret\",\"mfa_method\" \"mfa_method: …" db.statement="\n\nSELECT\n id,\n \"username\",\n \"password_hash\",\n \"last_name\",\n \"first_name\",\n \"email\",\n \"phone\",\n \"mfa_enabled\",\n \"is_active\",\n \"openid_sub\",\n \"totp_enabled\",\n \"email_mfa_enabled\",\n \"totp_secret\",\n \"email_mfa_secret\",\n \"mfa_method\" \"mfa_method: _\",\n \"recovery_codes\" \"recovery_codes: _\"\nFROM\n \"user\"\nWHERE\n id = $1\n" rows_affected=0 rows_returned=1 elapsed=202.225µs elapsed_secs=0.000202225
nov. 26 17:36:15 SERVER-01 defguard[9430]: 2024-11-26T16:36:15.854667Z DEBUG http_request{method=POST path=/api/v1/auth/webauthn/finish}: sqlx::query: summary="SELECT id, name FROM …" db.statement="\n\nSELECT\n id,\n name\nFROM\n \"group\"\n JOIN group_user ON \"group\".id = group_user.group_id\nWHERE\n group_user.user_id = $1\n" rows_affected=0 rows_returned=0 elapsed=363.411µs elapsed_secs=0.000363411
nov. 26 17:36:15 SERVER-01 defguard[9430]: 2024-11-26T16:36:15.854844Z INFO http_request{method=POST path=/api/v1/auth/webauthn/finish}: defguard::handlers::auth: Finishing WebAuthn registration for user user01
nov. 26 17:36:15 SERVER-01 defguard[9430]: 2024-11-26T16:36:15.854969Z INFO http_request{method=POST path=/api/v1/auth/webauthn/finish}: defguard::handlers::auth: Passkey registration request origin: https://defguard-exp.domain.com/
nov. 26 17:36:15 SERVER-01 defguard[9430]: 2024-11-26T16:36:15.854976Z INFO http_request{method=POST path=/api/v1/auth/webauthn/finish}: defguard::handlers::auth: Allowed origins: ["https://defguard-exp.domain.com/"]
nov. 26 17:36:15 SERVER-01 defguard[9430]: 2024-11-26T16:36:15.855302Z ERROR http_request{method=POST path=/api/v1/auth/webauthn/finish}: defguard::handlers: Webauthn registration error: The user verified bit is not set, and required by policy
nov. 26 17:36:15 SERVER-01 defguard[9430]: 2024-11-26T16:36:15.855352Z INFO http_request{method=POST path=/api/v1/auth/webauthn/finish}: tower_http::trace::on_response: finished processing request latency=2 ms status=500
nov. 26 17:36:15 SERVER-01 defguard[9430]: 2024-11-26T16:36:15.855384Z ERROR http_request{method=POST path=/api/v1/auth/webauthn/finish}: tower_http::trace::on_failure: response failed classification=Status code: 500 Internal Server Error latency=2 ms
@Vaarlion does the domain actually exist and is Defguard reachable under this domain? (Meaning you actually enter in the browser: defguard-exp.domain.com)?
If you are registering a key and the domain which is in the config is not the same you enter in the browser - the registration will not work.
The domain must be set in: DEFGUARD_URL and DEFGUARD_WEBAUTHN_RP_ID
does the domain actually exist and is Defguard reachable under this domain
yes, the log have been anonymized but the domain, is reachable using a valid public https cert.
The domain must be set in: DEFGUARD_URL and DEFGUARD_WEBAUTHN_RP_ID
DEFGUARD_URL is set to the correct domain
DEFGUARD_WEBAUTHN_RP_ID is unset, but the config template say : # Optional. Generated based on DEFGUARD_URL if not provided.
I've added it to my domain without https:// and restarted, but sadly i forgot my token (and coffee badge :scream: ) at home today ... can't test it.
@Vaarlion ok thank you for your help an logs. we're going to take this to our ,workshop' and straighten this out! Have a good day!
Just FYI, adding DEFGUARD_WEBAUTHN_RP_ID did not fix this issue.
I could test again this morning
nov. 28 11:15:44 atexo-defguard-exp-infra-01 defguard[25870]: 2024-11-28T10:15:44.430882Z DEBUG http_request{method=POST path=/api/v1/auth/webauthn/init}: tower_http::trace::on_request: started processing request
nov. 28 11:15:44 atexo-defguard-exp-infra-01 defguard[25870]: 2024-11-28T10:15:44.431852Z DEBUG http_request{method=POST path=/api/v1/auth/webauthn/init}: sqlx::query: summary="SELECT id, user_id, state …" db.statement="\n\nSELECT\n id,\n user_id,\n state \"state: SessionState\",\n created,\n expires,\n webauthn_challenge,\n web3_challenge,\n ip_address,\n device_info\nFROM\n session\nWHERE\n id = $1\n" rows_affected=0 rows_returned=1 elapsed=262.213µs elapsed_secs=0.000262213
nov. 28 11:15:44 atexo-defguard-exp-infra-01 defguard[25870]: 2024-11-28T10:15:44.432360Z DEBUG http_request{method=POST path=/api/v1/auth/webauthn/init}: sqlx::query: summary="SELECT id, \"username\",\"password_hash\",\"last_name\",\"first_name\",\"email\",\"phone\",\"mfa_enabled\",\"is_active\",\"openid_sub\",\"totp_enabled\",\"email_mfa_enabled\",\"totp_secret\",\"email_mfa_secret\",\"mfa_method\" \"mfa_method: …" db.statement="\n\nSELECT\n id,\n \"username\",\n \"password_hash\",\n \"last_name\",\n \"first_name\",\n \"email\",\n \"phone\",\n \"mfa_enabled\",\n \"is_active\",\n \"openid_sub\",\n \"totp_enabled\",\n \"email_mfa_enabled\",\n \"totp_secret\",\n \"email_mfa_secret\",\n \"mfa_method\" \"mfa_method: _\",\n \"recovery_codes\" \"recovery_codes: _\"\nFROM\n \"user\"\nWHERE\n id = $1\n" rows_affected=0 rows_returned=1 elapsed=211.215µs elapsed_secs=0.000211215
nov. 28 11:15:44 atexo-defguard-exp-infra-01 defguard[25870]: 2024-11-28T10:15:44.433028Z DEBUG http_request{method=POST path=/api/v1/auth/webauthn/init}: sqlx::query: summary="SELECT id, name FROM …" db.statement="\n\nSELECT\n id,\n name\nFROM\n \"group\"\n JOIN group_user ON \"group\".id = group_user.group_id\nWHERE\n group_user.user_id = $1\n" rows_affected=0 rows_returned=0 elapsed=240.971µs elapsed_secs=0.000240971
nov. 28 11:15:44 atexo-defguard-exp-infra-01 defguard[25870]: 2024-11-28T10:15:44.433148Z INFO http_request{method=POST path=/api/v1/auth/webauthn/init}: defguard::handlers::auth: Initializing WebAuthn registration for user user1
nov. 28 11:15:44 atexo-defguard-exp-infra-01 defguard[25870]: 2024-11-28T10:15:44.433697Z DEBUG http_request{method=POST path=/api/v1/auth/webauthn/init}: sqlx::query: summary="SELECT passkey FROM webauthn …" db.statement="\n\nSELECT\n passkey\nFROM\n webauthn\nWHERE\n user_id = $1\n" rows_affected=0 rows_returned=0 elapsed=370.592µs elapsed_secs=0.000370592
nov. 28 11:15:44 atexo-defguard-exp-infra-01 defguard[25870]: 2024-11-28T10:15:44.436169Z DEBUG http_request{method=POST path=/api/v1/auth/webauthn/init}: sqlx::query: summary="UPDATE session SET webauthn_challenge …" db.statement="\n\nUPDATE\n session\nSET\n webauthn_challenge = $1\nWHERE\n id = $2\n" rows_affected=1 rows_returned=0 elapsed=2.152175ms elapsed_secs=0.002152175
nov. 28 11:15:44 atexo-defguard-exp-infra-01 defguard[25870]: 2024-11-28T10:15:44.436194Z INFO http_request{method=POST path=/api/v1/auth/webauthn/init}: defguard::handlers::auth: Initialized WebAuthn registration for user user1
nov. 28 11:15:44 atexo-defguard-exp-infra-01 defguard[25870]: 2024-11-28T10:15:44.436275Z INFO http_request{method=POST path=/api/v1/auth/webauthn/init}: tower_http::trace::on_response: finished processing request latency=5 ms status=200
nov. 28 11:15:47 atexo-defguard-exp-infra-01 defguard[25870]: 2024-11-28T10:15:47.187671Z DEBUG http_request{method=POST path=/api/v1/auth/webauthn/finish}: tower_http::trace::on_request: started processing request
nov. 28 11:15:47 atexo-defguard-exp-infra-01 defguard[25870]: 2024-11-28T10:15:47.188549Z DEBUG http_request{method=POST path=/api/v1/auth/webauthn/finish}: sqlx::query: summary="SELECT id, user_id, state …" db.statement="\n\nSELECT\n id,\n user_id,\n state \"state: SessionState\",\n created,\n expires,\n webauthn_challenge,\n web3_challenge,\n ip_address,\n device_info\nFROM\n session\nWHERE\n id = $1\n" rows_affected=0 rows_returned=1 elapsed=285.456µs elapsed_secs=0.000285456
nov. 28 11:15:47 atexo-defguard-exp-infra-01 defguard[25870]: 2024-11-28T10:15:47.188933Z DEBUG http_request{method=POST path=/api/v1/auth/webauthn/finish}: sqlx::query: summary="SELECT id, \"username\",\"password_hash\",\"last_name\",\"first_name\",\"email\",\"phone\",\"mfa_enabled\",\"is_active\",\"openid_sub\",\"totp_enabled\",\"email_mfa_enabled\",\"totp_secret\",\"email_mfa_secret\",\"mfa_method\" \"mfa_method: …" db.statement="\n\nSELECT\n id,\n \"username\",\n \"password_hash\",\n \"last_name\",\n \"first_name\",\n \"email\",\n \"phone\",\n \"mfa_enabled\",\n \"is_active\",\n \"openid_sub\",\n \"totp_enabled\",\n \"email_mfa_enabled\",\n \"totp_secret\",\n \"email_mfa_secret\",\n \"mfa_method\" \"mfa_method: _\",\n \"recovery_codes\" \"recovery_codes: _\"\nFROM\n \"user\"\nWHERE\n id = $1\n" rows_affected=0 rows_returned=1 elapsed=166.252µs elapsed_secs=0.000166252
nov. 28 11:15:47 atexo-defguard-exp-infra-01 defguard[25870]: 2024-11-28T10:15:47.189650Z DEBUG http_request{method=POST path=/api/v1/auth/webauthn/finish}: sqlx::query: summary="SELECT id, name FROM …" db.statement="\n\nSELECT\n id,\n name\nFROM\n \"group\"\n JOIN group_user ON \"group\".id = group_user.group_id\nWHERE\n group_user.user_id = $1\n" rows_affected=0 rows_returned=0 elapsed=279.666µs elapsed_secs=0.000279666
nov. 28 11:15:47 atexo-defguard-exp-infra-01 defguard[25870]: 2024-11-28T10:15:47.189866Z INFO http_request{method=POST path=/api/v1/auth/webauthn/finish}: defguard::handlers::auth: Finishing WebAuthn registration for user user1
nov. 28 11:15:47 atexo-defguard-exp-infra-01 defguard[25870]: 2024-11-28T10:15:47.189995Z INFO http_request{method=POST path=/api/v1/auth/webauthn/finish}: defguard::handlers::auth: Passkey registration request origin: https://defguard-exp.domain.com/
nov. 28 11:15:47 atexo-defguard-exp-infra-01 defguard[25870]: 2024-11-28T10:15:47.190003Z INFO http_request{method=POST path=/api/v1/auth/webauthn/finish}: defguard::handlers::auth: Allowed origins: ["https://defguard-exp.domain.com/"]
nov. 28 11:15:47 atexo-defguard-exp-infra-01 defguard[25870]: 2024-11-28T10:15:47.190093Z ERROR http_request{method=POST path=/api/v1/auth/webauthn/finish}: defguard::handlers: Webauthn registration error: The user verified bit is not set, and required by policy
nov. 28 11:15:47 atexo-defguard-exp-infra-01 defguard[25870]: 2024-11-28T10:15:47.190115Z INFO http_request{method=POST path=/api/v1/auth/webauthn/finish}: tower_http::trace::on_response: finished processing request latency=2 ms status=500
nov. 28 11:15:47 atexo-defguard-exp-infra-01 defguard[25870]: 2024-11-28T10:15:47.190121Z ERROR http_request{method=POST path=/api/v1/auth/webauthn/finish}: tower_http::trace::on_failure: response failed classification=Status code: 500 Internal Server Error latency=2 ms
@Vaarlion What OS/version you are using? Have you tried Defguard Core v1.1.4? Does the problem still exist?
Hi @moubctez We are running defguard core at V1.1.4 under ubuntu 24.04.01 LTS The issue (500 error in red at the top right corner) is still here but we have turned off debug logging for now since we entered production.
If you need me to provide new log, let me know :)
for information, this is still an issue with our small instance running with core v1.2.0
Hello We will soon push for a mandatory 2FA for our 98 user, and we would like to know if we can expect Yubikey to work soon, and wait for it, or make it clear in our documentation that the Yubikey option is not available ?
Hello @Vaarlion ,
Thank you for your patience. Can you please specify which Yubikey was causing this issue ?
@Vaarlion closing - please test latest 1.3 alphas - if the bug still persists, please specify logs, YK version and operating system version.
Sorry, i took a 2 week break and i'm starting back today. I have some catch up to do before i can look at this, but i'm not sure i will be able to install an alphas version on either of our prod env, and we just lost our test env to save on cost. I've teste last time with a yubikey 5 usb A, a yubikey 5 usb c and an older yubikey, but i don't remember it's version
Hello Since the 1.4.0 update became an urgent topic, i manage to get some time to update and test 2FA again. I can't confirm that i have the same error, but by doing a bit more googling, i found that another project had the same issue on firefox based browser because the API used werent the same.
I can confirm that our company use mainly firefox, and this does not work, but trying with a chromium browser just to check, it did work without issue. I can then log in and use that token from my firefox browser.
Should i open an issue asking for firefox compatibility on this subject ? Else can you add a warning popup saying that this will not work under firefox so we don't have constant user question when we enforce 2FA ?
Thanks !