From 86f39ff253530c12bce726d8c06e989b0a0b62b1 Mon Sep 17 00:00:00 2001 From: Gerard Guillemas Martos Date: Thu, 19 Sep 2024 10:41:32 +0100 Subject: [PATCH] Improve log messages for authentication errors (#4821) --- core/src/err/mod.rs | 8 +++-- core/src/iam/signin.rs | 78 +++++++++++++++++++++++++++++++---------- core/src/iam/signup.rs | 17 ++++++--- core/src/iam/verify.rs | 79 ++++++++++++++++++++++++++++-------------- 4 files changed, 131 insertions(+), 51 deletions(-) diff --git a/core/src/err/mod.rs b/core/src/err/mod.rs index 09078da1..16eb9d1a 100644 --- a/core/src/err/mod.rs +++ b/core/src/err/mod.rs @@ -983,9 +983,11 @@ pub enum Error { index: String, }, - /// The session has expired either because the token used - /// to establish it has expired or because an expiration - /// was explicitly defined when establishing it + /// The token has expired + #[error("The token has expired")] + ExpiredToken, + + /// The session has expired #[error("The session has expired")] ExpiredSession, diff --git a/core/src/iam/signin.rs b/core/src/iam/signin.rs index 260598f9..9d34f77c 100644 --- a/core/src/iam/signin.rs +++ b/core/src/iam/signin.rs @@ -209,8 +209,14 @@ pub async fn db_access( } Err(e) => match e { Error::Thrown(_) => Err(e), - e if *INSECURE_FORWARD_ACCESS_ERRORS => Err(e), - _ => Err(Error::AccessRecordSigninQueryFailed), + e => { + debug!("Record user signin query failed: {e}"); + if *INSECURE_FORWARD_ACCESS_ERRORS { + Err(e) + } else { + Err(Error::AccessRecordSigninQueryFailed) + } + } }, } } @@ -221,6 +227,9 @@ pub async fn db_access( // TODO(gguillemas): Remove this once bearer access is no longer experimental. if !*EXPERIMENTAL_BEARER_ACCESS { // Return opaque error to avoid leaking the existence of the feature. + debug!( + "Error attempting to authenticate with disabled bearer access feature" + ); return Err(Error::InvalidAuth); } // Check if the bearer access method supports issuing tokens. @@ -236,7 +245,10 @@ pub async fn db_access( let gr = match tx.get_db_access_grant(&ns, &db, &ac, &kid).await { Ok(gr) => gr, // Return opaque error to avoid leaking existence of the grant. - _ => return Err(Error::InvalidAuth), + Err(e) => { + debug!("Error retrieving bearer access grant: {e}"); + return Err(Error::InvalidAuth); + } }; // Ensure that the transaction is cancelled. tx.cancel().await?; @@ -248,7 +260,7 @@ pub async fn db_access( let tx = kvs.transaction(Read, Optimistic).await?; // Fetch the specified user from storage. let user = tx.get_db_user(&ns, &db, user).await.map_err(|e| { - trace!("Error while authenticating to database `{ns}/{db}`: {e}"); + debug!("Error retrieving user for bearer access to database `{ns}/{db}`: {e}"); // Return opaque error to avoid leaking grant subject existence. Error::InvalidAuth })?; @@ -363,7 +375,7 @@ pub async fn db_user( ..Claims::default() }; // Log the authenticated database info - trace!("Signing in to database `{}`", db); + trace!("Signing in to database `{ns}/{db}`"); // Create the authentication token let enc = encode(&HEADER, &val, &key); // Set the authentication on the session @@ -379,7 +391,11 @@ pub async fn db_user( _ => Err(Error::TokenMakingFailed), } } - _ => Err(Error::InvalidAuth), + // The password did not verify + Err(e) => { + debug!("Failed to verify signin credentials for user `{user}` in database `{ns}/{db}`: {e}"); + Err(Error::InvalidAuth) + } } } @@ -405,6 +421,9 @@ pub async fn ns_access( // TODO(gguillemas): Remove this once bearer access is no longer experimental. if !*EXPERIMENTAL_BEARER_ACCESS { // Return opaque error to avoid leaking the existence of the feature. + debug!( + "Error attempting to authenticate with disabled bearer access feature" + ); return Err(Error::InvalidAuth); } // Check if the bearer access method supports issuing tokens. @@ -420,7 +439,10 @@ pub async fn ns_access( let gr = match tx.get_ns_access_grant(&ns, &ac, &kid).await { Ok(gr) => gr, // Return opaque error to avoid leaking existence of the grant. - _ => return Err(Error::InvalidAuth), + Err(e) => { + debug!("Error retrieving bearer access grant: {e}"); + return Err(Error::InvalidAuth); + } }; // Ensure that the transaction is cancelled. tx.cancel().await?; @@ -431,11 +453,12 @@ pub async fn ns_access( // Create a new readonly transaction. let tx = kvs.transaction(Read, Optimistic).await?; // Fetch the specified user from storage. - let user = tx.get_ns_user(&ns, user).await.map_err(|e| { - trace!("Error while authenticating to namespace `{ns}`: {e}"); - // Return opaque error to avoid leaking grant subject existence. - Error::InvalidAuth - })?; + let user = + tx.get_ns_user(&ns, user).await.map_err(|e| { + debug!("Error retrieving user for bearer access to namespace `{ns}`: {e}"); + // Return opaque error to avoid leaking grant subject existence. + Error::InvalidAuth + })?; // Ensure that the transaction is cancelled. tx.cancel().await?; user.roles.clone() @@ -533,7 +556,7 @@ pub async fn ns_user( ..Claims::default() }; // Log the authenticated namespace info - trace!("Signing in to namespace `{}`", ns); + trace!("Signing in to namespace `{ns}`"); // Create the authentication token let enc = encode(&HEADER, &val, &key); // Set the authentication on the session @@ -549,7 +572,12 @@ pub async fn ns_user( } } // The password did not verify - _ => Err(Error::InvalidAuth), + Err(e) => { + debug!( + "Failed to verify signin credentials for user `{user}` in namespace `{ns}`: {e}" + ); + Err(Error::InvalidAuth) + } } } @@ -589,7 +617,10 @@ pub async fn root_user( } } // The password did not verify - _ => Err(Error::InvalidAuth), + Err(e) => { + debug!("Failed to verify signin credentials for user `{user}` in root: {e}"); + Err(Error::InvalidAuth) + } } } @@ -614,6 +645,9 @@ pub async fn root_access( // TODO(gguillemas): Remove this once bearer access is no longer experimental. if !*EXPERIMENTAL_BEARER_ACCESS { // Return opaque error to avoid leaking the existence of the feature. + debug!( + "Error attempting to authenticate with disabled bearer access feature" + ); return Err(Error::InvalidAuth); } // Check if the bearer access method supports issuing tokens. @@ -629,7 +663,10 @@ pub async fn root_access( let gr = match tx.get_root_access_grant(&ac, &kid).await { Ok(gr) => gr, // Return opaque error to avoid leaking existence of the grant. - _ => return Err(Error::InvalidAuth), + Err(e) => { + debug!("Error retrieving bearer access grant: {e}"); + return Err(Error::InvalidAuth); + } }; // Ensure that the transaction is cancelled. tx.cancel().await?; @@ -641,7 +678,7 @@ pub async fn root_access( let tx = kvs.transaction(Read, Optimistic).await?; // Fetch the specified user from storage. let user = tx.get_root_user(user).await.map_err(|e| { - trace!("Error while authenticating to root: {e}"); + debug!("Error retrieving user for bearer access to root: {e}"); // Return opaque error to avoid leaking grant subject existence. Error::InvalidAuth })?; @@ -753,10 +790,14 @@ pub fn verify_grant_bearer(gr: &Arc, key: String) -> Result<(), Err (Some(exp), None) => { if exp < &Datetime::default() { // Return opaque error to avoid leaking revocation status. + debug!("Bearer access grant `{}` for method `{}` is expired", gr.id, gr.ac); return Err(Error::InvalidAuth); } } - _ => return Err(Error::InvalidAuth), + (_, Some(_)) => { + debug!("Bearer access grant `{}` for method `{}` is revoked", gr.id, gr.ac); + return Err(Error::InvalidAuth); + } } // Check if the provided key matches the bearer key in the grant. // We use time-constant comparison to prevent timing attacks. @@ -765,6 +806,7 @@ pub fn verify_grant_bearer(gr: &Arc, key: String) -> Result<(), Err let signin_key_bytes: &[u8] = key.as_bytes(); let ok: bool = grant_key_bytes.ct_eq(signin_key_bytes).into(); if !ok { + debug!("Bearer access grant `{}` for method `{}` is invalid", gr.id, gr.ac); return Err(Error::InvalidAuth); } }; diff --git a/core/src/iam/signup.rs b/core/src/iam/signup.rs index 15cd11ff..8204b2bf 100644 --- a/core/src/iam/signup.rs +++ b/core/src/iam/signup.rs @@ -77,7 +77,7 @@ pub async fn db_access( sess.or.clone_from(&session.or); // Compute the value with the params match kvs.evaluate(val, &sess, vars).await { - // The signin value succeeded + // The signup value succeeded Ok(val) => { match val.record() { // There is a record returned @@ -113,7 +113,10 @@ pub async fn db_access( // Update rid with result from AUTHENTICATE clause rid = id; } - _ => return Err(Error::InvalidAuth), + _ => { + debug!("Authentication attempt as record user rejected by AUTHENTICATE clause"); + return Err(Error::InvalidAuth); + } }, Err(e) => return match e { Error::Thrown(_) => Err(e), @@ -153,8 +156,14 @@ pub async fn db_access( } Err(e) => match e { Error::Thrown(_) => Err(e), - e if *INSECURE_FORWARD_ACCESS_ERRORS => Err(e), - _ => Err(Error::AccessRecordSignupQueryFailed), + e => { + debug!("Record user signup query failed: {e}"); + if *INSECURE_FORWARD_ACCESS_ERRORS { + Err(e) + } else { + Err(Error::AccessRecordSignupQueryFailed) + } + } }, } } diff --git a/core/src/iam/verify.rs b/core/src/iam/verify.rs index eb04243c..da20f02d 100644 --- a/core/src/iam/verify.rs +++ b/core/src/iam/verify.rs @@ -120,7 +120,12 @@ pub async fn basic( } Err(err) => Err(err), }, - (None, Some(_)) => Err(Error::InvalidAuth), + (None, Some(db)) => { + debug!( + "Attempted basic authentication in database '{db}' without specifying a namespace" + ); + Err(Error::InvalidAuth) + } } } @@ -134,15 +139,15 @@ pub async fn token(kvs: &Datastore, session: &mut Session, token: &str) -> Resul // Check if the auth token can be used if let Some(nbf) = token_data.claims.nbf { if nbf > Utc::now().timestamp() { - trace!("The 'nbf' field in the authentication token was invalid"); + debug!("Token verification failed due to the 'nbf' claim containing a future time"); return Err(Error::InvalidAuth); } } // Check if the auth token has expired if let Some(exp) = token_data.claims.exp { if exp < Utc::now().timestamp() { - trace!("The 'exp' field in the authentication token was invalid"); - return Err(Error::InvalidAuth); + debug!("Token verification failed due to the 'exp' claim containing a past time"); + return Err(Error::ExpiredToken); } } // Check the token authentication claims @@ -183,7 +188,7 @@ pub async fn token(kvs: &Datastore, session: &mut Session, token: &str) -> Resul _ => return Err(Error::AccessMethodMismatch), }; // Verify the token - decode::(token, &cf.0, &cf.1)?; + verify_token(token, &cf.0, &cf.1)?; // AUTHENTICATE clause if let Some(au) = &de.authenticate { // Setup the system session for finding the signin record @@ -244,7 +249,7 @@ pub async fn token(kvs: &Datastore, session: &mut Session, token: &str) -> Resul _ => return Err(Error::AccessMethodMismatch), }?; // Verify the token - decode::(token, &cf.0, &cf.1)?; + verify_token(token, &cf.0, &cf.1)?; // AUTHENTICATE clause if let Some(au) = &de.authenticate { // Setup the system session for executing the clause @@ -285,7 +290,7 @@ pub async fn token(kvs: &Datastore, session: &mut Session, token: &str) -> Resul // The clause can make up for the missing "id" claim by resolving other claims to a specific record AccessType::Record(at) => match &de.authenticate { Some(au) => { - trace!("Access method `{}` is record access with authenticate clause", ac); + trace!("Access method `{}` is record access with AUTHENTICATE clause", ac); let cf = match &at.jwt.verify { JwtAccessVerify::Key(key) => config(key.alg, key.key.as_bytes()), #[cfg(feature = "jwks")] @@ -301,7 +306,7 @@ pub async fn token(kvs: &Datastore, session: &mut Session, token: &str) -> Resul }?; // Verify the token - decode::(token, &cf.0, &cf.1)?; + verify_token(token, &cf.0, &cf.1)?; // AUTHENTICATE clause // Setup the system session for finding the signin record let mut sess = Session::editor().with_ns(ns).with_db(db); @@ -342,7 +347,7 @@ pub async fn token(kvs: &Datastore, session: &mut Session, token: &str) -> Resul let tx = kvs.transaction(Read, Optimistic).await?; // Get the database user let de = tx.get_db_user(ns, db, id).await.map_err(|e| { - trace!("Error while authenticating to database `{db}`: {e}"); + debug!("Error while authenticating to database `{db}`: {e}"); Error::InvalidAuth })?; // Ensure that the transaction is cancelled @@ -350,9 +355,9 @@ pub async fn token(kvs: &Datastore, session: &mut Session, token: &str) -> Resul // Check the algorithm let cf = config(Algorithm::Hs512, de.code.as_bytes())?; // Verify the token - decode::(token, &cf.0, &cf.1)?; + verify_token(token, &cf.0, &cf.1)?; // Log the success - debug!("Authenticated to database `{}` with user `{}`", db, id); + debug!("Authenticated to database `{}` with user `{}` using token", db, id); // Set the session session.tk = Some(value); session.ns = Some(ns.to_owned()); @@ -397,7 +402,7 @@ pub async fn token(kvs: &Datastore, session: &mut Session, token: &str) -> Resul _ => return Err(Error::AccessMethodMismatch), }?; // Verify the token - decode::(token, &cf.0, &cf.1)?; + verify_token(token, &cf.0, &cf.1)?; // AUTHENTICATE clause if let Some(au) = &de.authenticate { // Setup the system session for executing the clause @@ -420,7 +425,7 @@ pub async fn token(kvs: &Datastore, session: &mut Session, token: &str) -> Resul .collect::, _>>()?, }; // Log the success - trace!("Authenticated to namespace `{}` with access method `{}`", ns, ac); + debug!("Authenticated to namespace `{}` with access method `{}`", ns, ac); // Set the session session.tk = Some(value); session.ns = Some(ns.to_owned()); @@ -445,7 +450,7 @@ pub async fn token(kvs: &Datastore, session: &mut Session, token: &str) -> Resul let tx = kvs.transaction(Read, Optimistic).await?; // Get the namespace user let de = tx.get_ns_user(ns, id).await.map_err(|e| { - trace!("Error while authenticating to namespace `{ns}`: {e}"); + debug!("Error while authenticating to namespace `{ns}`: {e}"); Error::InvalidAuth })?; // Ensure that the transaction is cancelled @@ -453,9 +458,9 @@ pub async fn token(kvs: &Datastore, session: &mut Session, token: &str) -> Resul // Check the algorithm let cf = config(Algorithm::Hs512, de.code.as_bytes())?; // Verify the token - decode::(token, &cf.0, &cf.1)?; + verify_token(token, &cf.0, &cf.1)?; // Log the success - trace!("Authenticated to namespace `{}` with user `{}`", ns, id); + debug!("Authenticated to namespace `{}` with user `{}` using token", ns, id); // Set the session session.tk = Some(value); session.ns = Some(ns.to_owned()); @@ -498,7 +503,7 @@ pub async fn token(kvs: &Datastore, session: &mut Session, token: &str) -> Resul _ => return Err(Error::AccessMethodMismatch), }?; // Verify the token - decode::(token, &cf.0, &cf.1)?; + verify_token(token, &cf.0, &cf.1)?; // AUTHENTICATE clause if let Some(au) = &de.authenticate { // Setup the system session for executing the clause @@ -521,7 +526,7 @@ pub async fn token(kvs: &Datastore, session: &mut Session, token: &str) -> Resul .collect::, _>>()?, }; // Log the success - trace!("Authenticated to root with access method `{}`", ac); + debug!("Authenticated to root with access method `{}`", ac); // Set the session session.tk = Some(value); session.ac = Some(ac.to_owned()); @@ -540,7 +545,7 @@ pub async fn token(kvs: &Datastore, session: &mut Session, token: &str) -> Resul let tx = kvs.transaction(Read, Optimistic).await?; // Get the namespace user let de = tx.get_root_user(id).await.map_err(|e| { - trace!("Error while authenticating to root: {e}"); + debug!("Error while authenticating to root: {e}"); Error::InvalidAuth })?; // Ensure that the transaction is cancelled @@ -548,9 +553,9 @@ pub async fn token(kvs: &Datastore, session: &mut Session, token: &str) -> Resul // Check the algorithm let cf = config(Algorithm::Hs512, de.code.as_bytes())?; // Verify the token - decode::(token, &cf.0, &cf.1)?; + verify_token(token, &cf.0, &cf.1)?; // Log the success - trace!("Authenticated to root level with user `{}`", id); + debug!("Authenticated to root level with user `{}` using token", id); // Set the session session.tk = Some(value); session.exp = expiration(de.duration.session)?; @@ -575,7 +580,7 @@ pub async fn verify_root_creds( let tx = ds.transaction(Read, Optimistic).await?; // Fetch the specified user from storage let user = tx.get_root_user(user).await.map_err(|e| { - trace!("Error while authenticating to root: {e}"); + debug!("Error retrieving user for authentication to root: {e}"); Error::InvalidAuth })?; // Ensure that the transaction is cancelled @@ -598,7 +603,7 @@ pub async fn verify_ns_creds( let tx = ds.transaction(Read, Optimistic).await?; // Fetch the specified user from storage let user = tx.get_ns_user(ns, user).await.map_err(|e| { - trace!("Error while authenticating to namespace `{ns}`: {e}"); + debug!("Error retrieving user for authentication to namespace `{ns}`: {e}"); Error::InvalidAuth })?; // Ensure that the transaction is cancelled @@ -622,7 +627,7 @@ pub async fn verify_db_creds( let tx = ds.transaction(Read, Optimistic).await?; // Fetch the specified user from storage let user = tx.get_db_user(ns, db, user).await.map_err(|e| { - trace!("Error while authenticating to database `{ns}/{db}`: {e}"); + debug!("Error retrieving user for authentication to database `{ns}/{db}`: {e}"); Error::InvalidAuth })?; // Ensure that the transaction is cancelled @@ -656,7 +661,10 @@ pub async fn authenticate_record( // If the AUTHENTICATE clause returns a record, authentication continues with that record Some(id) => Ok(id), // If the AUTHENTICATE clause returns anything else, authentication fails generically - _ => Err(Error::InvalidAuth), + _ => { + debug!("Authentication attempt as record user rejected by AUTHENTICATE clause"); + Err(Error::InvalidAuth) + } }, Err(e) => match e { // If the AUTHENTICATE clause throws a specific error, authentication fails with that error @@ -679,7 +687,10 @@ pub async fn authenticate_generic( // If the AUTHENTICATE clause returns nothing, authentication continues Value::None => Ok(()), // If the AUTHENTICATE clause returns anything else, authentication fails generically - _ => Err(Error::InvalidAuth), + _ => { + debug!("Authentication attempt as system user rejected by AUTHENTICATE clause"); + Err(Error::InvalidAuth) + } } } Err(e) => match e { @@ -691,6 +702,22 @@ pub async fn authenticate_generic( } } +fn verify_token(token: &str, key: &DecodingKey, validation: &Validation) -> Result<(), Error> { + match decode::(token, key, validation) { + Ok(_) => Ok(()), + Err(err) => { + // Only transparently return certain token verification errors + match err.kind() { + jsonwebtoken::errors::ErrorKind::ExpiredSignature => Err(Error::ExpiredToken), + _ => { + debug!("Error verifying authentication token: {err}"); + Err(Error::InvalidAuth) + } + } + } + } +} + #[cfg(test)] mod tests { use super::*;