diff --git a/.agents/skills/configuration-and-environments/SKILL.md b/.agents/skills/configuration-and-environments/SKILL.md index ee0ca56..5806870 100644 --- a/.agents/skills/configuration-and-environments/SKILL.md +++ b/.agents/skills/configuration-and-environments/SKILL.md @@ -16,7 +16,7 @@ The Lambda template has no appsettings files or environments. Its startup builds | Environment | Set by | Used for | | --- | --- | --- | | `local` | `launchSettings.json` (`DOTNET_ENVIRONMENT=local`) | `dotnet run` on a developer machine: console logs, sample data on | -| `docker` | `docker-compose.yml` and the Dockerfile | `docker compose up`: logs to Seq, database in `/app/data`, sample data on | +| `docker` | `docker-compose.yml` and the Dockerfile | `docker compose up`: telemetry over OTLP through the collector to the Aspire dashboard, database in `/app/data`, sample data on | | anything else | the host | Real deployments: base settings only, sample data off, HSTS on | Settings that exist today: diff --git a/.agents/skills/docker-and-compose/SKILL.md b/.agents/skills/docker-and-compose/SKILL.md index 30f3581..1ec303b 100644 --- a/.agents/skills/docker-and-compose/SKILL.md +++ b/.agents/skills/docker-and-compose/SKILL.md @@ -19,9 +19,9 @@ One multi-stage `Dockerfile` does everything the pipeline needs: | `publish` | Publishes the Presentation project | | `run` | The runtime image: non-root `$APP_UID`, `WORKDIR /app`, data in `/app/data`, a `HEALTHCHECK` on `/health/live` | -`docker-compose.yml` runs the app with `DOTNET_ENVIRONMENT=docker`, the `movie-reviews-data` volume and a pinned Seq image for logs. Images are built by CI but not pushed anywhere; the template ships the Dockerfile so users can. +`docker-compose.yml` runs the app with `DOTNET_ENVIRONMENT=docker`, the `movie-reviews-data` volume a pinned OpenTelemetry Collector that receives the app's OTLP logs, traces and metrics, configured by `otel-collector.yaml`, and a pinned Aspire dashboard the collector forwards them to (`telemetry`). The dashboard UI is at , and the collector's OTLP ports are published on 4317 and 4318 so a `dotnet run` can send to it too. Images are built by CI but not pushed anywhere; the template ships the Dockerfile so users can. -The Lambda template's `run` stage is the AWS Lambda .NET base image instead. It runs as user `65534` from `/var/task`, keeps its database in `/tmp`, and has no `HEALTHCHECK` or Seq. Compose maps the runtime interface emulator to port 9000, so the function can be invoked with a `POST` to `/2015-03-31/functions/function/invocations`. +The Lambda template's `run` stage is the AWS Lambda .NET base image instead. It runs as user `65534` from `/var/task`, keeps its database in `/tmp`, and has no `HEALTHCHECK`. Its compose file runs the collector and the Aspire dashboard as well. Compose maps the runtime interface emulator to port 9000, so the function can be invoked with a `POST` to `/2015-03-31/functions/function/invocations`. ## Steps diff --git a/.agents/skills/health-checks/SKILL.md b/.agents/skills/health-checks/SKILL.md index dd4c491..94ffab4 100644 --- a/.agents/skills/health-checks/SKILL.md +++ b/.agents/skills/health-checks/SKILL.md @@ -16,7 +16,7 @@ Two questions, two endpoints, in every template that runs a web host. | `/health/live` | Is the process up? | No checks. It only fails when the app can't answer at all. | | `/health/ready` | Can it do its job? | Every check tagged `ready`, which today is the database. | -Both are anonymous. The Docker image's `HEALTHCHECK` calls `/health/live`. Infrastructure owns the checks for what it talks to (`AddInfrastructureHealthChecks` in `src/Infrastructure/DependencyInjection.cs`); Presentation maps the endpoints. The Lambda template has no health endpoints, because Lambda manages its own lifecycle. +Both are anonymous and answer with plain text, because Docker, load balancers and orchestrators call them without a token. Neither is traced (`telemetry`). The Docker image's `HEALTHCHECK` calls `/health/live`. Infrastructure owns the checks for what it talks to (`AddInfrastructureHealthChecks` in `src/Infrastructure/DependencyInjection.cs`); Presentation maps the endpoints. The Lambda template has no health endpoints, because Lambda manages its own lifecycle. ## Steps @@ -38,7 +38,7 @@ public static IHealthChecksBuilder AddInfrastructureHealthChecks(this IHealthChe - Put a dependency check on `/health/live`. - Require authentication on either endpoint. -- Return version or configuration details from a health endpoint. +- Return version or configuration details from a health endpoint. Anyone can call it; the version is on every span, metric and log as `service.version`, and behind auth at the version endpoint. ## Check diff --git a/.agents/skills/mcp-inspector/SKILL.md b/.agents/skills/mcp-inspector/SKILL.md index fc8f5e5..70934c5 100644 --- a/.agents/skills/mcp-inspector/SKILL.md +++ b/.agents/skills/mcp-inspector/SKILL.md @@ -15,7 +15,7 @@ metadata: | --- | --- | | MCP server | | | MCP Inspector | | -| Seq (logs) | | +| Aspire dashboard (logs, traces, metrics) | | ## Steps @@ -23,7 +23,7 @@ metadata: 2. Open , flip the switch on the server card to connect, then open **Tools**, **Resources** or **Prompts**. 3. After changing a tool, check its description and every argument's description read well, the annotations are right, and a call returns the result model you expect. 4. Try the failure paths too: an unknown id, a star rating of 6. The model should get a message it can act on. -5. Find the request in Seq if something looks wrong (`serilog`). +5. Find the tool call in the Aspire dashboard if something looks wrong: its trace shows the tool, the use case and each SQL command, and its logs sit beside it (`telemetry`). 6. With authentication on, the Inspector needs a token from your authority. Leave `Authentication:Authority` empty for local checks. ## Don't diff --git a/.agents/skills/mediator/SKILL.md b/.agents/skills/mediator/SKILL.md index 2b57e7b..fa2f21a 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. `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. +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`), and its span wraps the use case (`telemetry`). `ValidationBehaviour` comes next, so invalid requests never reach a handler. ## Steps diff --git a/.agents/skills/optional-token-auth/SKILL.md b/.agents/skills/optional-token-auth/SKILL.md index e17f8ed..9e795ff 100644 --- a/.agents/skills/optional-token-auth/SKILL.md +++ b/.agents/skills/optional-token-auth/SKILL.md @@ -11,14 +11,14 @@ metadata: Authentication is off until someone sets `Authentication:Authority` (and usually `Authentication:Audience`). Then every request needs a valid JWT bearer token from that authority. The `dotnet new` options `--authority` and `--audience` fill those settings in. -Endpoints always ask for authorization, whether or not authentication is on. When it's off, the default policy lets every request through, so turning it on is a settings change, not a code change. Only health checks, the API reference and the version endpoint (where a template has them) are anonymous. The Lambda template has no token authentication; API Gateway or the caller's IAM role does that job. +Endpoints always ask for authorization, whether or not authentication is on. When it's off, the default policy lets every request through, so turning it on is a settings change, not a code change. Only health checks and the API reference (where a template has them) are anonymous. The version endpoint is protected like everything else; telemetry carries `service.version` for anyone who needs to know what's deployed. The Lambda template has no token authentication; API Gateway or the caller's IAM role does that job. Settings are read through `AuthenticationSettings.FromConfiguration` (`Enabled` is true when the authority isn't empty). ## Steps 1. A new endpoint or group gets `.RequireAuthorization()` (or the presentation layer's equivalent). That's the default; don't skip it. -2. Only make something anonymous if it has to work without a token: health, the API reference, the version. Say why in a comment. +2. Only make something anonymous if it has to work without a token: health and the API reference. Say why in a comment. 3. When authentication is on, the template tells clients how to get a token: a bearer scheme in the OpenAPI document where a template has one, and the protected resource metadata in MCP. 4. Test both modes: one test with no authority (anonymous works), one with an authority and no token (401). diff --git a/.agents/skills/serilog/SKILL.md b/.agents/skills/serilog/SKILL.md index bdf2266..ada5ea5 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, 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. +description: How logging works with Serilog - registration with AddSerilog, configuration from appsettings, sinks per environment, logs over OTLP, 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 --- @@ -14,8 +14,11 @@ Serilog is the logger. Application and Infrastructure code log through `Microsof | Environment | Sink | Where to look | | --- | --- | --- | | `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 | +| `docker` | Console, and OTLP through the collector to the Aspire dashboard | , or `docker compose logs` | +| Lambda, anywhere | Console, as compact JSON, and OTLP when the endpoint is set | CloudWatch Logs, or `docker compose logs` for the emulator, and the Aspire dashboard in Docker Compose | +| Any, when `OTEL_EXPORTER_OTLP_ENDPOINT` is set | Also OTLP, through `Serilog.Sinks.OpenTelemetry` | Whatever receives the OTLP (`telemetry`) | + +The OTLP sink is added in code, not in the appsettings files, because it follows the standard `OTEL_*` settings like the trace and metric exporters do. It sends the same `service.name`, `service.version` and `deployment.environment.name` as the traces, and each event carries the trace and span IDs of whatever was running when it was written, so a log line links to its trace. Every event carries these properties: @@ -26,7 +29,7 @@ Every event carries these properties: | `AssemblyVersion`, `AssemblyInformationalVersion` | Added in code at startup | | Anything pushed with `LogContext` | `FromLogContext` | -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. +Levels are set in configuration, never in code: `Information` by default and `Debug` in `local`, with `Information` for `Microsoft`, `Warning` for `Microsoft.AspNetCore` and `Microsoft.EntityFrameworkCore.Database.Command` (a line per SQL statement buries everything else, and EF Core's meter already counts them), and `Error` for `System`. The built-in `Logging` section is set to `None` so nothing is written twice. Three things log a request, and each says something the others don't: @@ -45,9 +48,9 @@ The Lambda template has no appsettings files. Its startup sets the same levels a 1. Take `ILogger` through the constructor where you need it. Never reference Serilog types outside the presentation layer. 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. +4. Name new properties in PascalCase with no spaces, so they can be used in templates and queried in any backend 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'`. +6. In the Aspire dashboard's structured logs, filter on any property, or open a log's trace from its trace ID. ## Example @@ -61,19 +64,30 @@ private static partial void LogHandled(ILogger logger, string requestName, doubl // src/Presentation/Extensions, where startup registers services _ = builder.Services.AddSerilog((services, loggerConfiguration) => { - var assembly = Assembly.GetEntryAssembly(); + var configuration = services.GetRequiredService(); - _ = loggerConfiguration.ReadFrom.Configuration(services.GetRequiredService()) + _ = loggerConfiguration.ReadFrom.Configuration(configuration) .Enrich.WithProperty( "AssemblyVersion", - assembly?.GetCustomAttribute()?.Version); + assembly.GetCustomAttribute()?.Version); + + if (telemetry.Enabled) + { + _ = loggerConfiguration.WriteTo.OpenTelemetry( + options => + { + options.ResourceAttributes = telemetry.ResourceAttributes; + options.OnBeginSuppressInstrumentation = SuppressInstrumentationScope.Begin; + }, + key => configuration[key]); + } }); ``` ```json // src/Presentation/appsettings.docker.json "Serilog": { - "WriteTo": [ { "Name": "Seq", "Args": { "serverUrl": "http://seq:5341" } } ], + "WriteTo": [ { "Name": "Console", "Args": { "outputTemplate": "..." } } ], "Properties": { "ApplicationName": "CleanModelContextProtocol-Docker" } } ``` @@ -94,6 +108,6 @@ _ = builder.Services.AddSerilog((services, loggerConfiguration) => ``` bash dotnet run --project ./src/Presentation # watch the console, then make a request -docker compose up -d --build # then open http://localhost:5341 +docker compose up -d --build # then open http://localhost:18888 dotnet test tests/Application.Tests.Unit # LoggingBehaviourTests check the messages with FakeLogger ``` diff --git a/.agents/skills/telemetry/SKILL.md b/.agents/skills/telemetry/SKILL.md new file mode 100644 index 0000000..7067676 --- /dev/null +++ b/.agents/skills/telemetry/SKILL.md @@ -0,0 +1,114 @@ +--- +name: telemetry +description: How OpenTelemetry traces, metrics and logs work - the standard OTEL_* settings that switch exporting on, the span LoggingBehaviour gives every use case, EF Core's built-in metrics, what each presentation layer instruments, the Aspire dashboard in Docker Compose, and the signals we're waiting on. Use when adding a span, metric or tag, changing what's exported or where, reading telemetry locally, or adding a dependency that should be traced. +metadata: + scope: shared +--- + +# Telemetry + +## The rule + +Telemetry is OpenTelemetry, and it leaves the app over OTLP and nothing else. No vendor SDK, no Aspire package, nothing that ties the code to one backend. Signals come from stable Microsoft and OpenTelemetry instrumentation; we write our own only where nothing covers it, and that's one span per use case. Traces and metrics are always collected; they're exported, with the logs, only when `OTEL_EXPORTER_OTLP_ENDPOINT` is set. Every standard `OTEL_*` setting works as the OpenTelemetry SDK documents it. + +| Signal | What we send | Where it comes from | +| --- | --- | --- | +| Traces | A span for each incoming request and each use case, plus outgoing HTTP calls | Presentation instrumentation, `LoggingBehaviour` | +| Metrics | EF Core's own meter, ASP.NET Core, HttpClient and runtime metrics, with exemplars linking a measurement to a trace | `Microsoft.EntityFrameworkCore`, Presentation instrumentation | +| Logs | Every Serilog event, carrying the trace and span IDs of whatever was running when it was written. Validation failures and missing entities are logged inside the use case span, so they sit on its trace | Serilog's OpenTelemetry sink (`serilog`) | +| Baggage | Propagated with the trace context by the ASP.NET Core and HttpClient instrumentation | W3C `baggage` header | +| Events | An `exception` event on the use case span for unexpected errors | `LoggingBehaviour` | + +Each layer publishes under its own name, and only the presentation layer's startup knows about the OpenTelemetry SDK: + +| Layer | Publishes | How | +| --- | --- | --- | +| Application | `ApplicationTelemetry.Name` activity source: a span per use case, named after the request, tagged with `application.request.name` and `application.request.outcome` | `LoggingBehaviour`, with `System.Diagnostics` only, so Application stays free of telemetry packages | +| Infrastructure | `Microsoft.EntityFrameworkCore` meter: queries, saves, active contexts, compiled query cache | Built into EF Core; startup subscribes to it by name | +| Presentation | `service.name`, `service.version` and `deployment.environment.name` on everything, plus its own instrumentation | `TelemetrySettings` and the startup's Telemetry region | + +What each presentation layer adds: + +| Template | Instrumentation | +| --- | --- | +| Minimal API, Web API | ASP.NET Core and HttpClient traces and metrics, runtime metrics, the authentication and authorization meters. Health endpoints aren't traced | +| GraphQL | The same, plus Hot Chocolate's resolver and operation spans from `HotChocolate.Diagnostics` | +| MCP | The same, plus the MCP SDK's own `Experimental.ModelContextProtocol` spans and `mcp.*.operation.duration` metrics | +| Lambda | A span per invocation from `OpenTelemetry.Instrumentation.AWSLambda`, and runtime metrics. Traces and metrics are flushed before the function returns, because Lambda can freeze the environment as soon as it does | + +The Lambda template builds its tracer and meter providers once in `Startup` with `Sdk.CreateTracerProviderBuilder()` and `Sdk.CreateMeterProviderBuilder()` rather than `AddOpenTelemetry()`, because the classes Lambda Annotations generates build two service providers from the same services, and each would otherwise export everything again. X-Ray context extraction is off, so a "not sampled" header from Lambda can't switch tracing off; the collector can still send to X-Ray. Lambda container images can't use layers, so in AWS the collector is either built into the image (the ADOT collector extension) or runs as a gateway. + +The app sends to an OpenTelemetry Collector, never straight to a backend, because that's how it should run in production: the collector owns batching, retries, sampling, scrubbing and the choice of backend, so none of that lives in the app. `otel-collector.yaml` holds its configuration: an OTLP receiver on 4317 (gRPC) and 4318 (HTTP), the `memory_limiter` and `batch` processors, and one exporter per backend. + +Locally, Docker Compose runs the collector (`otel/opentelemetry-collector`) and the Aspire dashboard (`mcr.microsoft.com/dotnet/aspire-dashboard`), and the collector forwards everything to the dashboard. The dashboard is only a container that receives OTLP and shows logs, traces and metrics at ; it keeps everything in memory, so it's empty after a restart. In production, run a collector beside the app or as a gateway and swap the dashboard exporter for your backend's. + +## Steps + +1. A new use case needs nothing: `LoggingBehaviour` gives it a span named after the request class, with its outcome as a tag. +2. Before writing any telemetry code, check what the instrumentation already records. Request durations per route, GraphQL operations, MCP tool calls and Lambda invocations are all covered, so we don't count or time them again. +3. To trace work inside Application, start a child span with `using var activity = ApplicationTelemetry.ActivitySource.StartActivity("Name");`, and use the [semantic convention](https://opentelemetry.io/docs/specs/semconv/) tag names where one exists. +4. A new dependency in Infrastructure (a queue, an HTTP API) gets its spans and metrics from its own instrumentation package, if a stable one exists. Subscribe to its source or meter name in the presentation layer's startup. +5. Use stable packages only. When the only instrumentation is a prerelease package, go without that signal and add it to the watch list below. +6. Test spans with an `ActivityListener` that keeps only the test's own trace (`unit-tests`). The integration tests send a `traceparent` header and check the request and use case spans join up. +7. To send telemetry somewhere new, add an exporter to `otel-collector.yaml` and list it in the pipelines. The app's settings don't change. +8. To see it locally, run `docker compose up -d --build` and open . For a `dotnet run`, start the collector with `docker compose up -d otel-collector` and set `OTEL_EXPORTER_OTLP_ENDPOINT=http://localhost:4317`. + +## Example + +```csharp +// src/Application/Common/Behaviours/LoggingBehaviour.cs +using var activity = ApplicationTelemetry.ActivitySource.StartActivity(RequestName); +_ = activity?.SetTag(ApplicationTelemetry.RequestNameTag, RequestName); +... +catch (Exception exception) +{ + _ = activity?.SetTag(ApplicationTelemetry.RequestOutcomeTag, "error") + .SetStatus(ActivityStatusCode.Error, exception.Message) + .AddException(exception); + + throw; +} +``` + +```yaml +# docker-compose.yml +environment: + OTEL_EXPORTER_OTLP_ENDPOINT: http://otel-collector:4317 + OTEL_EXPORTER_OTLP_PROTOCOL: grpc +``` + +```yaml +# otel-collector.yaml +exporters: + otlp_grpc/aspire: + endpoint: aspire-dashboard:18889 + tls: + insecure: true +``` + +## Watch list + +These signals and packages aren't stable for .NET yet. Check them when dependencies are updated, and adopt each one once it has a stable release: + +- `OpenTelemetry.Instrumentation.EntityFrameworkCore`: adds a span per SQL command. Until it's stable there are no database spans, only EF Core's metrics. +- Profiles: there's no stable .NET SDK for the profiling signal. +- The OpenTelemetry Events API: until then, events are `[LoggerMessage]` logs. + +## Don't + +- Reference an OpenTelemetry, Aspire or vendor package from Application or Infrastructure. They publish with `System.Diagnostics`, and Presentation subscribes. +- Export anywhere but OTLP, or hard-code an endpoint. Settings come from the `OTEL_*` variables. +- Point the app straight at a backend, the dashboard included. It sends to a collector, and the collector decides where things go. +- Add a prerelease package, or hand-write instrumentation, to get a signal a package will give us later. +- Add a custom metric that repeats one the instrumentation already records. +- Put ids, tokens or personal data in span names, tags or metric tags. +- Mark a span as an error for a validation failure or a missing entity. The caller got an answer; the outcome tag and the log say what happened. +- Trace the health endpoints. Probes would bury everything else. +- Start a span with `new Activity(...)`. Use the layer's `ActivitySource`, so nothing is recorded when nobody is listening. + +## Check + +``` bash +dotnet test --filter "FullyQualifiedName~Telemetry|FullyQualifiedName~LoggingBehaviour" # use case span and end-to-end trace tests +docker compose up -d --build # then open http://localhost:18888 and make a request +``` diff --git a/AGENTS.md b/AGENTS.md index 9c78b49..afcb1b5 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -69,6 +69,7 @@ Each skill is a folder in `.agents/skills` with a `SKILL.md`. If your tool doesn | `time-provider` | Need the current date or time | | `configuration-and-environments` | Add a setting or work with environments | | `serilog` | Log something or change log settings | +| `telemetry` | Add a span or metric, or change where traces, metrics and logs go | | `health-checks` | Change what liveness or readiness checks | | `optional-token-auth` | Protect an endpoint or change authentication | | `xml-docs-and-openapi` | Document a public type, endpoint or model | diff --git a/Directory.Packages.props b/Directory.Packages.props index 7fb7ddc..4118819 100644 --- a/Directory.Packages.props +++ b/Directory.Packages.props @@ -21,12 +21,17 @@ + + + + + - + diff --git a/NUGET.md b/NUGET.md index ba1f792..8c0c22e 100644 --- a/NUGET.md +++ b/NUGET.md @@ -27,7 +27,7 @@ cd Acme.Reviews ## Run it ```bash -# Build the image and start it with sample data, plus the MCP Inspector and Seq +# Build the image and start it with sample data, plus the MCP Inspector, a collector and the Aspire dashboard docker compose up -d --build # Run the tests while you're here @@ -44,7 +44,7 @@ The server is open until you pass `--authority` and `--audience`, and then `/mcp - **Application**: commands and queries through [Mediator](https://github.com/martinothamar/Mediator), validated by [FluentValidation](https://github.com/FluentValidation/FluentValidation) and mapped by [Mapperly](https://mapperly.riok.app) - **Infrastructure**: [Entity Framework Core](https://learn.microsoft.com/ef/core) on SQLite, with optional sample data - **Tests**: [xUnit](https://xunit.net), [Shouldly](https://github.com/shouldly/shouldly) and [NSubstitute](https://github.com/nsubstitute/NSubstitute), each on its own throwaway database -- **Extras**: [Serilog](https://github.com/serilog/serilog) with Seq, health checks, a Dockerfile that runs as a non-root user, Docker Compose, and a GitHub Actions pipeline that won't let your coverage slip +- **Extras**: [OpenTelemetry](https://opentelemetry.io) traces, metrics and [Serilog](https://github.com/serilog/serilog) logs over OTLP, health checks, a Dockerfile that runs as a non-root user, Docker Compose, and a GitHub Actions pipeline that won't let your coverage slip ## Releases diff --git a/README.md b/README.md index 395624e..e30749c 100644 --- a/README.md +++ b/README.md @@ -36,7 +36,7 @@ That's three layers, four test projects, a Dockerfile and a CI pipeline. Go and ## Run it ```bash -# Build the image and start it with sample data, plus the MCP Inspector and Seq +# Build the image and start it with sample data, plus the MCP Inspector, a collector and the Aspire dashboard docker compose up -d --build # Ask the movies_search tool for a page of movies @@ -80,7 +80,7 @@ Yes, the sample movies are named by a corporate buzzword generator, and the crit Curl is a fine way to prove it works and a terrible way to spend an afternoon. Open the [MCP Inspector](https://github.com/modelcontextprotocol/inspector) at instead. It's already pointed at the server, so flip the switch to connect and open **Tools**. -There are six tools shaped around jobs rather than tables: `movies_search`, `movies_get`, `authors_search`, `reviews_list`, `reviews_write` and `reviews_delete`. Each has a description written for agents and hints that say what's read-only and what's destructive. Lists come back ten at a time, with a `totalCount` and a `nextOffset` when there's more to come, so an agent doesn't drown in its own context window. There are resources for every movie, author and review, and prompts for jobs like comparing two movies. The logs land in Seq at . +There are six tools shaped around jobs rather than tables: `movies_search`, `movies_get`, `authors_search`, `reviews_list`, `reviews_write` and `reviews_delete`. Each has a description written for agents and hints that say what's read-only and what's destructive. Lists come back ten at a time, with a `totalCount` and a `nextOffset` when there's more to come, so an agent doesn't drown in its own context window. There are resources for every movie, author and review, and prompts for jobs like comparing two movies. Its logs, traces and metrics land in the [Aspire dashboard](https://learn.microsoft.com/dotnet/aspire/fundamentals/dashboard/standalone) at . No Docker? `dotnet run --project src/Presentation` works too. Every other way to run it, from plain `docker run` to stamping a version into the image, is in [docs/RUN.md](docs/RUN.md). @@ -100,7 +100,7 @@ And around the edges: - **Tests** use [xUnit](https://xunit.net), [Shouldly](https://github.com/shouldly/shouldly) and [NSubstitute](https://github.com/nsubstitute/NSubstitute), with coverage from [Coverlet](https://github.com/coverlet-coverage/coverlet). Each test gets its own throwaway in-memory database, so no test can spoil another one's data. - **Sample data** comes from [Bogus](https://github.com/bchavez/Bogus), and only when `Database:SeedSampleData` is on. A real deployment never starts with fake reviews. -- **Logs** go through [Serilog](https://github.com/serilog/serilog), to the console and to [Seq](https://datalust.co/seq) when you run it with Docker Compose. Health checks answer at `/health/live` and `/health/ready`. +- **Telemetry** is [OpenTelemetry](https://opentelemetry.io) all the way: a span for every request, tool call and use case, metrics from ASP.NET Core, the MCP SDK, EF Core and the .NET runtime, and [Serilog](https://github.com/serilog/serilog) logs that know which trace they belong to. It all leaves over OTLP when `OTEL_EXPORTER_OTLP_ENDPOINT` is set, so point it at whatever backend you like. Docker Compose runs an [OpenTelemetry Collector](https://opentelemetry.io/docs/collector/) that forwards it to the Aspire dashboard, the same shape you'd run in production. Health checks answer at `/health/live` and `/health/ready`. - **Build rules** live in `Directory.Build.props`. Code style and the recommended analyzers run on every build, warnings fail it, and package versions sit in one place with [Central Package Management](https://learn.microsoft.com/nuget/consume-packages/central-package-management). - **The container** runs as a non-root user and has its own health check. - **The pipeline** builds, checks formatting, tests with a 95% coverage bar, makes sure the packed template still works, runs [CodeQL](https://codeql.github.com), reviews new dependencies and their licences, starts the image to check it actually answers, and scans the container and Dockerfile with [Trivy](https://trivy.dev). Then it sums the lot up in one comment on your pull request, so you know exactly who to blame. It needs no accounts, tokens or secrets, so your copy works the moment you push it. Trust is earned. diff --git a/docker-compose.yml b/docker-compose.yml index cc2fc9f..5de0958 100644 --- a/docker-compose.yml +++ b/docker-compose.yml @@ -10,12 +10,14 @@ services: - "8080:8080" environment: DOTNET_ENVIRONMENT: docker + OTEL_EXPORTER_OTLP_ENDPOINT: http://otel-collector:4317 + OTEL_EXPORTER_OTLP_PROTOCOL: grpc volumes: - movie-reviews-data:/app/data networks: - cleanmodelcontextprotocol_network depends_on: - - seq + - otel-collector inspector: image: ghcr.io/modelcontextprotocol/inspector:2.13.0 command: ["--web", "--transport", "http", "--server-url", "http://api:8080/mcp"] @@ -25,13 +27,23 @@ services: - cleanmodelcontextprotocol_network depends_on: - api - seq: - image: datalust/seq:2026.1.17473 + otel-collector: + image: otel/opentelemetry-collector:0.164.0 + volumes: + - ./otel-collector.yaml:/etc/otelcol/config.yaml:ro + ports: + - "4317:4317" + - "4318:4318" + networks: + - cleanmodelcontextprotocol_network + depends_on: + - aspire-dashboard + aspire-dashboard: + image: mcr.microsoft.com/dotnet/aspire-dashboard:13.6.2 ports: - - "5341:80" + - "18888:18888" environment: - ACCEPT_EULA: "Y" - SEQ_FIRSTRUN_NOAUTHENTICATION: "true" + ASPIRE_DASHBOARD_UNSECURED_ALLOW_ANONYMOUS: "true" networks: - cleanmodelcontextprotocol_network volumes: diff --git a/docs/RUN.md b/docs/RUN.md index 4db89c6..f401b40 100644 --- a/docs/RUN.md +++ b/docs/RUN.md @@ -1,6 +1,6 @@ # Running Clean Model Context Protocol -There are two pre-configured environments, `local` and `docker`. The matching `appsettings.*.json` files decide where logs go: the console when running locally, and a [Seq](https://datalust.co/seq) container when running in Docker. +There are two pre-configured environments, `local` and `docker`. Logs go to the console in both. Traces, metrics and logs also leave over OTLP whenever `OTEL_EXPORTER_OTLP_ENDPOINT` is set, which Docker Compose does for you. ## Database @@ -23,7 +23,7 @@ dotnet run --project ./src/Presentation ## Docker Compose -`docker-compose.yml` starts the app, the [MCP Inspector](https://github.com/modelcontextprotocol/inspector) already pointed at it, and a Seq container for logs. +`docker-compose.yml` starts the app, the [MCP Inspector](https://github.com/modelcontextprotocol/inspector) already pointed at it, and the [Aspire dashboard](https://learn.microsoft.com/dotnet/aspire/fundamentals/dashboard/standalone), which shows its logs, traces and metrics. The app sends everything to an [OpenTelemetry Collector](https://opentelemetry.io/docs/collector/), and the collector forwards it to the dashboard, the same shape as a production setup. The dashboard is only a container that receives OTLP; nothing in the solution depends on Aspire. ``` bash docker compose up -d --build @@ -31,7 +31,7 @@ docker compose up -d --build - App: (MCP endpoint, Streamable HTTP) - MCP Inspector: . Flip the switch on the server card to connect, then open **Tools** to see every tool with its description and input schema and run it. -- Seq: +- Aspire dashboard: - Health checks: (the process is up) and (the database can be reached). Both answer without a token. The image's `HEALTHCHECK` uses the live one. The container runs as the image's non-root `app` user. @@ -42,6 +42,21 @@ To shut the containers down: docker compose down ``` +## Telemetry + +The app always collects [OpenTelemetry](https://opentelemetry.io) traces and metrics, and exports them, along with its logs, only when `OTEL_EXPORTER_OTLP_ENDPOINT` is set. Every other standard `OTEL_*` variable works too, such as `OTEL_SERVICE_NAME`, `OTEL_EXPORTER_OTLP_PROTOCOL` and `OTEL_EXPORTER_OTLP_HEADERS`, so sending it to Grafana, Honeycomb, Seq or a collector is a settings change. + +In production, send the app's telemetry to a collector rather than straight to a backend. Run one beside the app (a sidecar or agent) or as a shared gateway, and give it your backend's exporter. The collector then owns batching, retries, sampling and scrubbing, and changing backend never touches the app. `otel-collector.yaml` is a starting point: an OTLP receiver, the memory limiter and batch processors, and one exporter to swap. + +To see a `dotnet run` in the dashboard, start the collector and the dashboard, and point the app at the collector: + +``` bash +docker compose up -d otel-collector +OTEL_EXPORTER_OTLP_ENDPOINT=http://localhost:4317 dotnet run --project ./src/Presentation +``` + +Every span, metric and log carries `service.version`, so you can always tell which build sent it. + ## HTTPS Outside the `local` and `Development` environments the app sends an HSTS header and redirects HTTP to HTTPS. The container only listens on HTTP, so in production put it behind a proxy or load balancer that ends TLS, and set `ASPNETCORE_FORWARDEDHEADERS_ENABLED=true` so the app knows the original request was HTTPS. diff --git a/otel-collector.yaml b/otel-collector.yaml new file mode 100644 index 0000000..c4c628f --- /dev/null +++ b/otel-collector.yaml @@ -0,0 +1,44 @@ +# The OpenTelemetry Collector sits between the app and wherever its telemetry is stored. The app only ever talks +# OTLP to the collector, so batching, retries, sampling, scrubbing and the choice of backend all live here. +# Locally it forwards everything to the Aspire dashboard. In production, run a collector beside the app (a sidecar +# or agent) or as a shared gateway, and swap or add exporters for your backend. +# Reference: https://opentelemetry.io/docs/collector/configuration/ + +receivers: + otlp: + protocols: + grpc: + endpoint: 0.0.0.0:4317 + http: + endpoint: 0.0.0.0:4318 + +processors: + # Refuses data before the collector runs out of memory, so it fails gracefully instead of crashing. + memory_limiter: + check_interval: 1s + limit_percentage: 80 + spike_limit_percentage: 25 + # Sends in batches rather than one call per span, metric or log. + batch: {} + +exporters: + # Add your backend here (another otlp_grpc or otlp_http exporter, for example) and list it in the pipelines below. + otlp_grpc/aspire: + endpoint: aspire-dashboard:18889 + tls: + insecure: true + +service: + pipelines: + traces: + receivers: [otlp] + processors: [memory_limiter, batch] + exporters: [otlp_grpc/aspire] + metrics: + receivers: [otlp] + processors: [memory_limiter, batch] + exporters: [otlp_grpc/aspire] + logs: + receivers: [otlp] + processors: [memory_limiter, batch] + exporters: [otlp_grpc/aspire] diff --git a/src/Application/Common/Behaviours/LoggingBehaviour.cs b/src/Application/Common/Behaviours/LoggingBehaviour.cs index 317f52c..7dbce1c 100644 --- a/src/Application/Common/Behaviours/LoggingBehaviour.cs +++ b/src/Application/Common/Behaviours/LoggingBehaviour.cs @@ -1,14 +1,16 @@ namespace CleanModelContextProtocol.Application.Common.Behaviours; +using System.Diagnostics; using Exceptions; using FluentValidation; using Mediator; using Microsoft.Extensions.Logging; +using Telemetry; /// -/// 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. +/// Logs how every request ended and how long it took, and gives it a span named after the request. Validation failures +/// and missing entities are logged as information, because the caller gets an answer. Anything else marks the span as +/// an error and 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. @@ -21,6 +23,9 @@ public partial class LoggingBehaviour(ILogger Handle(TMessage message, MessageHandlerDelegate next, CancellationToken cancellationToken) { + using var activity = ApplicationTelemetry.ActivitySource.StartActivity(RequestName); + _ = activity?.SetTag(ApplicationTelemetry.RequestNameTag, RequestName); + var started = timeProvider.GetTimestamp(); try @@ -29,6 +34,7 @@ public async ValueTask Handle(TMessage message, MessageHandlerDelegat var elapsed = timeProvider.GetElapsedTime(started).TotalMilliseconds; LogHandled(logger, RequestName, elapsed); + _ = activity?.SetTag(ApplicationTelemetry.RequestOutcomeTag, "handled"); return response; } @@ -38,6 +44,7 @@ public async ValueTask Handle(TMessage message, MessageHandlerDelegat var properties = string.Join(", ", exception.Errors.Select(e => e.PropertyName).Distinct()); LogInvalid(logger, RequestName, elapsed, properties); + _ = activity?.SetTag(ApplicationTelemetry.RequestOutcomeTag, "invalid"); throw; } @@ -46,6 +53,21 @@ public async ValueTask Handle(TMessage message, MessageHandlerDelegat var elapsed = timeProvider.GetElapsedTime(started).TotalMilliseconds; LogNotFound(logger, RequestName, elapsed, exception.Message); + _ = activity?.SetTag(ApplicationTelemetry.RequestOutcomeTag, "not_found"); + + throw; + } + catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested) + { + _ = activity?.SetTag(ApplicationTelemetry.RequestOutcomeTag, "cancelled"); + + throw; + } + catch (Exception exception) + { + _ = activity?.SetTag(ApplicationTelemetry.RequestOutcomeTag, "error") + .SetStatus(ActivityStatusCode.Error, exception.Message) + .AddException(exception); throw; } diff --git a/src/Application/Common/Telemetry/ApplicationTelemetry.cs b/src/Application/Common/Telemetry/ApplicationTelemetry.cs new file mode 100644 index 0000000..d4dc95b --- /dev/null +++ b/src/Application/Common/Telemetry/ApplicationTelemetry.cs @@ -0,0 +1,22 @@ +namespace CleanModelContextProtocol.Application.Common.Telemetry; + +using System.Diagnostics; + +/// +/// The spans the Application layer publishes, one for each use case. The presentation layer's startup subscribes to +/// . Nothing is recorded unless something is listening, so the layer needs no telemetry package. +/// +public static class ApplicationTelemetry +{ + /// The name of the activity source. + public const string Name = "CleanModelContextProtocol.Application"; + + /// The tag holding the request's type name, such as GetMoviesQuery. + public const string RequestNameTag = "application.request.name"; + + /// The tag holding how the request ended: handled, invalid, not_found, cancelled or error. + public const string RequestOutcomeTag = "application.request.outcome"; + + /// Starts a span for each use case. + internal static readonly ActivitySource ActivitySource = new(Name); +} diff --git a/src/Presentation/Extensions/WebApplicationBuilderExtensions.cs b/src/Presentation/Extensions/WebApplicationBuilderExtensions.cs index fe198bf..f49ede0 100644 --- a/src/Presentation/Extensions/WebApplicationBuilderExtensions.cs +++ b/src/Presentation/Extensions/WebApplicationBuilderExtensions.cs @@ -3,10 +3,12 @@ namespace CleanModelContextProtocol.Presentation.Extensions; using System.Diagnostics.CodeAnalysis; using System.Reflection; using Application; +using Application.Common.Telemetry; using CleanModelContextProtocol.Presentation.Authentication; using CleanModelContextProtocol.Presentation.Completions; using CleanModelContextProtocol.Presentation.Errors; using CleanModelContextProtocol.Presentation.Serialization; +using CleanModelContextProtocol.Presentation.Telemetry; using Infrastructure; using Microsoft.AspNetCore.Authentication.JwtBearer; using Microsoft.AspNetCore.Authorization; @@ -14,6 +16,10 @@ namespace CleanModelContextProtocol.Presentation.Extensions; using Microsoft.Extensions.Configuration; using Microsoft.Extensions.DependencyInjection; using ModelContextProtocol.AspNetCore.Authentication; +using OpenTelemetry; +using OpenTelemetry.Metrics; +using OpenTelemetry.Resources; +using OpenTelemetry.Trace; using Serilog; [ExcludeFromCodeCoverage] @@ -21,17 +27,67 @@ public static class WebApplicationBuilderExtensions { public static WebApplicationBuilder ConfigureApplicationBuilder(this WebApplicationBuilder builder) { - var assembly = Assembly.GetEntryAssembly(); + #region Telemetry + + var assembly = typeof(WebApplicationBuilderExtensions).Assembly; + var telemetry = TelemetrySettings.FromConfiguration(builder.Configuration, builder.Environment.EnvironmentName, assembly); + + var openTelemetry = builder.Services.AddOpenTelemetry() + .ConfigureResource(resource => resource.AddAttributes(telemetry.ResourceAttributes)) + .WithTracing(tracing => tracing + .AddSource(ApplicationTelemetry.Name, "Experimental.ModelContextProtocol") + .AddAspNetCoreInstrumentation(options => + { + // Probes call the health endpoints every few seconds, so tracing them would bury everything else. + options.Filter = context => !context.Request.Path.StartsWithSegments("/health"); + options.RecordException = true; + }) + .AddHttpClientInstrumentation(options => options.RecordException = true)) + .WithMetrics(metrics => metrics + .AddMeter( + "Microsoft.EntityFrameworkCore", + "Microsoft.AspNetCore.Authentication", + "Microsoft.AspNetCore.Authorization", + "Experimental.ModelContextProtocol") + .AddAspNetCoreInstrumentation() + .AddHttpClientInstrumentation() + .AddRuntimeInstrumentation() + .SetExemplarFilter(ExemplarFilterType.TraceBased)); + + // The exporters read OTEL_EXPORTER_OTLP_ENDPOINT and the other OTEL_* settings themselves. + if (telemetry.Enabled) + { + _ = openTelemetry.UseOtlpExporter(); + } + + #endregion Telemetry #region Logging - _ = builder.Services.AddSerilog((services, loggerConfiguration) => _ = loggerConfiguration.ReadFrom.Configuration(services.GetRequiredService()) + _ = builder.Services.AddSerilog((services, loggerConfiguration) => + { + var configuration = services.GetRequiredService(); + + _ = loggerConfiguration.ReadFrom.Configuration(configuration) .Enrich.WithProperty( "AssemblyVersion", - assembly?.GetCustomAttribute()?.Version) + assembly.GetCustomAttribute()?.Version) .Enrich.WithProperty( "AssemblyInformationalVersion", - assembly?.GetCustomAttribute()?.InformationalVersion)); + assembly.GetCustomAttribute()?.InformationalVersion); + + // Logs leave over OTLP too, carrying the trace and span IDs of whatever was running when they were written. + if (telemetry.Enabled) + { + _ = loggerConfiguration.WriteTo.OpenTelemetry( + options => + { + options.ResourceAttributes = telemetry.ResourceAttributes; + options.OnBeginSuppressInstrumentation = SuppressInstrumentationScope.Begin; + }, + key => configuration[key]); + } + }); #endregion Logging @@ -90,7 +146,7 @@ public static WebApplicationBuilder ConfigureApplicationBuilder(this WebApplicat Name = "clean-model-context-protocol", Title = "Clean Model Context Protocol", Description = "Movies, the authors who review them, and their star ratings, served by a Clean Architecture .NET MCP server.", - Version = assembly?.GetCustomAttribute()?.InformationalVersion ?? string.Empty, + Version = assembly.GetCustomAttribute()?.InformationalVersion ?? string.Empty, WebsiteUrl = "https://github.com/LeanMeanCleanApps/CleanModelContextProtocol", Icons = [ diff --git a/src/Presentation/Presentation.csproj b/src/Presentation/Presentation.csproj index 2dea3b1..21208ea 100644 --- a/src/Presentation/Presentation.csproj +++ b/src/Presentation/Presentation.csproj @@ -18,11 +18,16 @@ + + + + + - + diff --git a/src/Presentation/Telemetry/TelemetrySettings.cs b/src/Presentation/Telemetry/TelemetrySettings.cs new file mode 100644 index 0000000..f72f91c --- /dev/null +++ b/src/Presentation/Telemetry/TelemetrySettings.cs @@ -0,0 +1,50 @@ +namespace CleanModelContextProtocol.Presentation.Telemetry; + +using System.Reflection; +using Microsoft.Extensions.Configuration; + +/// +/// What every span, metric and log carries, and where they go. Telemetry is always collected, but it's only exported +/// when OTEL_EXPORTER_OTLP_ENDPOINT is set. Every other OTEL_* setting the OpenTelemetry SDK knows, such as +/// OTEL_EXPORTER_OTLP_PROTOCOL or OTEL_EXPORTER_OTLP_HEADERS, works as usual. +/// +public class TelemetrySettings +{ + /// The service name used when OTEL_SERVICE_NAME isn't set. + public const string DefaultServiceName = "CleanModelContextProtocol"; + + /// The service.name on everything this app sends. + public required string ServiceName { get; init; } + + /// The service.version: the informational version of the presentation assembly. + public required string ServiceVersion { get; init; } + + /// The deployment.environment.name, such as local or docker. + public required string EnvironmentName { get; init; } + + /// Where the OTLP exporters send everything. Empty means nothing is exported. + public string? OtlpEndpoint { get; init; } + + public bool Enabled => !string.IsNullOrWhiteSpace(this.OtlpEndpoint); + + /// The resource attributes, so traces, metrics and logs all land on the same service. + public Dictionary ResourceAttributes => new() + { + ["service.name"] = this.ServiceName, + ["service.version"] = this.ServiceVersion, + ["deployment.environment.name"] = this.EnvironmentName + }; + + public static TelemetrySettings FromConfiguration(IConfiguration configuration, string environmentName, Assembly assembly) + { + var serviceName = configuration["OTEL_SERVICE_NAME"]; + + return new TelemetrySettings + { + ServiceName = string.IsNullOrWhiteSpace(serviceName) ? DefaultServiceName : serviceName, + ServiceVersion = assembly.GetCustomAttribute()?.InformationalVersion ?? "unknown", + EnvironmentName = environmentName, + OtlpEndpoint = configuration["OTEL_EXPORTER_OTLP_ENDPOINT"] + }; + } +} diff --git a/src/Presentation/appsettings.docker.json b/src/Presentation/appsettings.docker.json index 96a9391..793d7a7 100644 --- a/src/Presentation/appsettings.docker.json +++ b/src/Presentation/appsettings.docker.json @@ -2,9 +2,9 @@ "Serilog": { "WriteTo": [ { - "Name": "Seq", + "Name": "Console", "Args": { - "serverUrl": "http://seq:5341" + "outputTemplate": "{Timestamp:HH:mm:ss.fff zzz} [{Level}] [{SourceContext}] {Message}{NewLine}{Exception}" } } ], diff --git a/src/Presentation/appsettings.json b/src/Presentation/appsettings.json index 120b474..cc4de01 100644 --- a/src/Presentation/appsettings.json +++ b/src/Presentation/appsettings.json @@ -5,6 +5,7 @@ "Override": { "Microsoft": "Information", "Microsoft.AspNetCore": "Warning", + "Microsoft.EntityFrameworkCore.Database.Command": "Warning", "System": "Error" } }, diff --git a/template/template.csproj b/template/template.csproj index c422d7a..99f2928 100644 --- a/template/template.csproj +++ b/template/template.csproj @@ -35,7 +35,7 @@ - + diff --git a/tests/Application.Tests.Unit/Common/Behaviours/LoggingBehaviourTests.cs b/tests/Application.Tests.Unit/Common/Behaviours/LoggingBehaviourTests.cs index 7389589..d0c3006 100644 --- a/tests/Application.Tests.Unit/Common/Behaviours/LoggingBehaviourTests.cs +++ b/tests/Application.Tests.Unit/Common/Behaviours/LoggingBehaviourTests.cs @@ -1,10 +1,12 @@ namespace CleanModelContextProtocol.Application.Tests.Unit.Common.Behaviours; +using System.Diagnostics; using Application.Authors.Entities; using Application.Authors.Queries.GetAuthorById; using Application.Common.Behaviours; using Application.Common.Enums; using Application.Common.Exceptions; +using Application.Common.Telemetry; using FluentValidation; using FluentValidation.Results; using Mediator; @@ -16,8 +18,14 @@ namespace CleanModelContextProtocol.Application.Tests.Unit.Common.Behaviours; using Shouldly; using Xunit; -public class LoggingBehaviourTests +public sealed class LoggingBehaviourTests : IDisposable { + private const string TestSourceName = "CleanModelContextProtocol.Application.Tests"; + + private static readonly ActivitySource TestSource = new(TestSourceName); + + private readonly ActivityListener listener; + private readonly List spans = []; private readonly FakeLogger> logger = new(); private readonly FakeTimeProvider timeProvider = new(); private readonly LoggingBehaviour behaviour; @@ -26,6 +34,22 @@ public class LoggingBehaviourTests public LoggingBehaviourTests() { this.behaviour = new LoggingBehaviour(this.logger, this.timeProvider); + + // Other tests run at the same time, so only spans from this test's own trace are kept. + this.listener = new ActivityListener + { + ShouldListenTo = source => source.Name is ApplicationTelemetry.Name or TestSourceName, + Sample = (ref _) => ActivitySamplingResult.AllDataAndRecorded, + ActivityStopped = activity => + { + lock (this.spans) + { + this.spans.Add(activity); + } + } + }; + + ActivitySource.AddActivityListener(this.listener); } [Fact] @@ -43,6 +67,8 @@ public async Task Handle_ShouldLogHandled_WhenNextSucceeds() return author; }); + using var parent = TestSource.StartActivity("Test")!; + // Act var result = await this.behaviour.Handle(this.query, next, token); @@ -56,6 +82,13 @@ public async Task Handle_ShouldLogHandled_WhenNextSucceeds() record.Level.ShouldBe(LogLevel.Information); record.Message.ShouldBe("GetAuthorByIdQuery handled in 12.5 ms"); record.GetStructuredStateValue("RequestName").ShouldBe("GetAuthorByIdQuery"); + + var span = this.SpanIn(parent); + span.DisplayName.ShouldBe("GetAuthorByIdQuery"); + span.ParentSpanId.ShouldBe(parent.SpanId); + span.Status.ShouldBe(ActivityStatusCode.Unset); + span.GetTagItem(ApplicationTelemetry.RequestNameTag).ShouldBe("GetAuthorByIdQuery"); + span.GetTagItem(ApplicationTelemetry.RequestOutcomeTag).ShouldBe("handled"); } [Fact] @@ -71,6 +104,8 @@ public async Task Handle_ShouldLogInvalid_WhenValidationFails() new ValidationFailure("Name", "'Name' must not be empty.") ])); + using var parent = TestSource.StartActivity("Test")!; + // Act var exception = await Should.ThrowAsync(async () => await this.behaviour.Handle(this.query, next, CancellationToken.None)); @@ -82,6 +117,10 @@ public async Task Handle_ShouldLogInvalid_WhenValidationFails() this.logger.Collector.Count.ShouldBe(1); record.Level.ShouldBe(LogLevel.Information); record.Message.ShouldBe("GetAuthorByIdQuery failed validation in 0.0 ms for Id, Name"); + + var span = this.SpanIn(parent); + span.Status.ShouldBe(ActivityStatusCode.Unset); + span.GetTagItem(ApplicationTelemetry.RequestOutcomeTag).ShouldBe("invalid"); } [Fact] @@ -96,6 +135,8 @@ public async Task Handle_ShouldLogNotFound_WhenEntityIsMissing() return new NotFoundException($"The {EntityType.Author} with the supplied id was not found."); }); + using var parent = TestSource.StartActivity("Test")!; + // Act _ = await Should.ThrowAsync(async () => await this.behaviour.Handle(this.query, next, CancellationToken.None)); @@ -105,6 +146,10 @@ public async Task Handle_ShouldLogNotFound_WhenEntityIsMissing() 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."); + + var span = this.SpanIn(parent); + span.Status.ShouldBe(ActivityStatusCode.Unset); + span.GetTagItem(ApplicationTelemetry.RequestOutcomeTag).ShouldBe("not_found"); } [Fact] @@ -115,10 +160,56 @@ public async Task Handle_ShouldNotLog_WhenExceptionIsUnexpected() _ = next(default!, default).ThrowsAsyncForAnyArgs(new InvalidOperationException("Broken")); + using var parent = TestSource.StartActivity("Test")!; + // Act _ = await Should.ThrowAsync(async () => await this.behaviour.Handle(this.query, next, CancellationToken.None)); // Assert this.logger.Collector.Count.ShouldBe(0); + + var span = this.SpanIn(parent); + span.Status.ShouldBe(ActivityStatusCode.Error); + span.StatusDescription.ShouldBe("Broken"); + span.GetTagItem(ApplicationTelemetry.RequestOutcomeTag).ShouldBe("error"); + span.Events.ShouldHaveSingleItem().Name.ShouldBe("exception"); + } + + [Fact] + public async Task Handle_ShouldNotLog_WhenCallerCancels() + { + // Arrange + using var tokenSource = new CancellationTokenSource(); + await tokenSource.CancelAsync(); + + var next = Substitute.For>(); + + _ = next(default!, default).ThrowsAsyncForAnyArgs(new OperationCanceledException(tokenSource.Token)); + + using var parent = TestSource.StartActivity("Test")!; + + // Act + _ = await Should.ThrowAsync(async () => await this.behaviour.Handle(this.query, next, tokenSource.Token)); + + // Assert + this.logger.Collector.Count.ShouldBe(0); + + var span = this.SpanIn(parent); + span.Status.ShouldBe(ActivityStatusCode.Unset); + span.Events.ShouldBeEmpty(); + span.GetTagItem(ApplicationTelemetry.RequestOutcomeTag).ShouldBe("cancelled"); + } + + public void Dispose() + { + this.listener.Dispose(); + } + + private Activity SpanIn(Activity parent) + { + lock (this.spans) + { + return this.spans.Single(s => s.TraceId == parent.TraceId && s.Source.Name == ApplicationTelemetry.Name); + } } } diff --git a/tests/Presentation.Tests.Integration/Telemetry/TelemetryTests.cs b/tests/Presentation.Tests.Integration/Telemetry/TelemetryTests.cs new file mode 100644 index 0000000..a77a683 --- /dev/null +++ b/tests/Presentation.Tests.Integration/Telemetry/TelemetryTests.cs @@ -0,0 +1,142 @@ +namespace CleanModelContextProtocol.Presentation.Tests.Integration.Telemetry; + +using System.Diagnostics; +using System.Net; +using System.Net.Http.Headers; +using System.Text; +using Application.Common.Telemetry; +using Microsoft.Extensions.DependencyInjection; +using OpenTelemetry.Metrics; +using OpenTelemetry.Trace; +using Shouldly; +using Xunit; + +public sealed class TelemetryTests : IDisposable +{ + private const string AspNetCoreSourceName = "Microsoft.AspNetCore"; + private const string McpSourceName = "Experimental.ModelContextProtocol"; + + private readonly ActivityListener listener; + private readonly List spans = []; + + public TelemetryTests() + { + // Other tests send requests at the same time, so only spans from this test's own trace are kept. + this.listener = new ActivityListener + { + ShouldListenTo = source => source.Name is AspNetCoreSourceName or McpSourceName or ApplicationTelemetry.Name, + Sample = (ref _) => ActivitySamplingResult.AllDataAndRecorded, + ActivityStopped = activity => + { + lock (this.spans) + { + this.spans.Add(activity); + } + } + }; + + ActivitySource.AddActivityListener(this.listener); + } + + [Fact] + public async Task ToolCall_ShouldTrace_FromHttpThroughToolAndUseCaseToDatabase() + { + // Arrange + using var application = new ModelContextProtocolApplication(); + using var client = application.CreateClient(); + + var traceId = ActivityTraceId.CreateRandom(); + using var request = new HttpRequestMessage(HttpMethod.Post, "/mcp") + { + Content = new StringContent( + /*lang=json,strict*/ + """{"jsonrpc":"2.0","id":1,"method":"tools/call","params":{"name":"movies_search","arguments":{"limit":5}}}""", + Encoding.UTF8, + "application/json") + }; + request.Headers.Accept.Add(new MediaTypeWithQualityHeaderValue("application/json")); + request.Headers.Accept.Add(new MediaTypeWithQualityHeaderValue("text/event-stream")); + request.Headers.Add("traceparent", $"00-{traceId}-{ActivitySpanId.CreateRandom()}-01"); + + // Act + using var response = await client.SendAsync(request); + _ = await response.Content.ReadAsStringAsync(); + + // Assert + response.StatusCode.ShouldBe(HttpStatusCode.OK); + + var trace = await this.ServerTraceIn(traceId); + var server = trace.Single(s => s.Source.Name == AspNetCoreSourceName); + var tool = trace.Single(s => s.Source.Name == McpSourceName); + var useCase = trace.Single(s => s.Source.Name == ApplicationTelemetry.Name); + + server.Kind.ShouldBe(ActivityKind.Server); + tool.DisplayName.ShouldContain("movies_search"); + useCase.DisplayName.ShouldBe("GetMoviesQuery"); + useCase.ParentSpanId.ShouldBe(tool.SpanId); + useCase.GetTagItem(ApplicationTelemetry.RequestOutcomeTag).ShouldBe("handled"); + } + + [Fact] + public async Task HealthRequest_ShouldNotBeTraced() + { + // Arrange + using var application = new ModelContextProtocolApplication(); + using var client = application.CreateClient(); + + var traceId = ActivityTraceId.CreateRandom(); + using var request = new HttpRequestMessage(HttpMethod.Get, "/health/ready"); + request.Headers.Add("traceparent", $"00-{traceId}-{ActivitySpanId.CreateRandom()}-01"); + + // Act + using var response = await client.SendAsync(request); + + // Assert + response.StatusCode.ShouldBe(HttpStatusCode.OK); + this.SpansIn(traceId).ShouldNotContain(s => s.Source.Name == AspNetCoreSourceName && s.IsAllDataRequested && s.Recorded); + } + + [Fact] + public async Task Startup_ShouldRegister_TracerAndMeterProviders_WhenExporting() + { + // Arrange + using var application = new ModelContextProtocolApplication(settings: new Dictionary + { + ["OTEL_EXPORTER_OTLP_ENDPOINT"] = "http://localhost:4317", + ["OTEL_SERVICE_NAME"] = "TelemetryTests" + }); + using var client = application.CreateClient(); + + // Act + using var response = await client.GetAsync("/health/live"); + + // Assert + response.StatusCode.ShouldBe(HttpStatusCode.OK); + _ = application.Services.GetRequiredService(); + _ = application.Services.GetRequiredService(); + } + + public void Dispose() + { + this.listener.Dispose(); + } + + private async Task> ServerTraceIn(ActivityTraceId traceId) + { + // The test server can hand back the response a moment before its request span stops, so wait for that span. + for (var attempt = 0; attempt < 50 && !this.SpansIn(traceId).Exists(s => s.Source.Name == AspNetCoreSourceName); attempt++) + { + await Task.Delay(TimeSpan.FromMilliseconds(100)); + } + + return this.SpansIn(traceId); + } + + private List SpansIn(ActivityTraceId traceId) + { + lock (this.spans) + { + return [.. this.spans.Where(s => s.TraceId == traceId)]; + } + } +} diff --git a/tests/Presentation.Tests.Unit/Telemetry/TelemetrySettingsTests.cs b/tests/Presentation.Tests.Unit/Telemetry/TelemetrySettingsTests.cs new file mode 100644 index 0000000..450140d --- /dev/null +++ b/tests/Presentation.Tests.Unit/Telemetry/TelemetrySettingsTests.cs @@ -0,0 +1,65 @@ +namespace CleanModelContextProtocol.Presentation.Tests.Unit.Telemetry; + +using System.Reflection; +using System.Reflection.Emit; +using CleanModelContextProtocol.Presentation.Telemetry; +using Microsoft.Extensions.Configuration; +using Shouldly; +using Xunit; + +public class TelemetrySettingsTests +{ + [Fact] + public void FromConfiguration_ShouldReturn_DisabledDefaults_WhenNothingIsSet() + { + // Arrange + var configuration = new ConfigurationBuilder().Build(); + var assembly = typeof(TelemetrySettingsTests).Assembly; + + // Act + var result = TelemetrySettings.FromConfiguration(configuration, "local", assembly); + + // Assert + result.Enabled.ShouldBeFalse(); + result.ServiceName.ShouldBe(TelemetrySettings.DefaultServiceName); + result.ServiceVersion.ShouldBe(assembly.GetCustomAttribute()!.InformationalVersion); + result.EnvironmentName.ShouldBe("local"); + } + + [Fact] + public void FromConfiguration_ShouldReturn_EnabledSettings_WhenEndpointIsSet() + { + // Arrange + var configuration = new ConfigurationBuilder() + .AddInMemoryCollection(new Dictionary + { + ["OTEL_EXPORTER_OTLP_ENDPOINT"] = "http://aspire-dashboard:18889", + ["OTEL_SERVICE_NAME"] = "movie-reviews" + }) + .Build(); + + // Act + var result = TelemetrySettings.FromConfiguration(configuration, "docker", typeof(TelemetrySettingsTests).Assembly); + + // Assert + result.Enabled.ShouldBeTrue(); + result.OtlpEndpoint.ShouldBe("http://aspire-dashboard:18889"); + result.ResourceAttributes["service.name"].ShouldBe("movie-reviews"); + result.ResourceAttributes["service.version"].ShouldBe(result.ServiceVersion); + result.ResourceAttributes["deployment.environment.name"].ShouldBe("docker"); + } + + [Fact] + public void FromConfiguration_ShouldReturn_UnknownVersion_WhenAssemblyHasNone() + { + // Arrange + var configuration = new ConfigurationBuilder().Build(); + var assembly = AssemblyBuilder.DefineDynamicAssembly(new AssemblyName("NoVersion"), AssemblyBuilderAccess.Run); + + // Act + var result = TelemetrySettings.FromConfiguration(configuration, "local", assembly); + + // Assert + result.ServiceVersion.ShouldBe("unknown"); + } +}