diff --git a/src/GovUK.Dfe.ExternalApplications.Api.Client/Security/AzureBearerTokenHandler.cs b/src/GovUK.Dfe.ExternalApplications.Api.Client/Security/AzureBearerTokenHandler.cs index 5bb8d117..422e8bd5 100644 --- a/src/GovUK.Dfe.ExternalApplications.Api.Client/Security/AzureBearerTokenHandler.cs +++ b/src/GovUK.Dfe.ExternalApplications.Api.Client/Security/AzureBearerTokenHandler.cs @@ -14,11 +14,60 @@ protected override async Task SendAsync( HttpRequestMessage request, CancellationToken cancellationToken) { - // Always use Azure token for tokens client authentication - logger.LogDebug("Getting Azure token for tokens client authentication"); - var azureToken = await tokenAcquisitionService.GetTokenAsync(); - request.Headers.Authorization = new AuthenticationHeaderValue("Bearer", azureToken); - - return await base.SendAsync(request, cancellationToken); + logger.LogDebug(">>>>>>>>>> Authentication >>> AzureBearerTokenHandler.SendAsync called for request: {Method} {Uri}", + request.Method, request.RequestUri); + + try + { + // Always use Azure token for tokens client authentication + logger.LogDebug(">>>>>>>>>> Authentication >>> Getting Azure token for tokens client authentication"); + + var azureToken = await tokenAcquisitionService.GetTokenAsync(); + + if (string.IsNullOrEmpty(azureToken)) + { + logger.LogError(">>>>>>>>>> Authentication >>> Azure token acquisition returned null or empty token for request: {Method} {Uri}", + request.Method, request.RequestUri); + throw new InvalidOperationException("Azure token acquisition returned null or empty token"); + } + + logger.LogDebug(">>>>>>>>>> Authentication >>> Azure token acquired successfully, length: {TokenLength} chars", + azureToken.Length); + + request.Headers.Authorization = new AuthenticationHeaderValue("Bearer", azureToken); + + logger.LogDebug(">>>>>>>>>> Authentication >>> Authorization header set with Azure Bearer token for request: {Method} {Uri}", + request.Method, request.RequestUri); + + var response = await base.SendAsync(request, cancellationToken); + + logger.LogInformation(">>>>>>>>>> Authentication >>> Request completed with status: {StatusCode} for {Method} {Uri}", + response.StatusCode, request.Method, request.RequestUri); + + if (!response.IsSuccessStatusCode) + { + logger.LogWarning(">>>>>>>>>> Authentication >>> Request failed with status: {StatusCode} {ReasonPhrase} for {Method} {Uri}", + response.StatusCode, response.ReasonPhrase, request.Method, request.RequestUri); + + if (response.StatusCode == System.Net.HttpStatusCode.Unauthorized) + { + logger.LogError(">>>>>>>>>> Authentication >>> 401 Unauthorized response received - Azure token may be invalid or expired for {Method} {Uri}", + request.Method, request.RequestUri); + } + else if (response.StatusCode == System.Net.HttpStatusCode.Forbidden) + { + logger.LogError(">>>>>>>>>> Authentication >>> 403 Forbidden response received - Azure token may lack required permissions for {Method} {Uri}", + request.Method, request.RequestUri); + } + } + + return response; + } + catch (Exception ex) + { + logger.LogError(ex, ">>>>>>>>>> Authentication >>> Exception in AzureBearerTokenHandler for request: {Method} {Uri}", + request.Method, request.RequestUri); + throw; + } } } \ No newline at end of file diff --git a/src/GovUK.Dfe.ExternalApplications.Api.Client/Security/CachedInternalUserTokenStore.cs b/src/GovUK.Dfe.ExternalApplications.Api.Client/Security/CachedInternalUserTokenStore.cs index 0105f4da..f8d9a4ff 100644 --- a/src/GovUK.Dfe.ExternalApplications.Api.Client/Security/CachedInternalUserTokenStore.cs +++ b/src/GovUK.Dfe.ExternalApplications.Api.Client/Security/CachedInternalUserTokenStore.cs @@ -19,67 +19,137 @@ public class CachedInternalUserTokenStore( public string? GetToken() { + logger.LogDebug(">>>>>>>>>> Authentication >>> GetToken called"); + var ctx = httpContextAccessor.HttpContext; - if (ctx == null) return null; + if (ctx == null) + { + logger.LogWarning(">>>>>>>>>> Authentication >>> HttpContext is null in GetToken"); + return null; + } + logger.LogDebug(">>>>>>>>>> Authentication >>> Checking HttpContext.Items for cached token"); + // First check HttpContext.Items for this request if (ctx.Items.TryGetValue(TokenKey, out var tokenObj) && tokenObj is string requestToken) { + logger.LogDebug(">>>>>>>>>> Authentication >>> Found token in HttpContext.Items, length: {TokenLength} chars", + requestToken.Length); + if (IsTokenValid(requestToken)) { + logger.LogDebug(">>>>>>>>>> Authentication >>> HttpContext.Items token is valid, returning it"); return requestToken; } + + logger.LogDebug(">>>>>>>>>> Authentication >>> HttpContext.Items token is invalid, removing it"); ctx.Items.Remove(TokenKey); } + else + { + logger.LogDebug(">>>>>>>>>> Authentication >>> No token found in HttpContext.Items"); + } // Then check distributed cache + logger.LogDebug(">>>>>>>>>> Authentication >>> Checking distributed cache for token"); + var userId = GetUserIdFromContext(ctx); if (userId != null) { + logger.LogDebug(">>>>>>>>>> Authentication >>> User ID identified as: {UserId}", userId); + var cacheKey = $"{CacheKeyPrefix}{userId}"; + logger.LogDebug(">>>>>>>>>> Authentication >>> Looking up token in distributed cache with key: {CacheKey}", cacheKey); + var cachedTokenJson = distributedCache.GetString(cacheKey); if (!string.IsNullOrEmpty(cachedTokenJson)) { + logger.LogDebug(">>>>>>>>>> Authentication >>> Found cached token JSON in distributed cache, length: {JsonLength} chars", + cachedTokenJson.Length); + try { var cachedToken = JsonSerializer.Deserialize(cachedTokenJson); - if (cachedToken != null && IsTokenValid(cachedToken.Token)) + if (cachedToken != null) { - // Store in HttpContext.Items for subsequent requests in this request - ctx.Items[TokenKey] = cachedToken.Token; - return cachedToken.Token; + logger.LogDebug(">>>>>>>>>> Authentication >>> Successfully deserialized cached token, expires at: {ExpiresAt}", + cachedToken.ExpiresAt); + + if (IsTokenValid(cachedToken.Token)) + { + logger.LogDebug(">>>>>>>>>> Authentication >>> Cached token is valid, storing in HttpContext.Items and returning it"); + // Store in HttpContext.Items for subsequent requests in this request + ctx.Items[TokenKey] = cachedToken.Token; + return cachedToken.Token; + } + else + { + logger.LogDebug(">>>>>>>>>> Authentication >>> Cached token is invalid/expired, removing from cache"); + // Remove expired token from cache + distributedCache.Remove(cacheKey); + } } else { - // Remove expired token from cache + logger.LogWarning(">>>>>>>>>> Authentication >>> Deserialization returned null for cached token, removing from cache"); distributedCache.Remove(cacheKey); } } catch (JsonException ex) { - logger.LogWarning(ex, "Failed to deserialize cached token for user {UserId}", userId); + logger.LogWarning(ex, ">>>>>>>>>> Authentication >>> Failed to deserialize cached token for user {UserId}, removing from cache", userId); distributedCache.Remove(cacheKey); } } + else + { + logger.LogDebug(">>>>>>>>>> Authentication >>> No cached token found in distributed cache for user: {UserId}", userId); + } + } + else + { + logger.LogDebug(">>>>>>>>>> Authentication >>> Could not identify user ID from context - User.Identity.IsAuthenticated: {IsAuthenticated}", + ctx.User?.Identity?.IsAuthenticated); } + logger.LogDebug(">>>>>>>>>> Authentication >>> No valid token found in any cache location, returning null"); return null; } public void SetToken(string token) { + logger.LogDebug(">>>>>>>>>> Authentication >>> SetToken called with token length: {TokenLength} chars", token?.Length ?? 0); + + if (string.IsNullOrEmpty(token)) + { + logger.LogWarning(">>>>>>>>>> Authentication >>> SetToken called with null or empty token"); + return; + } + var ctx = httpContextAccessor.HttpContext; - if (ctx == null) return; + if (ctx == null) + { + logger.LogWarning(">>>>>>>>>> Authentication >>> HttpContext is null in SetToken"); + return; + } + logger.LogDebug(">>>>>>>>>> Authentication >>> Storing token in HttpContext.Items"); ctx.Items[TokenKey] = token; // Store in distributed cache for future requests var userId = GetUserIdFromContext(ctx); if (userId != null) { + logger.LogDebug(">>>>>>>>>> Authentication >>> User ID identified for caching: {UserId}", userId); + var cacheKey = $"{CacheKeyPrefix}{userId}"; - var tokenData = new CachedTokenData(token, GetTokenExpiry(token)); + var tokenExpiry = GetTokenExpiry(token); + var tokenData = new CachedTokenData(token, tokenExpiry); + + logger.LogDebug(">>>>>>>>>> Authentication >>> Token expires at: {ExpiryTime}, caching until: {CacheUntil}", + tokenExpiry, tokenExpiry.Subtract(CacheBuffer)); + var tokenJson = JsonSerializer.Serialize(tokenData); var cacheOptions = new DistributedCacheEntryOptions @@ -87,26 +157,69 @@ public void SetToken(string token) AbsoluteExpiration = tokenData.ExpiresAt.Subtract(CacheBuffer) }; - distributedCache.SetString(cacheKey, tokenJson, cacheOptions); - logger.LogDebug("Internal token cached for user {UserId} until {ExpiryTime}", userId, cacheOptions.AbsoluteExpiration); + try + { + distributedCache.SetString(cacheKey, tokenJson, cacheOptions); + logger.LogInformation(">>>>>>>>>> Authentication >>> Internal token cached for user {UserId} until {ExpiryTime}", + userId, cacheOptions.AbsoluteExpiration); + } + catch (Exception ex) + { + logger.LogError(ex, ">>>>>>>>>> Authentication >>> Failed to cache token for user {UserId}", userId); + } + } + else + { + logger.LogWarning(">>>>>>>>>> Authentication >>> Could not identify user ID for token caching"); } } public void ClearToken() { + logger.LogDebug(">>>>>>>>>> Authentication >>> ClearToken called"); + var ctx = httpContextAccessor.HttpContext; - if (ctx == null) return; + if (ctx == null) + { + logger.LogWarning(">>>>>>>>>> Authentication >>> HttpContext is null in ClearToken"); + return; + } // Clear from HttpContext.Items + logger.LogDebug(">>>>>>>>>> Authentication >>> Clearing token from HttpContext.Items"); + var wasInItems = ctx.Items.ContainsKey(TokenKey); ctx.Items.Remove(TokenKey); + + if (wasInItems) + { + logger.LogDebug(">>>>>>>>>> Authentication >>> Token removed from HttpContext.Items"); + } + else + { + logger.LogDebug(">>>>>>>>>> Authentication >>> No token found in HttpContext.Items to remove"); + } // Clear from distributed cache var userId = GetUserIdFromContext(ctx); if (userId != null) { + logger.LogDebug(">>>>>>>>>> Authentication >>> Clearing token from distributed cache for user: {UserId}", userId); + var cacheKey = $"{CacheKeyPrefix}{userId}"; - distributedCache.Remove(cacheKey); - logger.LogDebug("Cleared internal token cache for user {UserId}", userId); + + try + { + distributedCache.Remove(cacheKey); + logger.LogInformation(">>>>>>>>>> Authentication >>> Cleared internal token cache for user {UserId}", userId); + } + catch (Exception ex) + { + logger.LogError(ex, ">>>>>>>>>> Authentication >>> Failed to clear token cache for user {UserId}", userId); + } + } + else + { + logger.LogDebug(">>>>>>>>>> Authentication >>> Could not identify user ID for cache clearing"); } } @@ -116,7 +229,8 @@ private static bool IsTokenValid(string token) { var handler = new JwtSecurityTokenHandler(); var jwt = handler.ReadJwtToken(token); - return jwt.ValidTo > DateTime.UtcNow.AddMinutes(1); + var isValid = jwt.ValidTo > DateTime.UtcNow.AddMinutes(1); + return isValid; } catch { @@ -145,10 +259,12 @@ private static DateTime GetTokenExpiry(string token) if (user?.Identity?.IsAuthenticated == true) { // Try different claim types that might identify the user - return user.FindFirst("appid")?.Value ?? - user.FindFirst("azp")?.Value ?? - user.FindFirst(ClaimTypes.Email)?.Value ?? - user.FindFirst(ClaimTypes.NameIdentifier)?.Value; + var userId = user.FindFirst("appid")?.Value ?? + user.FindFirst("azp")?.Value ?? + user.FindFirst(ClaimTypes.Email)?.Value ?? + user.FindFirst(ClaimTypes.NameIdentifier)?.Value; + + return userId; } return null; } diff --git a/src/GovUK.Dfe.ExternalApplications.Api.Client/Security/TokenAcquisitionService.cs b/src/GovUK.Dfe.ExternalApplications.Api.Client/Security/TokenAcquisitionService.cs index b6810395..1d320e07 100644 --- a/src/GovUK.Dfe.ExternalApplications.Api.Client/Security/TokenAcquisitionService.cs +++ b/src/GovUK.Dfe.ExternalApplications.Api.Client/Security/TokenAcquisitionService.cs @@ -1,6 +1,7 @@ using System.Diagnostics.CodeAnalysis; using GovUK.Dfe.ExternalApplications.Api.Client.Settings; using Microsoft.Identity.Client; +using Microsoft.Extensions.Logging; namespace GovUK.Dfe.ExternalApplications.Api.Client.Security { @@ -8,25 +9,95 @@ namespace GovUK.Dfe.ExternalApplications.Api.Client.Security public class TokenAcquisitionService : ITokenAcquisitionService { private readonly ApiClientSettings _settings; + private readonly ILogger _logger; private readonly Lazy _app; - public TokenAcquisitionService(ApiClientSettings settings) + public TokenAcquisitionService(ApiClientSettings settings, ILogger logger) { _settings = settings ?? throw new ArgumentNullException(nameof(settings)); + _logger = logger ?? throw new ArgumentNullException(nameof(logger)); + + _logger.LogDebug(">>>>>>>>>> Authentication >>> TokenAcquisitionService constructor called with ClientId: {ClientId}, Authority: {Authority}, Scope: {Scope}", + _settings.ClientId, _settings.Authority, _settings.Scope); _app = new Lazy(() => - ConfidentialClientApplicationBuilder.Create(_settings.ClientId) - .WithClientSecret(_settings.ClientSecret) - .WithAuthority(new Uri(_settings.Authority!)) - .Build()); + { + _logger.LogDebug(">>>>>>>>>> Authentication >>> Creating ConfidentialClientApplication with ClientId: {ClientId}, Authority: {Authority}", + _settings.ClientId, _settings.Authority); + + try + { + var app = ConfidentialClientApplicationBuilder.Create(_settings.ClientId) + .WithClientSecret(_settings.ClientSecret) + .WithAuthority(new Uri(_settings.Authority!)) + .Build(); + + _logger.LogInformation(">>>>>>>>>> Authentication >>> ConfidentialClientApplication created successfully for ClientId: {ClientId}", + _settings.ClientId); + + return app; + } + catch (Exception ex) + { + _logger.LogError(ex, ">>>>>>>>>> Authentication >>> Failed to create ConfidentialClientApplication for ClientId: {ClientId}, Authority: {Authority}", + _settings.ClientId, _settings.Authority); + throw; + } + }); } public async Task GetTokenAsync() { - var authResult = await _app.Value.AcquireTokenForClient(new[] { _settings.Scope }) - .ExecuteAsync(); + _logger.LogDebug(">>>>>>>>>> Authentication >>> GetTokenAsync called for scope: {Scope}", _settings.Scope); + + try + { + _logger.LogDebug(">>>>>>>>>> Authentication >>> Starting token acquisition for ClientId: {ClientId}, Scope: {Scope}", + _settings.ClientId, _settings.Scope); + + var authResult = await _app.Value.AcquireTokenForClient(new[] { _settings.Scope }) + .ExecuteAsync(); + + if (authResult == null) + { + _logger.LogError(">>>>>>>>>> Authentication >>> Token acquisition returned null result for ClientId: {ClientId}, Scope: {Scope}", + _settings.ClientId, _settings.Scope); + throw new InvalidOperationException("Token acquisition returned null result"); + } + + if (string.IsNullOrEmpty(authResult.AccessToken)) + { + _logger.LogError(">>>>>>>>>> Authentication >>> Token acquisition returned empty access token for ClientId: {ClientId}, Scope: {Scope}", + _settings.ClientId, _settings.Scope); + throw new InvalidOperationException("Token acquisition returned empty access token"); + } + + _logger.LogInformation(">>>>>>>>>> Authentication >>> Token acquired successfully for ClientId: {ClientId}, Scope: {Scope}, ExpiresOn: {ExpiresOn}, TokenSource: {TokenSource}", + _settings.ClientId, _settings.Scope, authResult.ExpiresOn, authResult.AuthenticationResultMetadata?.TokenSource); + + _logger.LogDebug(">>>>>>>>>> Authentication >>> Token details - TokenType: {TokenType}, IdToken: {HasIdToken}, Account: {HasAccount}", + authResult.TokenType, !string.IsNullOrEmpty(authResult.IdToken), authResult.Account != null); - return authResult.AccessToken; + return authResult.AccessToken; + } + catch (MsalServiceException ex) + { + _logger.LogError(ex, ">>>>>>>>>> Authentication >>> MSAL Service Exception during token acquisition - ErrorCode: {ErrorCode}, Claims: {Claims}, CorrelationId: {CorrelationId}, ClientId: {ClientId}, Scope: {Scope}", + ex.ErrorCode, ex.Claims, ex.CorrelationId, _settings.ClientId, _settings.Scope); + throw; + } + catch (MsalClientException ex) + { + _logger.LogError(ex, ">>>>>>>>>> Authentication >>> MSAL Client Exception during token acquisition - ErrorCode: {ErrorCode}, ClientId: {ClientId}, Scope: {Scope}", + ex.ErrorCode, _settings.ClientId, _settings.Scope); + throw; + } + catch (Exception ex) + { + _logger.LogError(ex, ">>>>>>>>>> Authentication >>> Unexpected exception during token acquisition for ClientId: {ClientId}, Scope: {Scope}", + _settings.ClientId, _settings.Scope); + throw; + } } } } diff --git a/src/GovUK.Dfe.ExternalApplications.Api.Client/Security/TokenExchangeHandler.cs b/src/GovUK.Dfe.ExternalApplications.Api.Client/Security/TokenExchangeHandler.cs index c61a0178..10f4b5cf 100644 --- a/src/GovUK.Dfe.ExternalApplications.Api.Client/Security/TokenExchangeHandler.cs +++ b/src/GovUK.Dfe.ExternalApplications.Api.Client/Security/TokenExchangeHandler.cs @@ -28,49 +28,214 @@ protected override async Task SendAsync( HttpRequestMessage request, CancellationToken cancellationToken) { + logger.LogDebug(">>>>>>>>>> Authentication >>> TokenExchangeHandler.SendAsync started for request: {Method} {Uri}", + request.Method, request.RequestUri); + var httpContext = httpContextAccessor.HttpContext; + if (httpContext == null) + { + logger.LogError(">>>>>>>>>> Authentication >>> HttpContext is null in TokenExchangeHandler for request: {Method} {Uri}", + request.Method, request.RequestUri); + return UnauthorizedResponse(request); + } + + logger.LogDebug(">>>>>>>>>> Authentication >>> HttpContext available, User.Identity.IsAuthenticated: {IsAuthenticated}, User.Identity.Name: {UserName}", + httpContext.User?.Identity?.IsAuthenticated, httpContext.User?.Identity?.Name); + + // Get initial token status overview + logger.LogInformation(">>>>>>>>>> Authentication >>> ===== TOKEN STATUS OVERVIEW FOR REQUEST: {Method} {Uri} =====", + request.Method, request.RequestUri); + var internalToken = tokenStore.GetToken(); - if (!string.IsNullOrEmpty(internalToken) && IsTokenValid(internalToken)) + logger.LogDebug(">>>>>>>>>> Authentication >>> Retrieved internal token from store, HasToken: {HasToken}", + !string.IsNullOrEmpty(internalToken)); + + // Log internal token expiry if available + if (!string.IsNullOrEmpty(internalToken)) + { + var internalTokenExpiry = GetTokenExpiry(internalToken); + var internalTokenTimeRemaining = internalTokenExpiry - DateTime.UtcNow; + + logger.LogInformation(">>>>>>>>>> Authentication >>> INTERNAL TOKEN EXPIRY: {ExpiryTime} UTC (Time remaining: {TimeRemaining})", + internalTokenExpiry, internalTokenTimeRemaining); + + var isValid = IsTokenValid(internalToken); + logger.LogDebug(">>>>>>>>>> Authentication >>> Internal token validation result: {IsValid}, TokenLength: {TokenLength}", + isValid, internalToken.Length); + + if (isValid) + { + logger.LogInformation(">>>>>>>>>> Authentication >>> Using cached internal token for API request: {Method} {Uri}", + request.Method, request.RequestUri); + + logger.LogInformation(">>>>>>>>>> Authentication >>> ===== USING CACHED TOKEN - NO EXCHANGE NEEDED ====="); + logger.LogInformation(">>>>>>>>>> Authentication >>> CACHED INTERNAL TOKEN EXPIRY: {ExpiryTime} UTC (Time remaining: {TimeRemaining})", + internalTokenExpiry, internalTokenTimeRemaining); + logger.LogInformation(">>>>>>>>>> Authentication >>> ===== PROCEEDING WITH CACHED TOKEN ====="); + + // We have a valid internal token, use it and continue + request.Headers.Authorization = new System.Net.Http.Headers.AuthenticationHeaderValue("Bearer", internalToken); + + var response = await base.SendAsync(request, cancellationToken); + + logger.LogInformation(">>>>>>>>>> Authentication >>> Request with cached token completed with status: {StatusCode} for {Method} {Uri}", + response.StatusCode, request.Method, request.RequestUri); + + if (response.StatusCode == HttpStatusCode.Unauthorized || response.StatusCode == HttpStatusCode.Forbidden) + { + logger.LogWarning(">>>>>>>>>> Authentication >>> Cached token resulted in {StatusCode} - token may be expired or invalid for {Method} {Uri}", + response.StatusCode, request.Method, request.RequestUri); + + // Clear the token and try exchange + tokenStore.ClearToken(); + logger.LogDebug(">>>>>>>>>> Authentication >>> Cleared invalid cached token, attempting token exchange"); + + // Don't return the failed response, continue to token exchange + } + else + { + return response; + } + } + else + { + logger.LogDebug(">>>>>>>>>> Authentication >>> Cached internal token is invalid/expired, clearing and proceeding to exchange"); + tokenStore.ClearToken(); + } + } + else { - logger.LogDebug("Using cached internal token for API request"); - // We have a valid internal token, use it and continue - request.Headers.Authorization = new System.Net.Http.Headers.AuthenticationHeaderValue("Bearer", internalToken); - return await base.SendAsync(request, cancellationToken); + logger.LogDebug(">>>>>>>>>> Authentication >>> No internal token in cache, proceeding to token exchange"); } try { + logger.LogDebug(">>>>>>>>>> Authentication >>> Starting token exchange process for request: {Method} {Uri}", + request.Method, request.RequestUri); + // Get DSI token from authentication context + logger.LogDebug(">>>>>>>>>> Authentication >>> Retrieving DSI id_token from authentication context"); var externalIdpToken = await httpContext?.GetTokenAsync("id_token"); - if (string.IsNullOrEmpty(externalIdpToken) || !IsTokenValid(externalIdpToken)) + + if (string.IsNullOrEmpty(externalIdpToken)) + { + logger.LogError(">>>>>>>>>> Authentication >>> No DSI id_token found in authentication context for user: {UserName}", + httpContext?.User?.Identity?.Name); + return UnauthorizedResponse(request); + } + + logger.LogDebug(">>>>>>>>>> Authentication >>> DSI id_token retrieved, length: {TokenLength} chars", + externalIdpToken.Length); + + // Log ExternalIdpToken (DSI token) expiry + var externalIdpTokenExpiry = GetTokenExpiry(externalIdpToken); + var externalIdpTokenTimeRemaining = externalIdpTokenExpiry - DateTime.UtcNow; + + logger.LogInformation(">>>>>>>>>> Authentication >>> EXTERNAL IDP TOKEN (DSI) EXPIRY: {ExpiryTime} UTC (Time remaining: {TimeRemaining})", + externalIdpTokenExpiry, externalIdpTokenTimeRemaining); + + var isExternalTokenValid = IsTokenValid(externalIdpToken); + logger.LogDebug(">>>>>>>>>> Authentication >>> DSI token validation result: {IsValid}", isExternalTokenValid); + + if (!isExternalTokenValid) { - logger.LogWarning("No valid DSI token found"); + logger.LogWarning(">>>>>>>>>> Authentication >>> DSI id_token is invalid or expired for user: {UserName}", + httpContext?.User?.Identity?.Name); return UnauthorizedResponse(request); } // Azure token (for authorization to call exchange endpoint) + logger.LogDebug(">>>>>>>>>> Authentication >>> Getting Azure token for token exchange endpoint authorization"); var azureToken = await tokenAcquisitionService.GetTokenAsync(); + + if (string.IsNullOrEmpty(azureToken)) + { + logger.LogError(">>>>>>>>>> Authentication >>> Failed to get Azure token for token exchange endpoint"); + return UnauthorizedResponse(request); + } + + logger.LogDebug(">>>>>>>>>> Authentication >>> Azure token acquired for exchange endpoint, length: {TokenLength} chars", + azureToken.Length); + + // Log Azure token expiry + var azureTokenExpiry = GetTokenExpiry(azureToken); + var azureTokenTimeRemaining = azureTokenExpiry - DateTime.UtcNow; + + logger.LogInformation(">>>>>>>>>> Authentication >>> AZURE TOKEN EXPIRY: {ExpiryTime} UTC (Time remaining: {TimeRemaining})", + azureTokenExpiry, azureTokenTimeRemaining); // Call exchange endpoint with DSI token in body + logger.LogInformation(">>>>>>>>>> Authentication >>> Calling token exchange endpoint with DSI token"); var exchangeResult = await tokensClient.ExchangeAndStoreAsync(externalIdpToken, tokenStore, cancellationToken); + if (exchangeResult == null) + { + logger.LogError(">>>>>>>>>> Authentication >>> Token exchange returned null result"); + return UnauthorizedResponse(request); + } + + logger.LogDebug(">>>>>>>>>> Authentication >>> Token exchange completed, HasAccessToken: {HasAccessToken}", + !string.IsNullOrEmpty(exchangeResult.AccessToken)); + if (string.IsNullOrEmpty(exchangeResult.AccessToken)) { - logger.LogDebug("Token exchange returned empty internal token"); + logger.LogError(">>>>>>>>>> Authentication >>> Token exchange returned empty internal token for user: {UserName}", + httpContext?.User?.Identity?.Name); return UnauthorizedResponse(request); } + logger.LogInformation(">>>>>>>>>> Authentication >>> Token exchange successful, new internal token acquired, length: {TokenLength} chars", + exchangeResult.AccessToken.Length); + + // Log newly exchanged OBO token expiry + var newInternalTokenExpiry = GetTokenExpiry(exchangeResult.AccessToken); + var newInternalTokenTimeRemaining = newInternalTokenExpiry - DateTime.UtcNow; + + logger.LogInformation(">>>>>>>>>> Authentication >>> NEW EXCHANGED OBO TOKEN EXPIRY: {ExpiryTime} UTC (Time remaining: {TimeRemaining})", + newInternalTokenExpiry, newInternalTokenTimeRemaining); + // Use the new internal token for the current request request.Headers.Authorization = new System.Net.Http.Headers.AuthenticationHeaderValue("Bearer", exchangeResult.AccessToken); + + logger.LogDebug(">>>>>>>>>> Authentication >>> Authorization header set with new internal token for request: {Method} {Uri}", + request.Method, request.RequestUri); } catch (Exception ex) { - logger.LogError(ex, "Token exchange process failed"); + logger.LogError(ex, ">>>>>>>>>> Authentication >>> Token exchange process failed for request: {Method} {Uri}, User: {UserName}", + request.Method, request.RequestUri, httpContext?.User?.Identity?.Name); return UnauthorizedResponse(request); } - return await base.SendAsync(request, cancellationToken); + logger.LogInformation(">>>>>>>>>> Authentication >>> ===== FINAL TOKEN SUMMARY BEFORE API CALL ====="); + logger.LogInformation(">>>>>>>>>> Authentication >>> Request: {Method} {Uri}", request.Method, request.RequestUri); + logger.LogInformation(">>>>>>>>>> Authentication >>> All token expiry times logged above - check for:"); + logger.LogInformation(">>>>>>>>>> Authentication >>> 1. EXTERNAL IDP TOKEN (DSI) EXPIRY"); + logger.LogInformation(">>>>>>>>>> Authentication >>> 2. AZURE TOKEN EXPIRY"); + logger.LogInformation(">>>>>>>>>> Authentication >>> 3. INTERNAL/OBO TOKEN EXPIRY"); + logger.LogInformation(">>>>>>>>>> Authentication >>> ===== PROCEEDING WITH API CALL ====="); + + logger.LogDebug(">>>>>>>>>> Authentication >>> Sending request with internal token: {Method} {Uri}", + request.Method, request.RequestUri); + + var finalResponse = await base.SendAsync(request, cancellationToken); + + logger.LogInformation(">>>>>>>>>> Authentication >>> Final request completed with status: {StatusCode} for {Method} {Uri}", + finalResponse.StatusCode, request.Method, request.RequestUri); + + if (finalResponse.StatusCode == HttpStatusCode.Unauthorized) + { + logger.LogError(">>>>>>>>>> Authentication >>> 401 Unauthorized after token exchange - internal token may be invalid or user may lack permissions for {Method} {Uri}", + request.Method, request.RequestUri); + } + else if (finalResponse.StatusCode == HttpStatusCode.Forbidden) + { + logger.LogError(">>>>>>>>>> Authentication >>> 403 Forbidden after token exchange - user may lack specific permissions for {Method} {Uri}", + request.Method, request.RequestUri); + } + + return finalResponse; } private static bool IsTokenValid(string token) @@ -79,7 +244,8 @@ private static bool IsTokenValid(string token) { var handler = new JwtSecurityTokenHandler(); var jwt = handler.ReadJwtToken(token); - return jwt.ValidTo > DateTime.UtcNow.Add(ExpiryBuffer); + var isValid = jwt.ValidTo > DateTime.UtcNow.Add(ExpiryBuffer); + return isValid; } catch { @@ -87,6 +253,20 @@ private static bool IsTokenValid(string token) } } + private static DateTime GetTokenExpiry(string token) + { + try + { + var handler = new JwtSecurityTokenHandler(); + var jwt = handler.ReadJwtToken(token); + return jwt.ValidTo; + } + catch + { + return DateTime.UtcNow; // Default fallback for invalid tokens + } + } + private static HttpResponseMessage UnauthorizedResponse(HttpRequestMessage request) { var payload = new ExceptionResponse diff --git a/src/GovUK.Dfe.ExternalApplications.Api.Client/Security/TokenRefreshExtensions.cs b/src/GovUK.Dfe.ExternalApplications.Api.Client/Security/TokenRefreshExtensions.cs index a57b334b..632272bd 100644 --- a/src/GovUK.Dfe.ExternalApplications.Api.Client/Security/TokenRefreshExtensions.cs +++ b/src/GovUK.Dfe.ExternalApplications.Api.Client/Security/TokenRefreshExtensions.cs @@ -1,5 +1,6 @@ using Microsoft.Extensions.DependencyInjection; using Microsoft.AspNetCore.Http; +using Microsoft.Extensions.Logging; namespace GovUK.Dfe.ExternalApplications.Api.Client.Security; @@ -12,9 +13,37 @@ public static class TokenRefreshExtensions public static void ForceTokenRefresh(this IHttpContextAccessor httpContextAccessor) { var httpContext = httpContextAccessor.HttpContext; - if (httpContext == null) return; + + // Get logger factory and create logger with specific category name since this is a static class + var loggerFactory = httpContext?.RequestServices.GetService(); + var logger = loggerFactory?.CreateLogger("GovUK.Dfe.ExternalApplications.Api.Client.Security.TokenRefreshExtensions"); + + logger?.LogInformation(">>>>>>>>>> Authentication >>> ForceTokenRefresh called"); + + if (httpContext == null) + { + logger?.LogWarning(">>>>>>>>>> Authentication >>> HttpContext is null in ForceTokenRefresh"); + return; + } - var tokenStore = httpContext.RequestServices.GetRequiredService(); - tokenStore.ClearToken(); + logger?.LogDebug(">>>>>>>>>> Authentication >>> Getting IInternalUserTokenStore service for token refresh"); + + try + { + var tokenStore = httpContext.RequestServices.GetRequiredService(); + + logger?.LogInformation(">>>>>>>>>> Authentication >>> Clearing token to force refresh for user: {UserName}", + httpContext.User?.Identity?.Name); + + tokenStore.ClearToken(); + + logger?.LogInformation(">>>>>>>>>> Authentication >>> Token refresh completed - next API request will trigger new token exchange"); + } + catch (Exception ex) + { + logger?.LogError(ex, ">>>>>>>>>> Authentication >>> Failed to force token refresh for user: {UserName}", + httpContext.User?.Identity?.Name); + throw; + } } -} \ No newline at end of file +} \ No newline at end of file diff --git a/src/GovUK.Dfe.ExternalApplications.Api.Client/readme.md b/src/GovUK.Dfe.ExternalApplications.Api.Client/readme.md index abba36a4..2cb06bec 100644 --- a/src/GovUK.Dfe.ExternalApplications.Api.Client/readme.md +++ b/src/GovUK.Dfe.ExternalApplications.Api.Client/readme.md @@ -8,7 +8,6 @@ The API Client Library description. ## Key Features - ## Installation To install the API Client Library, use the following command in your .NET project: