From 4cc758be2a763098fbace231a700cadd7e8b9f24 Mon Sep 17 00:00:00 2001 From: Richard Beauchamp Date: Sun, 15 Sep 2024 13:30:27 -0700 Subject: [PATCH] chore: enhance logging in WebSocketJwtAuthInterceptor to enable root cause analysis if connections are being rejected --- .github/release-drafter.yml | 20 +++- src/RxDBDotNet/RxDBDotNet.csproj | 5 + .../Security/WebSocketJwtAuthInterceptor.cs | 111 ++++++++++++++++-- 3 files changed, 123 insertions(+), 13 deletions(-) diff --git a/.github/release-drafter.yml b/.github/release-drafter.yml index dda87c3..95fbaba 100644 --- a/.github/release-drafter.yml +++ b/.github/release-drafter.yml @@ -25,6 +25,15 @@ categories: - title: '🧪 Tests' labels: - 'test' + - title: '🏗️ Build' + labels: + - 'build' + - title: '🔄 CI' + labels: + - 'ci' + - title: '↩️ Revert' + labels: + - 'revert' change-template: '- $TITLE @$AUTHOR (#$NUMBER)' change-title-escapes: '\<*_&' # You can add # and @ to disable mentions, and add ` to disable code blocks. version-resolver: @@ -39,7 +48,7 @@ version-resolver: - 'patch' default: patch template: | - ## What’s Changed + ## What's Changed $CHANGES autolabeler: @@ -67,3 +76,12 @@ autolabeler: - label: 'test' title: - '/^test(\([^)]+\))?:/i' + - label: 'build' + title: + - '/^build(\([^)]+\))?:/i' + - label: 'ci' + title: + - '/^ci(\([^)]+\))?:/i' + - label: 'revert' + title: + - '/^revert(\([^)]+\))?:/i' \ No newline at end of file diff --git a/src/RxDBDotNet/RxDBDotNet.csproj b/src/RxDBDotNet/RxDBDotNet.csproj index 2cf8157..d8767ef 100644 --- a/src/RxDBDotNet/RxDBDotNet.csproj +++ b/src/RxDBDotNet/RxDBDotNet.csproj @@ -24,6 +24,7 @@ © $([System.DateTime]::Now.Year) Ziptility and Contributors to the RxDBDotNet Project RxDBDotNet facilitates real-time data replication and synchronization between RxDB clients and .NET backends using GraphQL and Hot Chocolate. rxdb;graphql;replication;offline-first;realtime;dotnet + README.md https://github.com/Ziptility/RxDBDotNet https://github.com/Ziptility/RxDBDotNet.git git @@ -41,6 +42,10 @@ + + + + diff --git a/src/RxDBDotNet/Security/WebSocketJwtAuthInterceptor.cs b/src/RxDBDotNet/Security/WebSocketJwtAuthInterceptor.cs index 6e42158..de9ec0c 100644 --- a/src/RxDBDotNet/Security/WebSocketJwtAuthInterceptor.cs +++ b/src/RxDBDotNet/Security/WebSocketJwtAuthInterceptor.cs @@ -87,14 +87,21 @@ public override async ValueTask OnConnectAsync( ArgumentNullException.ThrowIfNull(session); ArgumentNullException.ThrowIfNull(connectionInitMessage); + _logger.LogInformation("WebSocket connection attempt from {RemoteIpAddress}", session.Connection.HttpContext.Connection.RemoteIpAddress); + _logger.LogDebug("Connection payload: {@Payload}", connectionInitMessage); + try { // Check if JWT Bearer authentication is configured // This allows the middleware to work in both authenticated and non-authenticated setups - if (!await IsJwtBearerConfiguredAsync().ConfigureAwait(false)) + var isJwtConfigured = await IsJwtBearerConfiguredAsync().ConfigureAwait(false); + _logger.LogDebug("JWT Bearer authentication is {ConfigurationStatus}", isJwtConfigured ? "configured" : "not configured"); + + if (!isJwtConfigured) { // If JWT Bearer is not configured, we accept all connections // This is crucial for supporting non-authenticated scenarios + _logger.LogInformation("Accepting connection without authentication as JWT Bearer is not configured"); return ConnectionStatus.Accept(); } @@ -102,19 +109,24 @@ public override async ValueTask OnConnectAsync( var token = ExtractToken(connectionInitMessage); if (string.IsNullOrEmpty(token)) { + _logger.LogWarning("No valid authorization token provided in the connection payload"); return RejectConnection("No valid authorization token provided."); } + _logger.LogDebug("Token extracted from connection payload. Proceeding with validation"); + // Validate the token var claimsPrincipal = await ValidateTokenAsync(token, cancellationToken).ConfigureAwait(false); if (claimsPrincipal == null) { + _logger.LogWarning("Invalid authorization token"); return RejectConnection("Invalid authorization token."); } // If the token is valid, set the ClaimsPrincipal on the HttpContext // This allows the rest of the application to access the authenticated user's claims session.Connection.HttpContext.User = claimsPrincipal; + _logger.LogInformation("Connection authenticated successfully for user {UserId}", claimsPrincipal.FindFirst(ClaimTypes.NameIdentifier)?.Value); return ConnectionStatus.Accept(); } catch (Exception ex) @@ -131,11 +143,13 @@ public override async ValueTask OnConnectAsync( /// /// The connection initialization message. /// The extracted JWT token, or null if no valid token is found. - private static string? ExtractToken(IOperationMessagePayload connectionInitMessage) + private string? ExtractToken(IOperationMessagePayload connectionInitMessage) { var connectPayload = connectionInitMessage.As(); var authorizationHeader = connectPayload?.Headers.Authorization; + _logger.LogDebug("Authorization header {HeaderPresence}", string.IsNullOrEmpty(authorizationHeader) ? "not present" : "present"); + if (string.IsNullOrEmpty(authorizationHeader) || !authorizationHeader.StartsWith(BearerPrefix, StringComparison.OrdinalIgnoreCase)) { return null; @@ -173,27 +187,45 @@ private static ConnectionStatus RejectConnection(string reason) /// private async Task ValidateTokenAsync(string token, CancellationToken cancellationToken) { + _logger.LogDebug("Starting token validation"); + // Retrieve the JWT Bearer options. These options are configured when setting up JWT authentication var jwtBearerOptions = _jwtOptionsMonitor.Get(JwtBearerDefaults.AuthenticationScheme); + _logger.LogDebug("JWT Bearer options retrieved"); // Get the token handler from the options. This is typically a JwtSecurityTokenHandler var tokenHandler = jwtBearerOptions.TokenHandlers.Single(); + _logger.LogDebug("Token handler retrieved: {TokenHandlerType}", tokenHandler.GetType().Name); // Get the token validation parameters from the options var validationParameters = jwtBearerOptions.TokenValidationParameters; + _logger.LogDebug("Token validation parameters retrieved"); + + LogTokenValidationParameters(validationParameters); try { await UpdateValidationParametersAsync(jwtBearerOptions, validationParameters, cancellationToken) .ConfigureAwait(false); + _logger.LogDebug("Validation parameters updated"); // Validate the token using the configured parameters // This step performs the actual cryptographic verification of the token + _logger.LogDebug("Validating token"); var tokenValidationResult = await tokenHandler .ValidateTokenAsync(token, validationParameters) .ConfigureAwait(false); - return tokenValidationResult.IsValid ? new ClaimsPrincipal(tokenValidationResult.ClaimsIdentity) : null; + if (tokenValidationResult.IsValid) + { + _logger.LogInformation("Token validated successfully"); + return new ClaimsPrincipal(tokenValidationResult.ClaimsIdentity); + } + + _logger.LogWarning("Token validation failed. Error: {Error}. Exception details: {@Exception}", + tokenValidationResult.Exception?.Message, + tokenValidationResult.Exception); + return null; } catch (Exception ex) { @@ -204,6 +236,29 @@ await UpdateValidationParametersAsync(jwtBearerOptions, validationParameters, ca } } + private void LogTokenValidationParameters(TokenValidationParameters validationParameters) + { + _logger.LogDebug("Token validation parameters: " + + "ValidateIssuer = {ValidateIssuer}, " + + "ValidIssuers = {ValidIssuers}, " + + "ValidateAudience = {ValidateAudience}, " + + "ValidAudiences = {ValidAudiences}, " + + "ValidateLifetime = {ValidateLifetime}, " + + "RequireExpirationTime = {RequireExpirationTime}, " + + "ClockSkew = {ClockSkew}, " + + "ValidateIssuerSigningKey = {ValidateIssuerSigningKey}, " + + "SignatureValidationKeysAvailable = {SignatureValidationKeysAvailable}", + validationParameters.ValidateIssuer, + validationParameters.ValidIssuers != null ? string.Join(", ", validationParameters.ValidIssuers) : "null", + validationParameters.ValidateAudience, + validationParameters.ValidAudiences != null ? string.Join(", ", validationParameters.ValidAudiences) : "null", + validationParameters.ValidateLifetime, + validationParameters.RequireExpirationTime, + validationParameters.ClockSkew, + validationParameters.ValidateIssuerSigningKey, + validationParameters.IssuerSigningKey != null || (validationParameters.IssuerSigningKeys?.Any() ?? false)); + } + /// /// Updates the token validation parameters with the latest OpenID Connect configuration if necessary. /// @@ -216,26 +271,43 @@ await UpdateValidationParametersAsync(jwtBearerOptions, validationParameters, ca /// This approach ensures that the application always uses the most up-to-date signing keys /// without requiring a restart or manual configuration update. /// - private static async Task UpdateValidationParametersAsync( + private async Task UpdateValidationParametersAsync( JwtBearerOptions jwtBearerOptions, TokenValidationParameters validationParameters, CancellationToken cancellationToken) { + _logger.LogDebug("Current IssuerSigningKeys count: {KeyCount}", validationParameters.IssuerSigningKeys?.Count() ?? 0); + // Check if we need to retrieve the OpenID Connect configuration // This is necessary when: // 1. No issuer signing keys are explicitly configured // 2. A configuration manager is available (typically set up when using OIDC discovery) if (validationParameters.IssuerSigningKeys.IsNullOrEmpty() && jwtBearerOptions.ConfigurationManager != null) { - // Asynchronously retrieve the OpenID Connect configuration - // This typically involves a network call to the OIDC provider's discovery endpoint - var config = await jwtBearerOptions.ConfigurationManager - .GetConfigurationAsync(cancellationToken) - .ConfigureAwait(false); + _logger.LogDebug("Retrieving OpenID Connect configuration"); + try + { + // Asynchronously retrieve the OpenID Connect configuration + // This typically involves a network call to the OIDC provider's discovery endpoint + var config = await jwtBearerOptions.ConfigurationManager + .GetConfigurationAsync(cancellationToken) + .ConfigureAwait(false); // Update the validation parameters with the fetched signing keys // This ensures we're using the most recent keys for token validation - validationParameters.IssuerSigningKeys = config.SigningKeys; + validationParameters.IssuerSigningKeys = config.SigningKeys; + _logger.LogInformation("OpenID Connect configuration retrieved and signing keys updated"); + _logger.LogDebug("Updated IssuerSigningKeys count: {KeyCount}", validationParameters.IssuerSigningKeys?.Count() ?? 0); + } + catch (Exception ex) + { + _logger.LogError(ex, "Failed to retrieve OpenID Connect configuration"); + throw; + } + } + else + { + _logger.LogDebug("Skipping OpenID Connect configuration retrieval: IssuerSigningKeys present or ConfigurationManager not available"); } } @@ -256,17 +328,32 @@ private async Task IsJwtBearerConfiguredAsync() { if (_isJwtBearerConfigured.HasValue) { + _logger.LogDebug("Using cached JWT Bearer configuration status: {IsConfigured}", _isJwtBearerConfigured.Value); return _isJwtBearerConfigured.Value; } if (_schemeProvider == null) { + _logger.LogWarning("Authentication scheme provider is null, considering JWT Bearer as not configured"); _isJwtBearerConfigured = false; return false; } - var scheme = await _schemeProvider.GetSchemeAsync(JwtBearerDefaults.AuthenticationScheme).ConfigureAwait(false); - _isJwtBearerConfigured = scheme != null; + try + { + var scheme = await _schemeProvider.GetSchemeAsync(JwtBearerDefaults.AuthenticationScheme).ConfigureAwait(false); + _isJwtBearerConfigured = scheme != null; + _logger.LogInformation("JWT Bearer authentication scheme {SchemeStatus}", _isJwtBearerConfigured.Value ? "found" : "not found"); + + var allSchemes = await _schemeProvider.GetAllSchemesAsync().ConfigureAwait(false); + _logger.LogDebug("All authentication schemes: {@Schemes}", allSchemes.Select(s => s.Name)); + } + catch (Exception ex) + { + _logger.LogError(ex, "Error occurred while checking JWT Bearer configuration"); + _isJwtBearerConfigured = false; + } + return _isJwtBearerConfigured.Value; } }