[IDP-1955] Adding logging and tracing for better troubleshooting (#92)

src/Workleap.Authentication.ClientCredentialsGrant.Tests/ClientCredentialsTokenCacheTests.cs

@@ -4,6 +4,7 @@
 using Workleap.Extensions.Http.Authentication.ClientCredentialsGrant;
 using Microsoft.Extensions.Caching.Distributed;
 using Microsoft.Extensions.Caching.Memory;
+using Microsoft.Extensions.Logging.Abstractions;
 using Microsoft.Extensions.Options;
 
 namespace Workleap.Authentication.ClientCredentialsGrant.Tests;
@@ -37,7 +38,7 @@ public ClientCredentialsTokenCacheTests()
         var optionsMonitor = A.Fake<IOptionsMonitor<ClientCredentialsOptions>>();
         A.CallTo(() => optionsMonitor.Get(A<string>._)).ReturnsLazily((string name) => namedOptions.GetOrAdd(name, _ => new ClientCredentialsOptions()));
 
-        this._tokenCache = new ClientCredentialsTokenCache(this._memoryCache, this._distributedCache, this._tokenSerializer, optionsMonitor);
+        this._tokenCache = new ClientCredentialsTokenCache(this._memoryCache, this._distributedCache, this._tokenSerializer, optionsMonitor, new NullLogger<ClientCredentialsTokenCache>());
     }
 
     [Fact]

src/Workleap.Authentication.ClientCredentialsGrant.Tests/ClientCredentialsTokenTests.cs

@@ -0,0 +1,19 @@
+using System.Globalization;
+using Workleap.Extensions.Http.Authentication.ClientCredentialsGrant;
+
+namespace Workleap.Authentication.ClientCredentialsGrant.Tests;
+
+public class ClientCredentialsTokenTests
+{
+    [Theory]
+    [InlineData("2024-01-10", "2024-01-09", 0)]
+    [InlineData("2024-01-10", "2024-01-11", 1)]
+    public void GetTimeToLive_Works(string nowStr, string expirationStr, int expectedTimeToLiveInDays)
+    {
+        var now = DateTimeOffset.ParseExact(nowStr, "yyyy-MM-dd", CultureInfo.InvariantCulture);
+        var expiration = DateTimeOffset.ParseExact(expirationStr, "yyyy-MM-dd", CultureInfo.InvariantCulture);
+
+        var token = new ClientCredentialsToken("dummy", expiration);
+        Assert.Equal(TimeSpan.FromDays(expectedTimeToLiveInDays), token.GetTimeToLive(now));
+    }
+}

src/Workleap.Authentication.ClientCredentialsGrant.Tests/IntegrationTests_Setup.cs

@@ -0,0 +1,206 @@
+using System.Collections.Concurrent;
+using Duende.IdentityServer.Models;
+using Duende.IdentityServer.Stores;
+using Workleap.AspNetCore.Authentication.ClientCredentialsGrant;
+using Workleap.Extensions.Http.Authentication.ClientCredentialsGrant;
+using Microsoft.AspNetCore.Builder;
+using Microsoft.AspNetCore.DataProtection;
+using Microsoft.AspNetCore.Hosting.Server;
+using Microsoft.AspNetCore.TestHost;
+using Microsoft.Extensions.Caching.Distributed;
+using Microsoft.Extensions.DependencyInjection;
+using Microsoft.Extensions.Logging;
+using Secret = Duende.IdentityServer.Models.Secret;
+
+namespace Workleap.Authentication.ClientCredentialsGrant.Tests;
+
+public sealed partial class IntegrationTests
+{
+    private const string InvoicesAudience = "invoices";
+
+    private const string InvoicesReadScope = $"{InvoicesAudience}:read";
+    private const string InvoicesPayScope = $"{InvoicesAudience}:pay";
+
+    private const string InvoicesReadClientId = "invoices_read_client";
+    private const string InvoicesReadClientSecret = "invoices_read_client_secret";
+
+    private const string InvoicesAuthority = "https://identity.local";
+
+    private const string InvoiceReadHttpClientName = "invoices_read_http_client";
+
+    // Tokens will be evicted from cache prior to their expiration
+    private static readonly TimeSpan TokenLifetime = TimeSpan.FromSeconds(12);
+    private static readonly TimeSpan TokenCacheLifetimeBuffer = TimeSpan.FromSeconds(3);
+
+    private WebApplication CreateTestIdentityProvider()
+    {
+        // Define some OAuth 2.0 scopes for fictional invoices access management
+        ApiScope[] identityApiScopes =
+        [
+            new ApiScope(InvoicesReadScope, "Reads your invoices."),
+            new ApiScope(InvoicesPayScope, "Pays your invoices.")
+        ];
+
+        // Define the protected resources, here an invoice API (represents something we want to communicate with)
+        ApiResource[] identityApiResources =
+        [
+            new ApiResource(InvoicesAudience, "Invoice API")
+            {
+                Scopes = [InvoicesReadScope, InvoicesPayScope]
+            }
+        ];
+
+        // Define the OAuth 2.0 clients and the scopes that can be granted
+        Client[] identityOAuthClients =
+        [
+            // This client only allows to read invoices
+            new Client
+            {
+                ClientId = InvoicesReadClientId,
+                ClientSecrets = [new Secret(InvoicesReadClientSecret.Sha256())],
+                AllowedGrantTypes = GrantTypes.ClientCredentials,
+                AllowedScopes = [InvoicesReadScope],
+                AccessTokenLifetime = (int)TokenLifetime.TotalSeconds,
+            }
+        ];
+
+        // Build a real but in-memory ASP.NET Core test server that will both act as identity provider (using IdentityServer) and as the protected API that we'll try to access using a authenticated HttpClient
+        var builder = WebApplication.CreateSlimBuilder();
+        builder.WebHost.UseTestServer(x => x.BaseAddress = new Uri(InvoicesAuthority, UriKind.Absolute));
+
+        builder.Logging.SetMinimumLevel(LogLevel.Information);
+        builder.Logging.ClearProviders();
+        builder.Logging.AddProvider(new XunitLoggerProvider(testOutputHelper, "idp"));
+
+        builder.Services.AddDataProtection().UseEphemeralDataProtectionProvider();
+
+        builder.Services.AddIdentityServer()
+            .AddInMemoryClients(identityOAuthClients)
+            .AddInMemoryApiResources(identityApiResources)
+            .AddInMemoryApiScopes(identityApiScopes)
+            .AddSigningKeyStore<InMemorySigningKeyStore>();
+
+        var idp = builder.Build();
+
+        idp.Use(async (context, next) =>
+        {
+            // https://identityserver4.readthedocs.io/en/latest/endpoints/token.html#example
+            const string identityServerTokenEndpoint = "/connect/token";
+
+            if (context.Request.Path == identityServerTokenEndpoint)
+            {
+                Interlocked.Increment(ref this._tokenRequestCount);
+            }
+
+            await next(context);
+        });
+
+        idp.UseIdentityServer();
+
+        return idp;
+    }
+
+    private WebApplication CreateTestApi(CreateApiOptions createApiOptions)
+    {
+        var builder = WebApplication.CreateSlimBuilder();
+        builder.WebHost.UseTestServer();
+
+        builder.Logging.SetMinimumLevel(LogLevel.Debug);
+        builder.Logging.ClearProviders();
+        builder.Logging.AddProvider(new XunitLoggerProvider(testOutputHelper, createApiOptions.AppName));
+
+        builder.Services.AddSingleton<TestServer>(x => (TestServer)x.GetRequiredService<IServer>());
+        builder.Services.AddDataProtection().UseEphemeralDataProtectionProvider();
+
+        // Create the authorization policy that will be used to protect our invoices endpoints
+        builder.Services.AddAuthentication().AddClientCredentials(options =>
+        {
+            options.Audience = InvoicesAudience;
+            options.Authority = InvoicesAuthority;
+            options.Backchannel = createApiOptions.IdentityProvider.GetTestClient();
+        });
+
+        // This invoice authorization policy must be individually applied to endpoints
+        builder.Services.AddClientCredentialsAuthorization();
+
+        // Change the primary HTTP message handler of this library to communicate with the in-memory IDP server
+        builder.Services.AddHttpClient(ClientCredentialsConstants.BackchannelHttpClientName)
+            .ConfigurePrimaryHttpMessageHandler(() => createApiOptions.IdentityProvider.GetTestServer().CreateHandler());
+
+        // Configure the authenticated HttpClient used to communicate with the protected invoices endpoint
+        // Also change the primary HTTP message handler to communicate with this in-memory test server without accessing the network
+        builder.Services.AddHttpClient(InvoiceReadHttpClientName)
+            .ConfigurePrimaryHttpMessageHandler(x => x.GetRequiredService<TestServer>().CreateHandler())
+            .AddClientCredentialsHandler(options =>
+            {
+                options.Authority = InvoicesAuthority;
+                options.ClientId = InvoicesReadClientId;
+                options.ClientSecret = InvoicesReadClientSecret;
+                options.Scope = InvoicesReadScope;
+                options.CacheLifetimeBuffer = TokenCacheLifetimeBuffer;
+                options.EnforceHttps = createApiOptions.EnforceHttps;
+            });
+
+        // Share the same distributed cache among all instances of the test APIs
+        builder.Services.AddSingleton<IDistributedCache>(this._sharedDistributedCache);
+
+        // Here begins ASP.NET Core middleware pipelines registration
+        var api = builder.Build();
+
+        api.UseAuthorization();
+
+        api.MapGet("/anonymous", () => "This endpoint is public")
+            .RequireHost("invoice-app.local");
+
+        api.MapGet("/read-invoices", () => "This protected endpoint is for reading invoices")
+            .RequireAuthorization(ClientCredentialsDefaults.AuthorizationReadPolicy)
+            .RequireHost("invoice-app.local");
+
+        api.MapGet("/pay-invoices", () => "This protected endpoint is for paying invoices")
+            .RequireAuthorization(ClientCredentialsDefaults.AuthorizationWritePolicy)
+            .RequireHost("invoice-app.local");
+
+        api.MapGet("/read-invoices-granular", () => "This protected endpoint is for reading invoices")
+            .RequireClientCredentials("read")
+            .RequireHost("invoice-app.local");
+
+        api.MapGet("/pay-invoices-granular", () => "This protected endpoint is for paying invoices")
+            .RequireClientCredentials("pay")
+            .RequireHost("invoice-app.local");
+
+        return api;
+    }
+
+    // Prevents IdentityServer from using the actual file system to store the signing keys
+    // It also reduces the amount of logs, which makes troubleshooting easier
+    private sealed class InMemorySigningKeyStore : ISigningKeyStore
+    {
+        private readonly ConcurrentDictionary<string, SerializedKey> _keys = new(StringComparer.Ordinal);
+
+        public Task<IEnumerable<SerializedKey>> LoadKeysAsync()
+        {
+            return Task.FromResult(this._keys.Values.ToArray().AsEnumerable());
+        }
+
+        public Task StoreKeyAsync(SerializedKey key)
+        {
+            this._keys[key.Id] = key;
+            return Task.CompletedTask;
+        }
+
+        public Task DeleteKeyAsync(string id)
+        {
+            this._keys.TryRemove(id, out _);
+            return Task.CompletedTask;
+        }
+    }
+
+    private sealed class CreateApiOptions(WebApplication identityProvider)
+    {
+        public WebApplication IdentityProvider { get; } = identityProvider;
+
+        public required string AppName { get; init; }
+
+        public required bool EnforceHttps { get; init; }
+    }
+}

src/Workleap.Authentication.ClientCredentialsGrant.Tests/OpenAPI/OpenApiSecurityDescriptionTests.cs

@@ -1,9 +1,10 @@
 using CliWrap;
+using CliWrap.Buffered;
 using Meziantou.Framework;
 
 namespace Workleap.Authentication.ClientCredentialsGrant.Tests.OpenAPI;
 
-public class OpenApiSecurityDescriptionTests
+public class OpenApiSecurityDescriptionTests(ITestOutputHelper testOutputHelper)
 {
     [Fact]
     public async Task Given_API_With_Client_Credentials_Attribute_When_Generating_OpenAPI_Then_Equal_Expected_Document()
@@ -20,7 +21,11 @@ public async Task Given_API_With_Client_Credentials_Attribute_When_Generating_Op
             .WithWorkingDirectory(projectFolder)
             .WithValidation(CommandResultValidation.None)
             .WithArguments(["build", "--no-incremental"])
-            .ExecuteAsync();
+            .ExecuteBufferedAsync();
+
+        testOutputHelper.WriteLine("Build output:");
+        testOutputHelper.WriteLine(result.StandardError);
+        testOutputHelper.WriteLine(result.StandardOutput);
 
         // Check if the build was successful
         Assert.Equal(0, result.ExitCode);

src/Workleap.Authentication.ClientCredentialsGrant.Tests/Workleap.Authentication.ClientCredentialsGrant.Tests.csproj

@@ -1,6 +1,6 @@
 <Project Sdk="Microsoft.NET.Sdk">
   <PropertyGroup>
-    <TargetFrameworks>net6.0;net8.0</TargetFrameworks>
+    <TargetFramework>net8.0</TargetFramework>
     <IsPackable>false</IsPackable>
     <IsTestProject>true</IsTestProject>
     <SignAssembly>true</SignAssembly>
@@ -18,8 +18,7 @@
     <PackageReference Include="Duende.IdentityServer" Version="6.3.10" />
     <PackageReference Include="FakeItEasy" Version="8.3.0" />
     <PackageReference Include="Meziantou.Framework.FullPath" Version="1.0.13" />
-    <PackageReference Include="Microsoft.AspNetCore.TestHost" Version="6.0.32" Condition=" '$(TargetFramework)' == 'net6.0' " />
-    <PackageReference Include="Microsoft.AspNetCore.TestHost" Version="8.0.7" Condition=" '$(TargetFramework)' == 'net8.0' " />
+    <PackageReference Include="Microsoft.AspNetCore.TestHost" Version="8.0.7" />
     <PackageReference Include="Microsoft.NET.Test.Sdk" Version="17.10.0" />
     <PackageReference Include="xunit" Version="2.9.0" />
     <PackageReference Include="xunit.runner.visualstudio" Version="2.8.2">

src/Workleap.Authentication.ClientCredentialsGrant.Tests/XunitLoggerProvider.cs

@@ -3,26 +3,19 @@
 
 namespace Workleap.Authentication.ClientCredentialsGrant.Tests;
 
-internal sealed class XunitLoggerProvider : ILoggerProvider, ILogger
+internal sealed class XunitLoggerProvider(ITestOutputHelper testOutput, string appName) : ILoggerProvider, ILogger
 {
     private static readonly Dictionary<LogLevel, string> LogLevelStrings = new Dictionary<LogLevel, string>
     {
-        [LogLevel.None] = "NON",
-        [LogLevel.Trace] = "TRC",
-        [LogLevel.Debug] = "DBG",
-        [LogLevel.Information] = "INF",
-        [LogLevel.Warning] = "WRN",
-        [LogLevel.Error] = "ERR",
-        [LogLevel.Critical] = "CRT",
+        [LogLevel.None] = "none",
+        [LogLevel.Trace] = "trce",
+        [LogLevel.Debug] = "dbug",
+        [LogLevel.Information] = "info",
+        [LogLevel.Warning] = "warn",
+        [LogLevel.Error] = "fail",
+        [LogLevel.Critical] = "crit"
     };
 
-    private readonly ITestOutputHelper _output;
-
-    public XunitLoggerProvider(ITestOutputHelper output)
-    {
-        this._output = output;
-    }
-
     public ILogger CreateLogger(string categoryName)
     {
         return this;
@@ -32,7 +25,7 @@ public ILogger CreateLogger(string categoryName)
     public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
     {
         var message = formatter(state, exception);
-        this._output.WriteLine("[{0:HH:mm:ss:ffff} {1}] {2}", DateTime.Now, LogLevelStrings[logLevel], message);
+        testOutput.WriteLine("[{0:HH:mm:ss:ffff} {1} {2}] {3}", DateTime.Now, appName, LogLevelStrings[logLevel], message);
     }
 
     public bool IsEnabled(LogLevel logLevel)
@@ -41,9 +34,7 @@ public bool IsEnabled(LogLevel logLevel)
     }
 
     public IDisposable BeginScope<TState>(TState state)
-#if NET7_0_OR_GREATER
         where TState : notnull
-#endif
     {
         return new NoopDisposable();
     }

src/Workleap.Extensions.Http.Authentication.ClientCredentialsGrant/ClientCredentialsToken.cs

@@ -10,6 +10,16 @@ namespace Workleap.Extensions.Http.Authentication.ClientCredentialsGrant;
 
 internal sealed class ClientCredentialsToken
 {
+    public ClientCredentialsToken()
+    {
+    }
+
+    public ClientCredentialsToken(string accessToken, DateTimeOffset expiration)
+    {
+        this.AccessToken = accessToken;
+        this.Expiration = expiration;
+    }
+
     [JsonPropertyName("accessToken")]
     public string AccessToken { get; init; } = string.Empty;
 
@@ -21,6 +31,12 @@ private bool Equals(ClientCredentialsToken other)
         return this.AccessToken == other.AccessToken && this.Expiration.Equals(other.Expiration);
     }
 
+    public TimeSpan GetTimeToLive(DateTimeOffset now)
+    {
+        var timeToLive = this.Expiration - now;
+        return timeToLive > TimeSpan.Zero ? timeToLive : TimeSpan.Zero;
+    }
+
     public override bool Equals(object? obj)
     {
         return ReferenceEquals(this, obj) || (obj is ClientCredentialsToken other && this.Equals(other));