handlers::oauth2::token: Way better error logging on the token endpoint

crates/handlers/src/oauth2/token.rs

@@ -13,7 +13,7 @@ use headers::{CacheControl, HeaderMap, HeaderMapExt, Pragma};
 use hyper::StatusCode;
 use mas_axum_utils::{
     client_authorization::{ClientAuthorization, CredentialsVerificationError},
-    sentry::SentryEventID,
+    record_error,
 };
 use mas_data_model::{
     AuthorizationGrantStage, Client, Device, DeviceCodeGrantState, SiteConfig, TokenType, UserAgent,
@@ -42,7 +42,7 @@ use oauth2_types::{
 };
 use opentelemetry::{Key, KeyValue, metrics::Counter};
 use thiserror::Error;
-use tracing::{debug, info};
+use tracing::{debug, info, warn};
 use ulid::Ulid;
 
 use super::{generate_id_token, generate_token_pair};
@@ -72,17 +72,28 @@ pub(crate) enum RouteError {
     #[error("client not found")]
     ClientNotFound,
 
-    #[error("client not allowed")]
-    ClientNotAllowed,
+    #[error("client not allowed to use the token endpoint: {0}")]
+    ClientNotAllowed(Ulid),
 
-    #[error("could not verify client credentials")]
-    ClientCredentialsVerification(#[from] CredentialsVerificationError),
+    #[error("invalid client credentials for client {client_id}")]
+    InvalidClientCredentials {
+        client_id: Ulid,
+        #[source]
+        source: CredentialsVerificationError,
+    },
+
+    #[error("could not verify client credentials for client {client_id}")]
+    ClientCredentialsVerification {
+        client_id: Ulid,
+        #[source]
+        source: CredentialsVerificationError,
+    },
 
     #[error("grant not found")]
     GrantNotFound,
 
-    #[error("invalid grant")]
-    InvalidGrant,
+    #[error("invalid grant {0}")]
+    InvalidGrant(Ulid),
 
     #[error("refresh token not found")]
     RefreshTokenNotFound,
@@ -96,20 +107,23 @@ pub(crate) enum RouteError {
     #[error("client id mismatch: expected {expected}, got {actual}")]
     ClientIDMismatch { expected: Ulid, actual: Ulid },
 
-    #[error("policy denied the request")]
-    DeniedByPolicy(Vec<mas_policy::Violation>),
+    #[error("policy denied the request: {0}")]
+    DeniedByPolicy(mas_policy::EvaluationResult),
 
     #[error("unsupported grant type")]
     UnsupportedGrantType,
 
-    #[error("unauthorized client")]
-    UnauthorizedClient,
+    #[error("client {0} is not authorized to use this grant type")]
+    UnauthorizedClient(Ulid),
 
-    #[error("failed to load browser session")]
-    NoSuchBrowserSession,
+    #[error("unexpected client {was} (expected {expected})")]
+    UnexptectedClient { was: Ulid, expected: Ulid },
 
-    #[error("failed to load oauth session")]
-    NoSuchOAuthSession,
+    #[error("failed to load browser session {0}")]
+    NoSuchBrowserSession(Ulid),
+
+    #[error("failed to load oauth session {0}")]
+    NoSuchOAuthSession(Ulid),
 
     #[error(
         "failed to load the next refresh token ({next:?}) from the previous one ({previous:?})"
@@ -145,14 +159,25 @@ pub(crate) enum RouteError {
 
 impl IntoResponse for RouteError {
     fn into_response(self) -> axum::response::Response {
-        let event_id = sentry::capture_error(&self);
+        let sentry_event_id = record_error!(
+            self,
+            Self::Internal(_)
+                | Self::ClientCredentialsVerification { .. }
+                | Self::NoSuchBrowserSession(_)
+                | Self::NoSuchOAuthSession(_)
+                | Self::ProvisionDeviceFailed(_)
+                | Self::NoSuchNextRefreshToken { .. }
+                | Self::NoSuchNextAccessToken { .. }
+                | Self::NoAccessTokenOnRefreshToken { .. }
+        );
 
         TOKEN_REQUEST_COUNTER.add(1, &[KeyValue::new(RESULT, "error")]);
 
         let response = match self {
             Self::Internal(_)
-            | Self::NoSuchBrowserSession
-            | Self::NoSuchOAuthSession
+            | Self::ClientCredentialsVerification { .. }
+            | Self::NoSuchBrowserSession(_)
+            | Self::NoSuchOAuthSession(_)
             | Self::ProvisionDeviceFailed(_)
             | Self::NoSuchNextRefreshToken { .. }
             | Self::NoSuchNextAccessToken { .. }
@@ -160,10 +185,12 @@ impl IntoResponse for RouteError {
                 StatusCode::INTERNAL_SERVER_ERROR,
                 Json(ClientError::from(ClientErrorCode::ServerError)),
             ),
+
             Self::BadRequest => (
                 StatusCode::BAD_REQUEST,
                 Json(ClientError::from(ClientErrorCode::InvalidRequest)),
             ),
+
             Self::PkceVerification(err) => (
                 StatusCode::BAD_REQUEST,
                 Json(
@@ -171,19 +198,25 @@ impl IntoResponse for RouteError {
                         .with_description(format!("PKCE verification failed: {err}")),
                 ),
             ),
-            Self::ClientNotFound | Self::ClientCredentialsVerification(_) => (
+
+            Self::ClientNotFound | Self::InvalidClientCredentials { .. } => (
                 StatusCode::UNAUTHORIZED,
                 Json(ClientError::from(ClientErrorCode::InvalidClient)),
             ),
-            Self::ClientNotAllowed | Self::UnauthorizedClient => (
+
+            Self::ClientNotAllowed(_)
+            | Self::UnauthorizedClient(_)
+            | Self::UnexptectedClient { .. } => (
                 StatusCode::UNAUTHORIZED,
                 Json(ClientError::from(ClientErrorCode::UnauthorizedClient)),
             ),
-            Self::DeniedByPolicy(violations) => (
+
+            Self::DeniedByPolicy(evaluation) => (
                 StatusCode::FORBIDDEN,
                 Json(
                     ClientError::from(ClientErrorCode::InvalidScope).with_description(
-                        violations
+                        evaluation
+                            .violations
                             .into_iter()
                             .map(|violation| violation.msg)
                             .collect::<Vec<_>>()
@@ -191,19 +224,23 @@ impl IntoResponse for RouteError {
                     ),
                 ),
             ),
+
             Self::DeviceCodeRejected => (
                 StatusCode::FORBIDDEN,
                 Json(ClientError::from(ClientErrorCode::AccessDenied)),
             ),
+
             Self::DeviceCodeExpired => (
                 StatusCode::FORBIDDEN,
                 Json(ClientError::from(ClientErrorCode::ExpiredToken)),
             ),
+
             Self::DeviceCodePending => (
                 StatusCode::FORBIDDEN,
                 Json(ClientError::from(ClientErrorCode::AuthorizationPending)),
             ),
-            Self::InvalidGrant
+
+            Self::InvalidGrant(_)
             | Self::DeviceCodeExchanged
             | Self::RefreshTokenNotFound
             | Self::RefreshTokenInvalid(_)
@@ -213,13 +250,14 @@ impl IntoResponse for RouteError {
                 StatusCode::BAD_REQUEST,
                 Json(ClientError::from(ClientErrorCode::InvalidGrant)),
             ),
+
             Self::UnsupportedGrantType => (
                 StatusCode::BAD_REQUEST,
                 Json(ClientError::from(ClientErrorCode::UnsupportedGrantType)),
             ),
         };
 
-        (SentryEventID::from(event_id), response).into_response()
+        (sentry_event_id, response).into_response()
     }
 }
 
@@ -231,7 +269,6 @@ impl_from_error_for_route!(super::IdTokenSignatureError);
     name = "handlers.oauth2.token.post",
     fields(client.id = client_authorization.client_id()),
     skip_all,
-    err,
 )]
 pub(crate) async fn post(
     mut rng: BoxRng,
@@ -258,12 +295,27 @@ pub(crate) async fn post(
     let method = client
         .token_endpoint_auth_method
         .as_ref()
-        .ok_or(RouteError::ClientNotAllowed)?;
+        .ok_or(RouteError::ClientNotAllowed(client.id))?;
 
     client_authorization
         .credentials
         .verify(&http_client, &encrypter, method, &client)
-        .await?;
+        .await
+        .map_err(|err| {
+            // Classify the error differntly, depending on whether it's an 'internal' error,
+            // or just because the client presented invalid credentials.
+            if err.is_internal() {
+                RouteError::ClientCredentialsVerification {
+                    client_id: client.id,
+                    source: err,
+                }
+            } else {
+                RouteError::InvalidClientCredentials {
+                    client_id: client.id,
+                    source: err,
+                }
+            }
+        })?;
 
     let form = client_authorization.form.ok_or(RouteError::BadRequest)?;
 
@@ -367,7 +419,7 @@ async fn authorization_code_grant(
 ) -> Result<(AccessTokenResponse, BoxRepository), RouteError> {
     // Check that the client is allowed to use this grant type
     if !client.grant_types.contains(&GrantType::AuthorizationCode) {
-        return Err(RouteError::UnauthorizedClient);
+        return Err(RouteError::UnauthorizedClient(client.id));
     }
 
     let authz_grant = repo
@@ -381,40 +433,40 @@ async fn authorization_code_grant(
     let session_id = match authz_grant.stage {
         AuthorizationGrantStage::Cancelled { cancelled_at } => {
             debug!(%cancelled_at, "Authorization grant was cancelled");
-            return Err(RouteError::InvalidGrant);
+            return Err(RouteError::InvalidGrant(authz_grant.id));
         }
         AuthorizationGrantStage::Exchanged {
             exchanged_at,
             fulfilled_at,
             session_id,
         } => {
-            debug!(%exchanged_at, %fulfilled_at, "Authorization code was already exchanged");
+            warn!(%exchanged_at, %fulfilled_at, "Authorization code was already exchanged");
 
             // Ending the session if the token was already exchanged more than 20s ago
             if now - exchanged_at > Duration::microseconds(20 * 1000 * 1000) {
-                debug!("Ending potentially compromised session");
+                warn!("Ending potentially compromised session");
                 let session = repo
                     .oauth2_session()
                     .lookup(session_id)
                     .await?
-                    .ok_or(RouteError::NoSuchOAuthSession)?;
+                    .ok_or(RouteError::NoSuchOAuthSession(session_id))?;
                 repo.oauth2_session().finish(clock, session).await?;
                 repo.save().await?;
             }
 
-            return Err(RouteError::InvalidGrant);
+            return Err(RouteError::InvalidGrant(authz_grant.id));
         }
         AuthorizationGrantStage::Pending => {
-            debug!("Authorization grant has not been fulfilled yet");
-            return Err(RouteError::InvalidGrant);
+            warn!("Authorization grant has not been fulfilled yet");
+            return Err(RouteError::InvalidGrant(authz_grant.id));
         }
         AuthorizationGrantStage::Fulfilled {
             session_id,
             fulfilled_at,
         } => {
             if now - fulfilled_at > Duration::microseconds(10 * 60 * 1000 * 1000) {
-                debug!("Code exchange took more than 10 minutes");
-                return Err(RouteError::InvalidGrant);
+                warn!("Code exchange took more than 10 minutes");
+                return Err(RouteError::InvalidGrant(authz_grant.id));
             }
 
             session_id
@@ -425,7 +477,7 @@ async fn authorization_code_grant(
         .oauth2_session()
         .lookup(session_id)
         .await?
-        .ok_or(RouteError::NoSuchOAuthSession)?;
+        .ok_or(RouteError::NoSuchOAuthSession(session_id))?;
 
     if let Some(user_agent) = user_agent {
         session = repo
@@ -435,10 +487,16 @@ async fn authorization_code_grant(
     }
 
     // This should never happen, since we looked up in the database using the code
-    let code = authz_grant.code.as_ref().ok_or(RouteError::InvalidGrant)?;
+    let code = authz_grant
+        .code
+        .as_ref()
+        .ok_or(RouteError::InvalidGrant(authz_grant.id))?;
 
     if client.id != session.client_id {
-        return Err(RouteError::UnauthorizedClient);
+        return Err(RouteError::UnexptectedClient {
+            was: client.id,
+            expected: session.client_id,
+        });
     }
 
     match (code.pkce.as_ref(), grant.code_verifier.as_ref()) {
@@ -453,14 +511,14 @@ async fn authorization_code_grant(
 
     let Some(user_session_id) = session.user_session_id else {
         tracing::warn!("No user session associated with this OAuth2 session");
-        return Err(RouteError::InvalidGrant);
+        return Err(RouteError::InvalidGrant(authz_grant.id));
     };
 
     let browser_session = repo
         .browser_session()
         .lookup(user_session_id)
         .await?
-        .ok_or(RouteError::NoSuchBrowserSession)?;
+        .ok_or(RouteError::NoSuchBrowserSession(user_session_id))?;
 
     let last_authentication = repo
         .browser_session()
@@ -539,7 +597,7 @@ async fn refresh_token_grant(
 ) -> Result<(AccessTokenResponse, BoxRepository), RouteError> {
     // Check that the client is allowed to use this grant type
     if !client.grant_types.contains(&GrantType::RefreshToken) {
-        return Err(RouteError::UnauthorizedClient);
+        return Err(RouteError::UnauthorizedClient(client.id));
     }
 
     let refresh_token = repo
@@ -552,7 +610,7 @@ async fn refresh_token_grant(
         .oauth2_session()
         .lookup(refresh_token.session_id)
         .await?
-        .ok_or(RouteError::NoSuchOAuthSession)?;
+        .ok_or(RouteError::NoSuchOAuthSession(refresh_token.session_id))?;
 
     // Let's for now record the user agent on each refresh, that should be
     // responsive enough and not too much of a burden on the database.
@@ -692,7 +750,7 @@ async fn client_credentials_grant(
 ) -> Result<(AccessTokenResponse, BoxRepository), RouteError> {
     // Check that the client is allowed to use this grant type
     if !client.grant_types.contains(&GrantType::ClientCredentials) {
-        return Err(RouteError::UnauthorizedClient);
+        return Err(RouteError::UnauthorizedClient(client.id));
     }
 
     // Default to an empty scope if none is provided
@@ -715,7 +773,7 @@ async fn client_credentials_grant(
         })
         .await?;
     if !res.valid() {
-        return Err(RouteError::DeniedByPolicy(res.violations));
+        return Err(RouteError::DeniedByPolicy(res));
     }
 
     // Start the session
@@ -771,7 +829,7 @@ async fn device_code_grant(
 ) -> Result<(AccessTokenResponse, BoxRepository), RouteError> {
     // Check that the client is allowed to use this grant type
     if !client.grant_types.contains(&GrantType::DeviceCode) {
-        return Err(RouteError::UnauthorizedClient);
+        return Err(RouteError::UnauthorizedClient(client.id));
     }
 
     let grant = repo
@@ -804,14 +862,14 @@ async fn device_code_grant(
         }
         DeviceCodeGrantState::Fulfilled {
             browser_session_id, ..
-        } => browser_session_id,
+        } => *browser_session_id,
     };
 
     let browser_session = repo
         .browser_session()
-        .lookup(*browser_session_id)
+        .lookup(browser_session_id)
         .await?
-        .ok_or(RouteError::NoSuchBrowserSession)?;
+        .ok_or(RouteError::NoSuchBrowserSession(browser_session_id))?;
 
     // Start the session
     let mut session = repo