Log every use case and unexpected tool errors

.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

.agents/skills/errors-and-exceptions/SKILL.md

@@ -19,14 +19,17 @@ 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`:
    - `NotFoundException.ThrowIfNull(result, EntityType.Movie);` after a fetch.
    - `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<NotFoundException>`.
-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
 

.agents/skills/mediator/SKILL.md

@@ -21,7 +21,7 @@ Requests travel from the presentation layer to Application through Mediator (`Me
 
 Every request uses `IRequest<TResponse>`. 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<,>));
 ```
 

.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` | <http://localhost:5341> |
+| Lambda, anywhere | Console, as compact JSON | CloudWatch Logs, or `docker compose logs` for the emulator |
 
 Every event carries these properties:
 
@@ -25,23 +26,37 @@ 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<T>` 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`).
 6. In Seq, filter with property expressions: `ApplicationName = 'CleanModelContextProtocol-Docker' and @Level = 'Error'`.
 
 ## 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
 ```

.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
 

.agents/skills/unit-tests/SKILL.md

@@ -27,6 +27,7 @@ Names read as `Method_Should<Outcome>_<Condition>`: `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<T>` (`Microsoft.Extensions.Diagnostics.Testing`) and assert on `logger.Collector`: the count, then the level, message and exception of `LatestRecord`.
 
 ## Example
 

Directory.Packages.props

@@ -15,6 +15,8 @@
     <PackageVersion Include="Microsoft.EntityFrameworkCore.Design" Version="10.0.14" />
     <PackageVersion Include="Microsoft.EntityFrameworkCore.Sqlite" Version="10.0.14" />
     <PackageVersion Include="Microsoft.Extensions.Diagnostics.HealthChecks.EntityFrameworkCore" Version="10.0.14" />
+    <PackageVersion Include="Microsoft.Extensions.Diagnostics.Testing" Version="10.11.0" />
+    <PackageVersion Include="Microsoft.Extensions.Logging.Abstractions" Version="10.0.14" />
     <PackageVersion Include="Microsoft.Extensions.TimeProvider.Testing" Version="10.11.0" />
     <PackageVersion Include="Microsoft.NET.Test.Sdk" Version="18.11.0" />
     <PackageVersion Include="ModelContextProtocol.AspNetCore" Version="2.3.0" />

src/Application/Application.csproj

@@ -7,6 +7,7 @@
   <ItemGroup>
     <PackageReference Include="FluentValidation.DependencyInjectionExtensions" />
     <PackageReference Include="Mediator.Abstractions" />
+    <PackageReference Include="Microsoft.Extensions.Logging.Abstractions" />
   </ItemGroup>
 
 </Project>

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;
+
+/// <summary>
+/// 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.
+/// </summary>
+/// <typeparam name="TMessage">The request being sent.</typeparam>
+/// <typeparam name="TResponse">The response the handler returns.</typeparam>
+/// <param name="logger">Where the log events go.</param>
+/// <param name="timeProvider">The clock that times each request.</param>
+public partial class LoggingBehaviour<TMessage, TResponse>(ILogger<LoggingBehaviour<TMessage, TResponse>> logger, TimeProvider timeProvider) : IPipelineBehavior<TMessage, TResponse>
+    where TMessage : IMessage
+{
+    private static readonly string RequestName = typeof(TMessage).Name;
+
+    public async ValueTask<TResponse> Handle(TMessage message, MessageHandlerDelegate<TMessage, TResponse> 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
+}

src/Application/DependencyInjection.cs

@@ -1,18 +1,23 @@
 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
 {
     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;

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<IReviewsRepository>(x =>
             x.GetRequiredService<EntityFrameworkMovieReviewsRepository>());
 
-        _ = services.AddSingleton(TimeProvider.System);
+        services.TryAddSingleton(TimeProvider.System);
 
         return services;
     }