diff --git a/.agents/skills/api-conventions/SKILL.md b/.agents/skills/api-conventions/SKILL.md index db582ad..f3fe170 100644 --- a/.agents/skills/api-conventions/SKILL.md +++ b/.agents/skills/api-conventions/SKILL.md @@ -29,6 +29,8 @@ Errors reach the model in two ways, both from `src/Presentation/Errors/`: | Tools | `ToolErrorFilter` | A normal result with `IsError = true` and a message the model can act on: `Validation Failed: ...` or `Not Found: ...`, ending with what to do next | | Resources and prompts | `ProtocolErrorFilter` | An `McpProtocolException`: `ResourceNotFound` for not found, `InvalidParams` for validation | +Anything else is unexpected. `ToolErrorFilter` logs it as `Error` and returns `Error: An error occurred while processing your request.`, because the model only sees a tool error and nothing else would log it. `ProtocolErrorFilter` lets it through, and the MCP SDK logs it and sends an internal error (`serilog`). + `ServerInstructions` in `WebApplicationBuilderExtensions` is the model's first read. It names the tools, how they connect and the rules (paging with `nextOffset`, confirm before deleting). ## Steps diff --git a/.agents/skills/errors-and-exceptions/SKILL.md b/.agents/skills/errors-and-exceptions/SKILL.md index f32408c..7ba4fa6 100644 --- a/.agents/skills/errors-and-exceptions/SKILL.md +++ b/.agents/skills/errors-and-exceptions/SKILL.md @@ -19,6 +19,8 @@ Application signals failure by throwing; it never returns error codes or result The presentation layer maps each exception to its own shape in one place (in a web API, an `IExceptionHandler` writing RFC 9457 problem details). Messages are written for the caller and never include stack traces or internal details. +`LoggingBehaviour` logs validation failures and not found as `Information`, because the caller got an answer. The presentation layer's handler logs anything unexpected as `Error`, with the exception, in the same place it reports it (`serilog`). + ## Steps 1. For a missing entity, use the helpers rather than `throw new`: @@ -26,7 +28,8 @@ The presentation layer maps each exception to its own shape in one place (in a w - `NotFoundException.Throw(EntityType.Author);` after an existence check. 2. A new kind of entity needs a value in `EntityType` (`src/Application/Common/Enums/EntityType.cs`). 3. Test the not-found path in the handler tests with `Should.ThrowAsync`. -4. If you add a new exception type, map it in the presentation layer's error handler in the same change, and test the mapping. +4. If you add a new exception type, map it in the presentation layer's error handler in the same change, and test the mapping. If the caller should see it as an answer rather than a fault, log it in `LoggingBehaviour` too. +5. Test that the handler logs an unexpected exception once, as `Error`, and logs nothing for the ones it maps (`unit-tests`). ## Example diff --git a/.agents/skills/mediator/SKILL.md b/.agents/skills/mediator/SKILL.md index 33fc82b..2b57e7b 100644 --- a/.agents/skills/mediator/SKILL.md +++ b/.agents/skills/mediator/SKILL.md @@ -21,7 +21,7 @@ Requests travel from the presentation layer to Application through Mediator (`Me Every request uses `IRequest`. Mediator also offers `ICommand` and `IQuery` markers; we don't use them, because nothing yet needs a behaviour that applies to only one kind. -Behaviours run in the order they're registered. The first one registered is the outermost, so it runs first on the way in and last on the way out. `ValidationBehaviour` is registered first, so invalid requests never reach a handler. +Behaviours run in the order they're registered. The first one registered is the outermost, so it runs first on the way in and last on the way out. `LoggingBehaviour` is registered first, so it times and logs everything inside it, validation failures included (`serilog`). `ValidationBehaviour` comes next, so invalid requests never reach a handler. ## Steps @@ -36,6 +36,9 @@ Behaviours run in the order they're registered. The first one registered is the ```csharp // src/Application/DependencyInjection.cs _ = services.AddValidatorsFromAssembly(Assembly.GetExecutingAssembly(), ServiceLifetime.Transient); +services.TryAddSingleton(TimeProvider.System); + +_ = services.AddScoped(typeof(IPipelineBehavior<,>), typeof(LoggingBehaviour<,>)); _ = services.AddScoped(typeof(IPipelineBehavior<,>), typeof(ValidationBehaviour<,>)); ``` diff --git a/.agents/skills/serilog/SKILL.md b/.agents/skills/serilog/SKILL.md index 8dd834c..bdf2266 100644 --- a/.agents/skills/serilog/SKILL.md +++ b/.agents/skills/serilog/SKILL.md @@ -1,6 +1,6 @@ --- name: serilog -description: How logging works with Serilog - registration with AddSerilog, configuration from appsettings, sinks per environment (console locally, Seq in Docker), the enrichers and properties on every event, request logging, levels, and message templates. Use when adding a log line, changing log configuration or levels, adding a property, or looking for where logs go. +description: How logging works with Serilog - registration with AddSerilog, configuration from appsettings, sinks per environment, the enrichers and properties on every event, the request log, the LoggingBehaviour, who logs an unexpected exception, levels, and source-generated log messages. Use when adding a log line, changing log configuration or levels, adding a property, or looking for where logs go. metadata: scope: shared --- @@ -15,6 +15,7 @@ Serilog is the logger. Application and Infrastructure code log through `Microsof | --- | --- | --- | | `local` | Console, with the output template in `appsettings.local.json` | The terminal | | `docker` | Seq at `http://seq:5341` | | +| Lambda, anywhere | Console, as compact JSON | CloudWatch Logs, or `docker compose logs` for the emulator | Every event carries these properties: @@ -25,16 +26,24 @@ Every event carries these properties: | `AssemblyVersion`, `AssemblyInformationalVersion` | Added in code at startup | | Anything pushed with `LogContext` | `FromLogContext` | -Levels are set in appsettings, never in code: `Debug` by default, `Information` for `Microsoft`, `Warning` for `Microsoft.AspNetCore`, `Error` for `System`. The built-in `Logging` section is set to `None` so nothing is written twice. +Levels are set in configuration, never in code: `Information` by default and `Debug` in `local`, with `Information` for `Microsoft`, `Warning` for `Microsoft.AspNetCore` and `Error` for `System`. The built-in `Logging` section is set to `None` so nothing is written twice. -Web templates log one line per request with `UseSerilogRequestLogging()`, under `Serilog.AspNetCore.RequestLoggingMiddleware`. +Three things log a request, and each says something the others don't: -The Lambda template doesn't register a logger yet. CloudWatch Logs keeps what the Lambda runtime writes, including any unhandled exception. +| What | Where | Logs | +| --- | --- | --- | +| The request log | `UseSerilogRequestLogging()`, in web templates only | One line per request with its method, path, status code and time. It's registered before the exception handler, so it logs the status code the client actually got | +| `LoggingBehaviour` | `src/Application/Common/Behaviours/`, around every use case | `Information` when a request is handled, fails validation or finds nothing, with the request name and its time in milliseconds | +| The presentation error handler | The exception handler or error filter | `Error`, with the exception, for anything it reports as unexpected | + +An unexpected exception is logged once, by the class that turns it into a response, because handling it stops the framework logging it. `LoggingBehaviour` leaves it alone. In Lambda the exception goes back to the caller as a function error and the runtime writes it to CloudWatch Logs, so nothing logs it a second time. + +The Lambda template has no appsettings files. Its startup sets the same levels and properties in code, and environment variables such as `Serilog__MinimumLevel__Default` override them. ## Steps 1. Take `ILogger` through the constructor where you need it. Never reference Serilog types outside the presentation layer. -2. Write message templates with named holes: `logger.LogInformation("Created review {ReviewId} for movie {MovieId}", review.Id, movieId);` +2. Write each message as a `[LoggerMessage]` method on a `partial` class, with named holes in the template. The source generator writes the code, so nothing is formatted when the level is off. Put the methods in a `#region Log Messages` at the bottom of the class. 3. Pick the level for the reader at 3am: `Information` for something that happened, `Warning` for something odd that was handled, `Error` for a failed request, `Debug` for detail you'd only want while developing. 4. Name new properties in PascalCase with no spaces, so they can be used in templates and queried in Seq without quoting. 5. Add a sink or change a level in the appsettings files. A new sink package goes in `Directory.Packages.props` (`packages-and-dependencies`). @@ -42,6 +51,12 @@ The Lambda template doesn't register a logger yet. CloudWatch Logs keeps what th ## Example +```csharp +// src/Application/Common/Behaviours/LoggingBehaviour.cs +[LoggerMessage(Level = LogLevel.Information, Message = "{RequestName} handled in {ElapsedMilliseconds:0.0} ms")] +private static partial void LogHandled(ILogger logger, string requestName, double elapsedMilliseconds); +``` + ```csharp // src/Presentation/Extensions, where startup registers services _ = builder.Services.AddSerilog((services, loggerConfiguration) => @@ -66,15 +81,19 @@ _ = builder.Services.AddSerilog((services, loggerConfiguration) => ## Don't - Use string interpolation in a log message (`$"Created {id}"`). It loses the property and allocates on every call. +- Call `logger.LogInformation(...)` and its friends directly. Write a `[LoggerMessage]` method instead. +- Log an exception that something else will log, such as one you rethrow. - Log tokens, connection strings, passwords or personal data. - Use `Console.WriteLine`. - Reference Serilog from Application or Infrastructure. - Register Serilog with `builder.Host.UseSerilog`. `AddSerilog` is the current registration. - Add a second request logger, such as `UseHttpLogging`. Requests are logged once, by Serilog. +- Move the request log after the exception handler. It would log every handled error as a `500`. ## Check ``` bash dotnet run --project ./src/Presentation # watch the console, then make a request docker compose up -d --build # then open http://localhost:5341 +dotnet test tests/Application.Tests.Unit # LoggingBehaviourTests check the messages with FakeLogger ``` diff --git a/.agents/skills/time-provider/SKILL.md b/.agents/skills/time-provider/SKILL.md index 0fdad64..daca126 100644 --- a/.agents/skills/time-provider/SKILL.md +++ b/.agents/skills/time-provider/SKILL.md @@ -9,16 +9,16 @@ metadata: ## The rule -Nothing reads the clock directly. Code that needs the time takes `TimeProvider` through its constructor and calls `GetUtcNow()`. Production gets `TimeProvider.System`, registered once in `src/Infrastructure/DependencyInjection.cs`. Tests pass a `FakeTimeProvider` (`Microsoft.Extensions.TimeProvider.Testing`) set to a fixed moment, so every date is known in advance. +Nothing reads the clock directly. Code that needs the time takes `TimeProvider` through its constructor and calls `GetUtcNow()`. Production gets `TimeProvider.System`, registered with `TryAddSingleton` in both `AddApplication` and `AddInfrastructure`, so either layer works on its own and the clock is only registered once. Tests pass a `FakeTimeProvider` (`Microsoft.Extensions.TimeProvider.Testing`) set to a fixed moment, so every date is known in advance. -Times are stored and compared in UTC. Only the Infrastructure layer reads the time today: the repository stamps `DateCreated` and `DateModified` on writes. +Times are stored and compared in UTC. Two things read the clock today. The repository stamps `DateCreated` and `DateModified` on writes, and `LoggingBehaviour` times each request with `GetTimestamp()` and `GetElapsedTime()`. ## Steps 1. Take `TimeProvider timeProvider` in the constructor, check it with `ArgumentNullException.ThrowIfNull`, and keep it in a `private readonly` field. 2. Read the time once per operation into a local (`var now = this.timeProvider.GetUtcNow().UtcDateTime;`) and use that value everywhere in the operation, so created and modified dates match. 3. In repository tests, use the clock from `MovieReviewsTestDatabase` (fixed at 2009-12-31 23:51:01 UTC) and assert against it. -4. To test something that depends on time passing, call `Advance(TimeSpan)` on the fake. +4. To test something that depends on time passing, call `Advance(TimeSpan)` on the fake. `LoggingBehaviourTests` advance it inside the fake `next` delegate, so the logged time is exact. ## Example diff --git a/.agents/skills/unit-tests/SKILL.md b/.agents/skills/unit-tests/SKILL.md index 3821032..c60e891 100644 --- a/.agents/skills/unit-tests/SKILL.md +++ b/.agents/skills/unit-tests/SKILL.md @@ -27,6 +27,7 @@ Names read as `Method_Should_`: `Handle_ShouldThrowException 3. Assert the result, then assert the calls: `Received(1)` with the exact arguments and token, and `DidNotReceiveWithAnyArgs()` for calls that mustn't happen. 4. Validators: a static validator instance, one valid case with `ShouldNotHaveAnyValidationErrors()`, and a `[Theory]` per rule with `ShouldHaveValidationErrorFor(...)`. 5. Use a real `CancellationTokenSource` so you can prove the token was passed on (`cancellation`). +6. To check a log message, pass a `FakeLogger` (`Microsoft.Extensions.Diagnostics.Testing`) and assert on `logger.Collector`: the count, then the level, message and exception of `LatestRecord`. ## Example diff --git a/Directory.Packages.props b/Directory.Packages.props index 8f24354..7fb7ddc 100644 --- a/Directory.Packages.props +++ b/Directory.Packages.props @@ -15,6 +15,8 @@ + + diff --git a/src/Application/Application.csproj b/src/Application/Application.csproj index 354c1cd..fc540ff 100644 --- a/src/Application/Application.csproj +++ b/src/Application/Application.csproj @@ -7,6 +7,7 @@ + diff --git a/src/Application/Common/Behaviours/LoggingBehaviour.cs b/src/Application/Common/Behaviours/LoggingBehaviour.cs new file mode 100644 index 0000000..3fffbe4 --- /dev/null +++ b/src/Application/Common/Behaviours/LoggingBehaviour.cs @@ -0,0 +1,70 @@ +namespace CleanModelContextProtocol.Application.Common.Behaviours; + +using System; +using System.Linq; +using System.Threading; +using System.Threading.Tasks; +using Exceptions; +using FluentValidation; +using Mediator; +using Microsoft.Extensions.Logging; + +/// +/// Logs how every request ended and how long it took. Validation failures and missing entities are logged as +/// information, because the caller gets an answer. Anything else is left to the presentation layer, which turns it +/// into a response and logs it once as an error. +/// +/// The request being sent. +/// The response the handler returns. +/// Where the log events go. +/// The clock that times each request. +public partial class LoggingBehaviour(ILogger> logger, TimeProvider timeProvider) : IPipelineBehavior + where TMessage : IMessage +{ + private static readonly string RequestName = typeof(TMessage).Name; + + public async ValueTask Handle(TMessage message, MessageHandlerDelegate next, CancellationToken cancellationToken) + { + var started = timeProvider.GetTimestamp(); + + try + { + var response = await next(message, cancellationToken); + var elapsed = timeProvider.GetElapsedTime(started).TotalMilliseconds; + + LogHandled(logger, RequestName, elapsed); + + return response; + } + catch (ValidationException exception) + { + var elapsed = timeProvider.GetElapsedTime(started).TotalMilliseconds; + var properties = string.Join(", ", exception.Errors.Select(e => e.PropertyName).Distinct()); + + LogInvalid(logger, RequestName, elapsed, properties); + + throw; + } + catch (NotFoundException exception) + { + var elapsed = timeProvider.GetElapsedTime(started).TotalMilliseconds; + + LogNotFound(logger, RequestName, elapsed, exception.Message); + + throw; + } + } + + #region Log Messages + + [LoggerMessage(Level = LogLevel.Information, Message = "{RequestName} handled in {ElapsedMilliseconds:0.0} ms")] + private static partial void LogHandled(ILogger logger, string requestName, double elapsedMilliseconds); + + [LoggerMessage(Level = LogLevel.Information, Message = "{RequestName} failed validation in {ElapsedMilliseconds:0.0} ms for {PropertyNames}")] + private static partial void LogInvalid(ILogger logger, string requestName, double elapsedMilliseconds, string propertyNames); + + [LoggerMessage(Level = LogLevel.Information, Message = "{RequestName} found nothing in {ElapsedMilliseconds:0.0} ms: {Reason}")] + private static partial void LogNotFound(ILogger logger, string requestName, double elapsedMilliseconds, string reason); + + #endregion Log Messages +} diff --git a/src/Application/DependencyInjection.cs b/src/Application/DependencyInjection.cs index 832b96d..d01fbd3 100644 --- a/src/Application/DependencyInjection.cs +++ b/src/Application/DependencyInjection.cs @@ -1,11 +1,13 @@ namespace CleanModelContextProtocol.Application; +using System; using System.Diagnostics.CodeAnalysis; using System.Reflection; using Common.Behaviours; using FluentValidation; using Mediator; using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.DependencyInjection.Extensions; [ExcludeFromCodeCoverage] public static class DependencyInjection @@ -13,6 +15,9 @@ public static class DependencyInjection public static IServiceCollection AddApplication(this IServiceCollection services) { _ = services.AddValidatorsFromAssembly(Assembly.GetExecutingAssembly(), ServiceLifetime.Transient); + services.TryAddSingleton(TimeProvider.System); + + _ = services.AddScoped(typeof(IPipelineBehavior<,>), typeof(LoggingBehaviour<,>)); _ = services.AddScoped(typeof(IPipelineBehavior<,>), typeof(ValidationBehaviour<,>)); return services; diff --git a/src/Infrastructure/DependencyInjection.cs b/src/Infrastructure/DependencyInjection.cs index 851d917..e2f0ede 100644 --- a/src/Infrastructure/DependencyInjection.cs +++ b/src/Infrastructure/DependencyInjection.cs @@ -9,6 +9,7 @@ namespace CleanModelContextProtocol.Infrastructure; using Databases.MovieReviews.Mapping; using Microsoft.EntityFrameworkCore; using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.DependencyInjection.Extensions; using Microsoft.Extensions.Diagnostics.HealthChecks; public static class DependencyInjection @@ -33,7 +34,7 @@ public static IServiceCollection AddInfrastructure(this IServiceCollection servi _ = services.AddScoped(x => x.GetRequiredService()); - _ = services.AddSingleton(TimeProvider.System); + services.TryAddSingleton(TimeProvider.System); return services; } diff --git a/src/Presentation/Errors/ToolErrorFilter.cs b/src/Presentation/Errors/ToolErrorFilter.cs index 9933fc9..bfd7ff1 100644 --- a/src/Presentation/Errors/ToolErrorFilter.cs +++ b/src/Presentation/Errors/ToolErrorFilter.cs @@ -2,13 +2,17 @@ namespace CleanModelContextProtocol.Presentation.Errors; using CleanModelContextProtocol.Application.Common.Exceptions; using FluentValidation; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; using ModelContextProtocol.Protocol; using ModelContextProtocol.Server; /// -/// Maps exceptions raised by the Application layer to MCP tool error results. +/// Maps exceptions raised by the Application layer to MCP tool error results. Anything it doesn't expect is logged +/// here as an error, because the client only sees a tool error and nothing else logs it. /// -public static class ToolErrorFilter +public static partial class ToolErrorFilter { public static McpRequestHandler Filter(McpRequestHandler next) { @@ -20,6 +24,13 @@ public static McpRequestHandler Filter(Mc } catch (Exception exception) when (exception is not OperationCanceledException) { + if (exception is not (ValidationException or NotFoundException)) + { + var logger = request.Services?.GetService()?.CreateLogger(typeof(ToolErrorFilter)) ?? NullLogger.Instance; + + LogUnexpected(logger, exception, request.Params?.Name); + } + return ToResult(exception); } }; @@ -42,4 +53,7 @@ public static CallToolResult ToResult(Exception exception) Content = [new TextContentBlock { Text = message }] }; } + + [LoggerMessage(Level = LogLevel.Error, Message = "An unexpected exception stopped the {ToolName} tool")] + private static partial void LogUnexpected(ILogger logger, Exception exception, string? toolName); } diff --git a/src/Presentation/appsettings.json b/src/Presentation/appsettings.json index fd102b5..120b474 100644 --- a/src/Presentation/appsettings.json +++ b/src/Presentation/appsettings.json @@ -1,7 +1,7 @@ { "Serilog": { "MinimumLevel": { - "Default": "Debug", + "Default": "Information", "Override": { "Microsoft": "Information", "Microsoft.AspNetCore": "Warning", diff --git a/src/Presentation/appsettings.local.json b/src/Presentation/appsettings.local.json index a071bf7..7f4709f 100644 --- a/src/Presentation/appsettings.local.json +++ b/src/Presentation/appsettings.local.json @@ -1,5 +1,8 @@ { "Serilog": { + "MinimumLevel": { + "Default": "Debug" + }, "WriteTo": [ { "Name": "Console", diff --git a/tests/Application.Tests.Unit/Application.Tests.Unit.csproj b/tests/Application.Tests.Unit/Application.Tests.Unit.csproj index ce4e323..dc287c3 100644 --- a/tests/Application.Tests.Unit/Application.Tests.Unit.csproj +++ b/tests/Application.Tests.Unit/Application.Tests.Unit.csproj @@ -17,6 +17,8 @@ all runtime; build; native; contentfiles; analyzers; buildtransitive + + diff --git a/tests/Application.Tests.Unit/Common/Behaviours/LoggingBehaviourTests.cs b/tests/Application.Tests.Unit/Common/Behaviours/LoggingBehaviourTests.cs new file mode 100644 index 0000000..f3ce311 --- /dev/null +++ b/tests/Application.Tests.Unit/Common/Behaviours/LoggingBehaviourTests.cs @@ -0,0 +1,127 @@ +namespace CleanModelContextProtocol.Application.Tests.Unit.Common.Behaviours; + +using System; +using System.Threading; +using System.Threading.Tasks; +using Application.Authors.Entities; +using Application.Authors.Queries.GetAuthorById; +using Application.Common.Behaviours; +using Application.Common.Enums; +using Application.Common.Exceptions; +using FluentValidation; +using FluentValidation.Results; +using Mediator; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Testing; +using Microsoft.Extensions.Time.Testing; +using NSubstitute; +using NSubstitute.ExceptionExtensions; +using Shouldly; +using Xunit; + +public class LoggingBehaviourTests +{ + private readonly FakeLogger> logger = new(); + private readonly FakeTimeProvider timeProvider = new(); + private readonly LoggingBehaviour behaviour; + private readonly GetAuthorByIdQuery query = new() { Id = Guid.NewGuid() }; + + public LoggingBehaviourTests() + { + this.behaviour = new LoggingBehaviour(this.logger, this.timeProvider); + } + + [Fact] + public async Task Handle_ShouldLogHandled_WhenNextSucceeds() + { + // Arrange + var author = new Author(Guid.NewGuid(), "Test", "Test", []); + using var tokenSource = new CancellationTokenSource(); + var token = tokenSource.Token; + var next = Substitute.For>(); + + _ = next(this.query, token).Returns(_ => + { + this.timeProvider.Advance(TimeSpan.FromMilliseconds(12.5)); + return author; + }); + + // Act + var result = await this.behaviour.Handle(this.query, next, token); + + // Assert + result.ShouldBe(author); + _ = await next.Received(1)(this.query, token); + + var record = this.logger.Collector.LatestRecord; + + this.logger.Collector.Count.ShouldBe(1); + record.Level.ShouldBe(LogLevel.Information); + record.Message.ShouldBe("GetAuthorByIdQuery handled in 12.5 ms"); + record.GetStructuredStateValue("RequestName").ShouldBe("GetAuthorByIdQuery"); + } + + [Fact] + public async Task Handle_ShouldLogInvalid_WhenValidationFails() + { + // Arrange + var next = Substitute.For>(); + + _ = next(default!, default).ThrowsAsyncForAnyArgs(new ValidationException( + [ + new ValidationFailure("Id", "'Id' must not be empty."), + new ValidationFailure("Id", "'Id' must be a real id."), + new ValidationFailure("Name", "'Name' must not be empty.") + ])); + + // Act + var exception = await Should.ThrowAsync(async () => await this.behaviour.Handle(this.query, next, CancellationToken.None)); + + // Assert + exception.Errors.ShouldNotBeEmpty(); + + var record = this.logger.Collector.LatestRecord; + + this.logger.Collector.Count.ShouldBe(1); + record.Level.ShouldBe(LogLevel.Information); + record.Message.ShouldBe("GetAuthorByIdQuery failed validation in 0.0 ms for Id, Name"); + } + + [Fact] + public async Task Handle_ShouldLogNotFound_WhenEntityIsMissing() + { + // Arrange + var next = Substitute.For>(); + + _ = next(default!, default).ThrowsAsyncForAnyArgs(_ => + { + this.timeProvider.Advance(TimeSpan.FromMilliseconds(3)); + return new NotFoundException($"The {EntityType.Author} with the supplied id was not found."); + }); + + // Act + _ = await Should.ThrowAsync(async () => await this.behaviour.Handle(this.query, next, CancellationToken.None)); + + // Assert + var record = this.logger.Collector.LatestRecord; + + this.logger.Collector.Count.ShouldBe(1); + record.Level.ShouldBe(LogLevel.Information); + record.Message.ShouldBe("GetAuthorByIdQuery found nothing in 3.0 ms: The Author with the supplied id was not found."); + } + + [Fact] + public async Task Handle_ShouldNotLog_WhenExceptionIsUnexpected() + { + // Arrange + var next = Substitute.For>(); + + _ = next(default!, default).ThrowsAsyncForAnyArgs(new InvalidOperationException("Broken")); + + // Act + _ = await Should.ThrowAsync(async () => await this.behaviour.Handle(this.query, next, CancellationToken.None)); + + // Assert + this.logger.Collector.Count.ShouldBe(0); + } +} diff --git a/tests/Presentation.Tests.Unit/Errors/ToolErrorFilterTests.cs b/tests/Presentation.Tests.Unit/Errors/ToolErrorFilterTests.cs index 0726ccd..dc0b7cb 100644 --- a/tests/Presentation.Tests.Unit/Errors/ToolErrorFilterTests.cs +++ b/tests/Presentation.Tests.Unit/Errors/ToolErrorFilterTests.cs @@ -4,12 +4,24 @@ namespace CleanModelContextProtocol.Presentation.Tests.Unit.Errors; using CleanModelContextProtocol.Presentation.Errors; using FluentValidation; using FluentValidation.Results; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Testing; using ModelContextProtocol.Protocol; +using ModelContextProtocol.Server; +using NSubstitute; using Shouldly; using Xunit; -public class ToolErrorFilterTests +public sealed class ToolErrorFilterTests : IDisposable { + private readonly ServiceProvider services = new ServiceCollection().AddFakeLogging().BuildServiceProvider(); + + public void Dispose() + { + this.services.Dispose(); + } + [Fact] public async Task Filter_ShouldReturn_Result() { @@ -38,6 +50,44 @@ public async Task Filter_ShouldReturn_ErrorResult() result.Content.OfType().Single().Text.ShouldBe("Not Found: Expected Exception Check the ids: movies_search, authors_search and reviews_list return valid ones."); } + [Fact] + public async Task Filter_ShouldLog_UnexpectedException() + { + // Arrange + var exception = new InvalidOperationException("Broken"); + var (request, collector) = this.CreateRequest(); + var handler = ToolErrorFilter.Filter((request, cancellationToken) => throw exception); + + // Act + var result = await handler(request, CancellationToken.None); + + // Assert + result.IsError.ShouldBe(true); + + var record = collector.LatestRecord; + + collector.Count.ShouldBe(1); + record.Level.ShouldBe(LogLevel.Error); + record.Exception.ShouldBe(exception); + record.Category.ShouldBe(typeof(ToolErrorFilter).FullName); + record.Message.ShouldBe("An unexpected exception stopped the movies_search tool"); + } + + [Fact] + public async Task Filter_ShouldNotLog_ExpectedException() + { + // Arrange + var (request, collector) = this.CreateRequest(); + var handler = ToolErrorFilter.Filter((request, cancellationToken) => throw new NotFoundException("Expected Exception")); + + // Act + var result = await handler(request, CancellationToken.None); + + // Assert + result.IsError.ShouldBe(true); + collector.Count.ShouldBe(0); + } + [Fact] public void ToResult_ShouldReturn_ValidationError() { @@ -78,4 +128,17 @@ public void ToResult_ShouldReturn_Error() result.IsError.ShouldBe(true); result.Content.OfType().Single().Text.ShouldBe("Error: An error occurred while processing your request."); } + + private (RequestContext Request, FakeLogCollector Collector) CreateRequest() + { + var request = new RequestContext( + Substitute.For(), + new JsonRpcRequest { Method = RequestMethods.ToolsCall }, + new CallToolRequestParams { Name = "movies_search" }) + { + Services = this.services + }; + + return (request, this.services.GetFakeLogCollector()); + } } diff --git a/tests/Presentation.Tests.Unit/Presentation.Tests.Unit.csproj b/tests/Presentation.Tests.Unit/Presentation.Tests.Unit.csproj index d998f2e..2deecf9 100644 --- a/tests/Presentation.Tests.Unit/Presentation.Tests.Unit.csproj +++ b/tests/Presentation.Tests.Unit/Presentation.Tests.Unit.csproj @@ -10,6 +10,7 @@ all runtime; build; native; contentfiles; analyzers; buildtransitive +