Merge pull request #138 from DuendeSoftware/brock/logging

Add more debug logging where appropriate
DuendeSoftware · Sep 25, 2022 · 1316f1c · 1316f1c
2 parents ee9be8b + f009311
commit 1316f1c
Show file tree

Hide file tree

Showing 10 changed files with 112 additions and 30 deletions.
diff --git a/samples/JS6.EF/wwwroot/index.html b/samples/JS6.EF/wwwroot/index.html
@@ -9,7 +9,7 @@
 <body>
     <div class="container">
         <header class="page-header">
-            <h1>SPA (.NET 5 host w/ EntityFramework)</h1>
+            <h1>SPA (w/ EntityFramework)</h1>
         </header>
 
         <div class="row">

diff --git a/src/Duende.Bff.EntityFramework/Store/UserSessionStore.cs b/src/Duende.Bff.EntityFramework/Store/UserSessionStore.cs
@@ -40,6 +40,8 @@ public UserSessionStore(IOptions<DataProtectionOptions> options, ISessionDbConte
     /// <inheritdoc/>
     public async Task CreateUserSessionAsync(UserSession session, CancellationToken cancellationToken)
     {
+        _logger.LogDebug("Creating user session record in store for sub {sub} sid {sid}", session.SubjectId, session.SessionId);
+
         var item = new UserSessionEntity()
         {
             ApplicationName = _applicationDiscriminator
@@ -65,6 +67,8 @@ public async Task DeleteUserSessionAsync(string key, CancellationToken cancellat
 
         if (item != null)
         {
+            _logger.LogDebug("Deleting user session record in store for sub {sub} sid {sid}", item.SubjectId, item.SessionId);
+
             _sessionDbContext.UserSessions.Remove(item);
             try
             {
@@ -114,6 +118,8 @@ public async Task DeleteUserSessionsAsync(UserSessionsFilter filter, Cancellatio
             items = items.Where(x => x.SessionId == filter.SessionId).ToArray();
         }
 
+        _logger.LogDebug("Deleting {count} user session(s) from store for sub {sub} sid {sid}", items.Length, filter.SubjectId, filter.SessionId);
+
         _sessionDbContext.UserSessions.RemoveRange(items);
 
         try
@@ -143,6 +149,8 @@ public async Task<UserSession> GetUserSessionAsync(string key, CancellationToken
         UserSession result = null;
         if (item != null)
         {
+            _logger.LogDebug("Getting user session record from store for sub {sub} sid {sid}", item.SubjectId, item.SessionId);
+
             result = new UserSession();
             item.CopyTo(result);
         }
@@ -179,12 +187,16 @@ public async Task<IReadOnlyCollection<UserSession>> GetUserSessionsAsync(UserSes
             items = items.Where(x => x.SessionId == filter.SessionId).ToArray();
         }
 
-        return items.Select(x =>
+        var results = items.Select(x =>
         {
             var item = new UserSession();
             x.CopyTo(item);
             return item;
         }).ToArray();
+
+        _logger.LogDebug("Getting {count} user session(s) from store for sub {sub} sid {sid}", results.Length, filter.SubjectId, filter.SessionId);
+
+        return results;
     }
 
     /// <inheritdoc/>
@@ -194,6 +206,8 @@ public async Task UpdateUserSessionAsync(string key, UserSessionUpdate session,
         var item = items.SingleOrDefault(x => x.Key == key && x.ApplicationName == _applicationDiscriminator);
         if (item != null)
         {
+            _logger.LogDebug("Updating user session record in store for sub {sub} sid {sid}", item.SubjectId, item.SessionId);
+
             session.CopyTo(item);
             await _sessionDbContext.SaveChangesAsync(cancellationToken);
         }

diff --git a/src/Duende.Bff/EndpointServices/BackchannelLogout/DefaultBackchannelLogoutService.cs b/src/Duende.Bff/EndpointServices/BackchannelLogout/DefaultBackchannelLogoutService.cs
@@ -66,6 +66,8 @@ public DefaultBackchannelLogoutService(
     /// <inheritdoc />
     public virtual async Task ProcessRequestAsync(HttpContext context)
     {
+        Logger.LogDebug("Processing back-channel logout request");
+
         context.Response.Headers.Add("Cache-Control", "no-cache, no-store");
         context.Response.Headers.Add("Pragma", "no-cache");
 
@@ -120,8 +122,13 @@ await UserSession.RevokeSessionsAsync(new UserSessionsFilter
         var claims = await ValidateJwt(logoutToken);
         if (claims == null)
         {
+            Logger.LogDebug("No claims in back-channel JWT");
             return null;
         }
+        else
+        {
+            Logger.LogTrace("Claims found in back-channel JWT {claims}", claims.Claims);
+        }
 
         if (claims.FindFirst("sub") == null && claims.FindFirst("sid") == null)
         {
@@ -174,6 +181,7 @@ await UserSession.RevokeSessionsAsync(new UserSessionsFilter
         var result = handler.ValidateToken(jwt, parameters);
         if (result.IsValid)
         {
+            Logger.LogDebug("Back-channel JWT validation successful");
             return result.ClaimsIdentity;
         }
 

diff --git a/src/Duende.Bff/EndpointServices/Login/DefaultLoginService.cs b/src/Duende.Bff/EndpointServices/Login/DefaultLoginService.cs
@@ -3,6 +3,7 @@
 
 using Microsoft.AspNetCore.Authentication;
 using Microsoft.AspNetCore.Http;
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 using System;
 using System.Linq;
@@ -19,26 +20,35 @@ public class DefaultLoginService : ILoginService
     /// The BFF options
     /// </summary>
     protected readonly BffOptions Options;
-    
+
     /// <summary>
     /// The return URL validator
     /// </summary>
     protected readonly IReturnUrlValidator ReturnUrlValidator;
+
+    /// <summary>
+    /// The logger
+    /// </summary>
+    protected readonly ILogger Logger;
 
     /// <summary>
     /// ctor
     /// </summary>
     /// <param name="options"></param>
     /// <param name="returnUrlValidator"></param>
-    public DefaultLoginService(IOptions<BffOptions> options, IReturnUrlValidator returnUrlValidator)
+    /// <param name="logger"></param>
+    public DefaultLoginService(IOptions<BffOptions> options, IReturnUrlValidator returnUrlValidator, ILogger<DefaultLoginService> logger)
     {
         Options = options.Value;
         ReturnUrlValidator = returnUrlValidator;
+        Logger = logger;
     }
 
     /// <inheritdoc />
     public virtual async Task ProcessRequestAsync(HttpContext context)
     {
+        Logger.LogDebug("Processing login request");
+
         context.CheckForBffMiddleware(Options);
 
         var returnUrl = context.Request.Query[Constants.RequestParameters.ReturnUrl].FirstOrDefault();
@@ -68,6 +78,8 @@ public virtual async Task ProcessRequestAsync(HttpContext context)
             RedirectUri = returnUrl
         };
 
+        Logger.LogDebug("Login endpoint triggering Challenge with returnUrl {returnUrl}", returnUrl);
+
         await context.ChallengeAsync(props);
     }
 }
diff --git a/src/Duende.Bff/EndpointServices/Logout/DefaultLogoutService.cs b/src/Duende.Bff/EndpointServices/Logout/DefaultLogoutService.cs
@@ -4,6 +4,7 @@
 using IdentityModel;
 using Microsoft.AspNetCore.Authentication;
 using Microsoft.AspNetCore.Http;
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 using System;
 using System.Linq;
@@ -30,23 +31,35 @@ public class DefaultLogoutService : ILogoutService
     /// The return URL validator
     /// </summary>
     protected readonly IReturnUrlValidator ReturnUrlValidator;
+
+    /// <summary>
+    /// The logger
+    /// </summary>
+    protected readonly ILogger Logger;
 
     /// <summary>
     /// Ctor
     /// </summary>
     /// <param name="options"></param>
     /// <param name="authenticationAuthenticationSchemeProviderProvider"></param>
     /// <param name="returnUrlValidator"></param>
-    public DefaultLogoutService(IOptions<BffOptions> options, IAuthenticationSchemeProvider authenticationAuthenticationSchemeProviderProvider, IReturnUrlValidator returnUrlValidator)
+    /// <param name="logger"></param>
+    public DefaultLogoutService(IOptions<BffOptions> options, 
+        IAuthenticationSchemeProvider authenticationAuthenticationSchemeProviderProvider, 
+        IReturnUrlValidator returnUrlValidator,
+        ILogger<DefaultLogoutService> logger)
     {
         Options = options.Value;
         AuthenticationSchemeProvider = authenticationAuthenticationSchemeProviderProvider;
         ReturnUrlValidator = returnUrlValidator;
+        Logger = logger;
     }
 
     /// <inheritdoc />
     public virtual async Task ProcessRequestAsync(HttpContext context)
     {
+        Logger.LogDebug("Processing logout request");
+
         context.CheckForBffMiddleware(Options);
 
         var result = await context.AuthenticateAsync();
@@ -66,12 +79,7 @@ public virtual async Task ProcessRequestAsync(HttpContext context)
             }
         }
 
-        // get rid of local cookie first
-        var signInScheme = await AuthenticationSchemeProvider.GetDefaultSignInSchemeAsync();
-        await context.SignOutAsync(signInScheme?.Name);
-
         var returnUrl = context.Request.Query[Constants.RequestParameters.ReturnUrl].FirstOrDefault();
-
         if (!string.IsNullOrWhiteSpace(returnUrl))
         {
             if (!await ReturnUrlValidator.IsValidAsync(returnUrl))
@@ -80,6 +88,10 @@ public virtual async Task ProcessRequestAsync(HttpContext context)
             }
         }
 
+        // get rid of local cookie first
+        var signInScheme = await AuthenticationSchemeProvider.GetDefaultSignInSchemeAsync();
+        await context.SignOutAsync(signInScheme?.Name);
+
         if (String.IsNullOrWhiteSpace(returnUrl))
         {
             if (context.Request.PathBase.HasValue)
@@ -97,6 +109,8 @@ public virtual async Task ProcessRequestAsync(HttpContext context)
             RedirectUri = returnUrl
         };
 
+        Logger.LogDebug("Logout endpoint triggering SignOut with returnUrl {returnUrl}", returnUrl);
+
         // trigger idp logout
         await context.SignOutAsync(props);
     }

diff --git a/src/Duende.Bff/EndpointServices/SilentLogin/DefaultSilentLoginCallbackService.cs b/src/Duende.Bff/EndpointServices/SilentLogin/DefaultSilentLoginCallbackService.cs
@@ -4,6 +4,7 @@
 using IdentityModel;
 using Microsoft.AspNetCore.Authentication;
 using Microsoft.AspNetCore.Http;
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 using System.Text;
 using System.Threading.Tasks;
@@ -15,21 +16,33 @@ namespace Duende.Bff;
 /// </summary>
 public class DefaultSilentLoginCallbackService : ISilentLoginCallbackService
 {
-    private readonly BffOptions _options;
+    /// <summary>
+    /// The BFF options
+    /// </summary>
+    protected readonly BffOptions Options;
+
+    /// <summary>
+    /// The logger
+    /// </summary>
+    protected readonly ILogger Logger;
 
     /// <summary>
     /// ctor
     /// </summary>
     /// <param name="options"></param>
-    public DefaultSilentLoginCallbackService(IOptions<BffOptions> options)
+    /// <param name="logger"></param>
+    public DefaultSilentLoginCallbackService(IOptions<BffOptions> options, ILogger<DefaultSilentLoginCallbackService> logger)
     {
-        _options = options.Value;
+        Options = options.Value;
+        Logger = logger;
     }
 
     /// <inheritdoc />
-    public async Task ProcessRequestAsync(HttpContext context)
+    public virtual async Task ProcessRequestAsync(HttpContext context)
     {
-        context.CheckForBffMiddleware(_options);
+        Logger.LogDebug("Processing silent login callback request");
+
+        context.CheckForBffMiddleware(Options);
 
         var result = (await context.AuthenticateAsync()).Succeeded ? "true" : "false";
         var json = $"{{source:'bff-silent-login', isLoggedIn:{result}}}";
@@ -46,6 +59,8 @@ public async Task ProcessRequestAsync(HttpContext context)
         context.Response.Headers["Cache-Control"] = "no-store, no-cache, max-age=0";
         context.Response.Headers["Pragma"] = "no-cache";
 
+        Logger.LogDebug("Silent login endpoint rendering HTML with JS postMessage to origin {origin} with isLoggedIn {isLoggedIn}", origin, result);
+
         await context.Response.WriteAsync(html, Encoding.UTF8);
     }
 }
diff --git a/src/Duende.Bff/EndpointServices/SilentLogin/DefaultSilentLoginService.cs b/src/Duende.Bff/EndpointServices/SilentLogin/DefaultSilentLoginService.cs
@@ -3,6 +3,7 @@
 
 using Microsoft.AspNetCore.Authentication;
 using Microsoft.AspNetCore.Http;
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 using System.Threading.Tasks;
 
@@ -13,24 +14,36 @@ namespace Duende.Bff;
 /// </summary>
 public class DefaultSilentLoginService : ISilentLoginService
 {
-    private readonly BffOptions _options;
+    /// <summary>
+    /// The BFF options
+    /// </summary>
+    protected readonly BffOptions Options;
+
+    /// <summary>
+    /// The logger
+    /// </summary>
+    protected readonly ILogger Logger;
 
     /// <summary>
     /// ctor
     /// </summary>
     /// <param name="options"></param>
-    public DefaultSilentLoginService(IOptions<BffOptions> options)
+    /// <param name="logger"></param>
+    public DefaultSilentLoginService(IOptions<BffOptions> options, ILogger<DefaultSilentLoginService> logger)
     {
-        _options = options.Value;
+        Options = options.Value;
+        Logger = logger;
     }
 
     /// <inheritdoc />
-    public async Task ProcessRequestAsync(HttpContext context)
+    public virtual async Task ProcessRequestAsync(HttpContext context)
     {
-        context.CheckForBffMiddleware(_options);
+        Logger.LogDebug("Processing silent login request");
+
+        context.CheckForBffMiddleware(Options);
 
         var pathBase = context.Request.PathBase;
-        var redirectPath = pathBase + _options.SilentLoginCallbackPath;
+        var redirectPath = pathBase + Options.SilentLoginCallbackPath;
 
         var props = new AuthenticationProperties
         {
@@ -41,6 +54,8 @@ public async Task ProcessRequestAsync(HttpContext context)
             },
         };
 
+        Logger.LogDebug("Silent login endpoint triggering Challenge with returnUrl {redirectUri}", redirectPath);
+
         await context.ChallengeAsync(props);
     }
 }
diff --git a/src/Duende.Bff/EndpointServices/User/DefaultUserService.cs b/src/Duende.Bff/EndpointServices/User/DefaultUserService.cs
@@ -47,6 +47,8 @@ public DefaultUserService(IOptions<BffOptions> options, ILoggerFactory loggerFac
     /// <inheritdoc />
     public virtual async Task ProcessRequestAsync(HttpContext context)
     {
+        Logger.LogDebug("Processing user request");
+
         context.CheckForBffMiddleware(Options);
 
         var result = await context.AuthenticateAsync();
@@ -63,6 +65,8 @@ public virtual async Task ProcessRequestAsync(HttpContext context)
             {
                 context.Response.StatusCode = 401;
             }
+
+            Logger.LogDebug("User endpoint indicates the user is not logged in, using status code {code}", context.Response.StatusCode);
         }
         else
         {
@@ -75,6 +79,8 @@ public virtual async Task ProcessRequestAsync(HttpContext context)
             context.Response.StatusCode = 200;
             context.Response.ContentType = "application/json";
             await context.Response.WriteAsync(json, Encoding.UTF8);
+
+            Logger.LogTrace("User endpoint indicates the user is logged in with claims {claims}", claims);
         }
     }