defguard icon indicating copy to clipboard operation
defguard copied to clipboard

Security key option available for user, but always fail with a 500

Open Vaarlion opened this issue 1 year ago • 12 comments

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:

  1. Install the latest version of core and proxy
  2. Create a user
  3. Go through enrollment
  4. Connect with that user to the core
  5. 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 avatar Nov 21 '24 14:11 Vaarlion

@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!

teon avatar Nov 22 '24 09:11 teon

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 avatar Nov 26 '24 16:11 Vaarlion

@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.

teon avatar Nov 26 '24 18:11 teon

The domain must be set in: DEFGUARD_URL and DEFGUARD_WEBAUTHN_RP_ID

teon avatar Nov 26 '24 18:11 teon

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 avatar Nov 27 '24 09:11 Vaarlion

@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!

teon avatar Nov 27 '24 09:11 teon

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 avatar Nov 28 '24 10:11 Vaarlion

@Vaarlion What OS/version you are using? Have you tried Defguard Core v1.1.4? Does the problem still exist?

moubctez avatar Jan 03 '25 09:01 moubctez

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 :)

Vaarlion avatar Jan 06 '25 11:01 Vaarlion

for information, this is still an issue with our small instance running with core v1.2.0

Vaarlion avatar Jan 27 '25 15:01 Vaarlion

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 ?

Vaarlion avatar Apr 01 '25 12:04 Vaarlion

Hello @Vaarlion ,

Thank you for your patience. Can you please specify which Yubikey was causing this issue ?

filipslezaklab avatar Apr 25 '25 11:04 filipslezaklab

@Vaarlion closing - please test latest 1.3 alphas - if the bug still persists, please specify logs, YK version and operating system version.

teon avatar May 05 '25 06:05 teon

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

Vaarlion avatar May 05 '25 07:05 Vaarlion

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 !

Vaarlion avatar Aug 25 '25 09:08 Vaarlion