Feature/added logs security

src/GovUK.Dfe.ExternalApplications.Api.Client/Security/AzureBearerTokenHandler.cs

@@ -14,11 +14,60 @@ protected override async Task<HttpResponseMessage> 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;
+        }
     }
 } 

src/GovUK.Dfe.ExternalApplications.Api.Client/Security/CachedInternalUserTokenStore.cs

@@ -19,94 +19,207 @@
 
     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<CachedTokenData>(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
             {
                 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 @@
         {
             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,12 +259,14 @@
         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;
     }
 
     private record CachedTokenData(string Token, DateTime ExpiresAt);