diff --git a/crates/client-api/src/auth.rs b/crates/client-api/src/auth.rs index fc777c8b105..8667b876689 100644 --- a/crates/client-api/src/auth.rs +++ b/crates/client-api/src/auth.rs @@ -8,9 +8,8 @@ use http::{request, HeaderValue, StatusCode}; use serde::{Deserialize, Serialize}; use spacetimedb::auth::identity::{ConnectionAuthCtx, SpacetimeIdentityClaims}; use spacetimedb::auth::identity::{JwtError, JwtErrorKind}; -use spacetimedb::auth::token_validation::{ - new_validator, DefaultValidator, TokenSigner, TokenValidationError, TokenValidator, -}; +use spacetimedb::auth::token_validation::{new_validator, DefaultValidator, TokenSigner, TokenValidator}; +pub use spacetimedb::auth::token_validation::{TokenValidationError, TokenValidationErrorCategory}; use spacetimedb::auth::JwtKeys; use spacetimedb::energy::FunctionBudget; use spacetimedb::identity::Identity; diff --git a/crates/core/src/auth/token_validation.rs b/crates/core/src/auth/token_validation.rs index c38d732882d..8806b3c62c0 100644 --- a/crates/core/src/auth/token_validation.rs +++ b/crates/core/src/auth/token_validation.rs @@ -20,7 +20,7 @@ use super::JwtKeys; #[derive(thiserror::Error, Debug)] pub enum TokenValidationError { - // TODO: Add real error types. + // TODO: Replace the remaining dependency-specific and catch-all variants with domain errors. // TODO: If we had our own errors defined we wouldn't be locked into this lib. #[error("Invalid token: {0}")] @@ -29,15 +29,50 @@ pub enum TokenValidationError { #[error("Specified key ID not found in JWKs")] KeyIDNotFound, + /// The token was decoded, but its claims are not acceptable. + #[error(transparent)] + InvalidClaims(anyhow::Error), + #[error(transparent)] JwkError(#[from] jwks::JwkError), #[error(transparent)] JwksError(#[from] jwks::JwksError), + + /// The identity provider's validation material could not be obtained. + #[error(transparent)] + IdentityProviderUnavailable(anyhow::Error), + // The other case is a catch-all for unexpected errors. #[error(transparent)] Other(#[from] anyhow::Error), } +/// The operational category of a token validation failure. +#[derive(Clone, Copy, Debug, Eq, PartialEq)] +pub enum TokenValidationErrorCategory { + /// The supplied token is invalid and the client may retry with different credentials. + InvalidCredentials, + /// Validation failed because identity-provider data could not be obtained or used. + IdentityProvider, + /// Validation failed because of an unexpected local condition. + Internal, +} + +impl TokenValidationError { + /// Classifies this failure for operational handling such as log severity. + pub fn category(&self) -> TokenValidationErrorCategory { + match self { + Self::TokenError(_) | Self::KeyIDNotFound | Self::InvalidClaims(_) => { + TokenValidationErrorCategory::InvalidCredentials + } + Self::JwkError(_) | Self::JwksError(_) | Self::IdentityProviderUnavailable(_) => { + TokenValidationErrorCategory::IdentityProvider + } + Self::Other(_) => TokenValidationErrorCategory::Internal, + } + } +} + // A token signer is responsible for signing tokens without doing any validation. pub trait TokenSigner: Sync + Send { // Serialize the given claims and sign a JWT token with them as the payload. @@ -158,7 +193,7 @@ impl TokenValidator for DecodingKey { let data = decode::(token, self, &validation)?; let claims = data.claims; - claims.try_into().map_err(TokenValidationError::Other) + claims.try_into().map_err(TokenValidationError::InvalidClaims) } } @@ -170,7 +205,7 @@ impl TokenValidator for BasicTokenValidator { if let Some(expected_issuer) = &self.issuer && *claims.issuer != **expected_issuer { - return Err(TokenValidationError::Other(anyhow::anyhow!( + return Err(TokenValidationError::InvalidClaims(anyhow::anyhow!( "Issuer mismatch: got {:?}, expected {:?}", claims.issuer, expected_issuer @@ -233,7 +268,11 @@ impl TokenValidator for CachingOidcTokenValidator { .cache .get(String::from(raw_issuer.clone()).into()) .await - .ok_or_else(|| anyhow::anyhow!("Error fetching public key for issuer {raw_issuer}"))?; + .ok_or_else(|| { + TokenValidationError::IdentityProviderUnavailable(anyhow::anyhow!( + "Error fetching public key for issuer {raw_issuer}" + )) + })?; validator.validate_token(token).await } } @@ -300,7 +339,7 @@ impl TokenValidator for JwksValidator { log::debug!("No key id in header. Trying all keys."); // TODO: Consider returning an error if no kid is given? // For now, lets just try all the keys. - let mut last_error = TokenValidationError::Other(anyhow::anyhow!("No kid found")); + let mut last_error = TokenValidationError::InvalidClaims(anyhow::anyhow!("No kid found")); for (kid, key) in &self.keyset.keys { log::debug!("Trying key {kid}"); let validator = BasicTokenValidator { @@ -328,7 +367,7 @@ mod tests { use crate::auth::identity::{IncomingClaims, SpacetimeIdentityClaims}; use crate::auth::token_validation::{ BasicTokenValidator, CachingOidcTokenValidator, FullTokenValidator, OidcTokenValidator, TokenSigner, - TokenValidator, + TokenValidationError, TokenValidationErrorCategory, TokenValidator, }; use crate::auth::JwtKeys; use base64::Engine; @@ -336,6 +375,23 @@ mod tests { use serde_json; use spacetimedb_lib::Identity; + #[test] + fn token_validation_error_categories_distinguish_authentication_failures() { + assert_eq!( + TokenValidationError::KeyIDNotFound.category(), + TokenValidationErrorCategory::InvalidCredentials + ); + assert_eq!( + TokenValidationError::IdentityProviderUnavailable(anyhow::anyhow!("controlled provider failure")) + .category(), + TokenValidationErrorCategory::IdentityProvider + ); + assert_eq!( + TokenValidationError::Other(anyhow::anyhow!("controlled internal failure")).category(), + TokenValidationErrorCategory::Internal + ); + } + #[tokio::test] async fn test_local_validator_checks_issuer() -> anyhow::Result<()> { // Test that the issuer must match the expected issuer for LocalTokenValidator. diff --git a/crates/pg/src/authentication_logging.rs b/crates/pg/src/authentication_logging.rs new file mode 100644 index 00000000000..22b8f85d733 --- /dev/null +++ b/crates/pg/src/authentication_logging.rs @@ -0,0 +1,129 @@ +use std::fmt::Display; + +#[derive(Clone, Copy, Debug, Eq, PartialEq)] +pub(crate) enum AuthenticationFailureKind { + InvalidCredentials, + IdentityProvider, + Internal, +} + +pub(crate) fn log_authentication_failure(database: &str, kind: AuthenticationFailureKind, err: &impl Display) { + match kind { + AuthenticationFailureKind::InvalidCredentials => { + log::warn!("PG: Authentication failed on database {database}: {err}"); + } + AuthenticationFailureKind::IdentityProvider => { + log::error!("PG: Identity provider failed while authenticating to database {database}: {err}"); + } + AuthenticationFailureKind::Internal => { + log::error!("PG: Internal authentication failure on database {database}: {err}"); + } + } +} + +#[cfg(test)] +fn log_authentication_failure_with_supplied_token( + database: &str, + _supplied_token: &str, + kind: AuthenticationFailureKind, + err: &impl Display, +) { + log_authentication_failure(database, kind, err); +} + +#[cfg(test)] +mod tests { + use super::*; + use log::{Level, LevelFilter, Log, Metadata, Record}; + use std::sync::{Mutex, Once}; + + const SYNTHETIC_TOKEN: &str = "SYNTHETIC_PG_AUTH_TOKEN_DO_NOT_LOG_5696"; + + #[derive(Clone, Debug)] + struct CapturedRecord { + level: Level, + target: String, + message: String, + } + + struct CapturingLogger { + records: Mutex>, + } + + impl Log for CapturingLogger { + fn enabled(&self, _metadata: &Metadata<'_>) -> bool { + true + } + + fn log(&self, record: &Record<'_>) { + self.records + .lock() + .unwrap_or_else(|poisoned| poisoned.into_inner()) + .push(CapturedRecord { + level: record.level(), + target: record.target().to_owned(), + message: record.args().to_string(), + }); + } + + fn flush(&self) {} + } + + static LOGGER: CapturingLogger = CapturingLogger { + records: Mutex::new(Vec::new()), + }; + static INSTALL_LOGGER: Once = Once::new(); + static CAPTURE_LOCK: Mutex<()> = Mutex::new(()); + + fn capture_authentication_failure(kind: AuthenticationFailureKind) -> CapturedRecord { + let _capture_guard = CAPTURE_LOCK.lock().unwrap_or_else(|poisoned| poisoned.into_inner()); + INSTALL_LOGGER.call_once(|| { + log::set_logger(&LOGGER).expect("test logger should only be installed once"); + log::set_max_level(LevelFilter::Trace); + }); + + let mut records = LOGGER.records.lock().unwrap_or_else(|poisoned| poisoned.into_inner()); + records.clear(); + drop(records); + + log_authentication_failure_with_supplied_token( + "synthetic-database", + SYNTHETIC_TOKEN, + kind, + &"controlled authentication failure", + ); + + let records = LOGGER.records.lock().unwrap_or_else(|poisoned| poisoned.into_inner()); + assert_eq!(records.len(), 1, "expected exactly one authentication log record"); + records[0].clone() + } + + fn assert_token_absent(record: &CapturedRecord) { + assert!(!record.message.contains(SYNTHETIC_TOKEN), "token leaked in log message"); + assert!(!record.target.contains(SYNTHETIC_TOKEN), "token leaked in log target"); + } + + #[test] + fn invalid_credentials_are_warned_without_logging_the_token() { + let record = capture_authentication_failure(AuthenticationFailureKind::InvalidCredentials); + + assert_eq!(record.level, Level::Warn); + assert_token_absent(&record); + } + + #[test] + fn identity_provider_failures_are_errors_without_logging_the_token() { + let record = capture_authentication_failure(AuthenticationFailureKind::IdentityProvider); + + assert_eq!(record.level, Level::Error); + assert_token_absent(&record); + } + + #[test] + fn internal_authentication_failures_are_errors_without_logging_the_token() { + let record = capture_authentication_failure(AuthenticationFailureKind::Internal); + + assert_eq!(record.level, Level::Error); + assert_token_absent(&record); + } +} diff --git a/crates/pg/src/lib.rs b/crates/pg/src/lib.rs index c4466bbc50d..6e009b7760b 100644 --- a/crates/pg/src/lib.rs +++ b/crates/pg/src/lib.rs @@ -1,2 +1,3 @@ +mod authentication_logging; mod encoder; pub mod pg_server; diff --git a/crates/pg/src/pg_server.rs b/crates/pg/src/pg_server.rs index e16f13fdf66..42a6d6a53fc 100644 --- a/crates/pg/src/pg_server.rs +++ b/crates/pg/src/pg_server.rs @@ -23,7 +23,7 @@ use pgwire::messages::startup::Authentication; use pgwire::messages::{PgWireBackendMessage, PgWireFrontendMessage}; use pgwire::tokio::process_socket; use spacetimedb_auth::identity::ConnectionAuthCtx; -use spacetimedb_client_api::auth::validate_token; +use spacetimedb_client_api::auth::{validate_token, TokenValidationError, TokenValidationErrorCategory}; use spacetimedb_client_api::routes::database; use spacetimedb_client_api::routes::database::SqlQueryParams; use spacetimedb_client_api::{Authorization, ControlStateReadAccess, ControlStateWriteAccess, NodeDelegate}; @@ -37,6 +37,8 @@ use thiserror::Error; use tokio::net::TcpListener; use tokio::sync::{Mutex, Notify}; +use crate::authentication_logging::{log_authentication_failure, AuthenticationFailureKind}; + #[derive(Error, Debug)] pub(crate) enum PgError { #[error("(metadata) {0}")] @@ -51,6 +53,14 @@ pub(crate) enum PgError { Other(#[from] anyhow::Error), } +fn authentication_failure_kind(err: &TokenValidationError) -> AuthenticationFailureKind { + match err.category() { + TokenValidationErrorCategory::InvalidCredentials => AuthenticationFailureKind::InvalidCredentials, + TokenValidationErrorCategory::IdentityProvider => AuthenticationFailureKind::IdentityProvider, + TokenValidationErrorCategory::Internal => AuthenticationFailureKind::Internal, + } +} + impl From for PgWireError { fn from(err: PgError) -> Self { if let PgError::Pg(err) = err { @@ -282,10 +292,8 @@ impl claims, Err(err) => { - log::error!( - "PG: Authentication failed for identity `{}` on database {database}: {err}", - pwd.password - ); + let kind = authentication_failure_kind(&err); + log_authentication_failure(&database, kind, &err); let err = ErrorInfo::new("FATAL".to_owned(), "28P01".to_owned(), err.to_string()); return close_client(client, err).await; }