From 6fd0f027562db66b1c512b2ace20443c8309d685 Mon Sep 17 00:00:00 2001 From: Stephen Walsh <868017+stphnwlsh@users.noreply.github.com> Date: Wed, 4 Nov 2026 03:14:47 +0000 Subject: [PATCH 1/4] Trace, measure and log every request over OpenTelemetry Traces, metrics and logs leave over OTLP when OTEL_EXPORTER_OTLP_ENDPOINT is set. A TelemetryBehaviour gives every use case a span and two metrics, a command interceptor gives every SQL command a span, and Serilog sends its logs with the trace they belong to. The MCP SDK's own spans and metrics are switched on, so a tool call reads as one trace. Docker Compose swaps Seq for an OpenTelemetry Collector that forwards to the Aspire dashboard. --- .../configuration-and-environments/SKILL.md | 2 +- .agents/skills/docker-and-compose/SKILL.md | 4 +- .agents/skills/health-checks/SKILL.md | 4 +- .agents/skills/mcp-inspector/SKILL.md | 4 +- .agents/skills/mediator/SKILL.md | 5 +- .agents/skills/optional-token-auth/SKILL.md | 4 +- .agents/skills/serilog/SKILL.md | 34 ++- .agents/skills/telemetry/SKILL.md | 112 +++++++++ AGENTS.md | 1 + Directory.Packages.props | 8 +- NUGET.md | 4 +- README.md | 6 +- docker-compose.yml | 24 +- docs/RUN.md | 21 +- otel-collector.yaml | 44 ++++ src/Application/Application.csproj | 1 + .../Common/Behaviours/TelemetryBehaviour.cs | 88 +++++++ .../Common/Telemetry/ApplicationTelemetry.cs | 87 +++++++ src/Application/DependencyInjection.cs | 5 + src/Infrastructure/DependencyInjection.cs | 7 +- .../Telemetry/DatabaseCommandInterceptor.cs | 215 +++++++++++++++++ .../Telemetry/InfrastructureTelemetry.cs | 18 ++ .../WebApplicationBuilderExtensions.cs | 68 +++++- src/Presentation/Presentation.csproj | 7 +- .../Telemetry/TelemetrySettings.cs | 50 ++++ src/Presentation/appsettings.docker.json | 4 +- src/Presentation/appsettings.json | 1 + template/template.csproj | 2 +- .../Behaviours/TelemetryBehaviourTests.cs | 224 ++++++++++++++++++ .../DatabaseCommandInterceptorTests.cs | 194 +++++++++++++++ .../Telemetry/TelemetryTests.cs | 136 +++++++++++ .../Telemetry/TelemetrySettingsTests.cs | 65 +++++ 32 files changed, 1403 insertions(+), 46 deletions(-) create mode 100644 .agents/skills/telemetry/SKILL.md create mode 100644 otel-collector.yaml create mode 100644 src/Application/Common/Behaviours/TelemetryBehaviour.cs create mode 100644 src/Application/Common/Telemetry/ApplicationTelemetry.cs create mode 100644 src/Infrastructure/Telemetry/DatabaseCommandInterceptor.cs create mode 100644 src/Infrastructure/Telemetry/InfrastructureTelemetry.cs create mode 100644 src/Presentation/Telemetry/TelemetrySettings.cs create mode 100644 tests/Application.Tests.Unit/Common/Behaviours/TelemetryBehaviourTests.cs create mode 100644 tests/Infrastructure.Tests.Integration/Telemetry/DatabaseCommandInterceptorTests.cs create mode 100644 tests/Presentation.Tests.Integration/Telemetry/TelemetryTests.cs create mode 100644 tests/Presentation.Tests.Unit/Telemetry/TelemetrySettingsTests.cs 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..d3bb448 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. `TelemetryBehaviour` is registered first, so its span wraps everything else and the logs inside it carry its trace (`telemetry`). `LoggingBehaviour` comes next and times and logs everything inside it, validation failures included (`serilog`). `ValidationBehaviour` is last, so invalid requests never reach a handler. ## Steps @@ -37,7 +37,10 @@ Behaviours run in the order they're registered. The first one registered is the // src/Application/DependencyInjection.cs _ = services.AddValidatorsFromAssembly(Assembly.GetExecutingAssembly(), ServiceLifetime.Transient); services.TryAddSingleton(TimeProvider.System); +_ = services.AddMetrics(); +_ = services.AddSingleton(); +_ = services.AddScoped(typeof(IPipelineBehavior<,>), typeof(TelemetryBehaviour<,>)); _ = services.AddScoped(typeof(IPipelineBehavior<,>), typeof(LoggingBehaviour<,>)); _ = services.AddScoped(typeof(IPipelineBehavior<,>), typeof(ValidationBehaviour<,>)); ``` 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..eae20d9 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` | | +| `docker` | Console, and OTLP through the collector to the Aspire dashboard | , or `docker compose logs` | | Lambda, anywhere | Console, as compact JSON | CloudWatch Logs, or `docker compose logs` for the emulator | +| 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` (each SQL command already has a span), 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..2235d7e --- /dev/null +++ b/.agents/skills/telemetry/SKILL.md @@ -0,0 +1,112 @@ +--- +name: telemetry +description: How OpenTelemetry traces, metrics and logs work - the standard OTEL_* settings that switch exporting on, the TelemetryBehaviour span and metrics for every use case, the database command spans, baggage, span events, 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. 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, each use case and each SQL command, plus outgoing HTTP calls | Presentation instrumentation, `TelemetryBehaviour`, `DatabaseCommandInterceptor` | +| Metrics | Request counts and durations per use case, EF Core's own meter, ASP.NET Core, HttpClient and runtime metrics, with exemplars linking a measurement to a trace | `ApplicationTelemetry`, `Microsoft.EntityFrameworkCore`, Presentation instrumentation | +| Logs | Every Serilog event, carrying the trace and span IDs of whatever was running when it was written | Serilog's OpenTelemetry sink (`serilog`) | +| Baggage | Propagated with the trace context, and copied onto each use case span as tags | W3C `baggage` header, `TelemetryBehaviour` | +| Events | Span events for validation failures and missing entities, and `exception` events for errors | `TelemetryBehaviour`, `DatabaseCommandInterceptor` | + +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 and meter: a span per request, `application.requests` and `application.request.duration` | `System.Diagnostics` only, so Application stays free of telemetry packages | +| Infrastructure | `InfrastructureTelemetry.Name` activity source: a client span per database command, with `db.system.name`, `db.namespace`, `db.operation.name` and the parameterised `db.query.text` | `DatabaseCommandInterceptor`, an EF Core `DbCommandInterceptor` | +| Infrastructure | `Microsoft.EntityFrameworkCore` meter: queries, saves, active contexts, compiled query cache | Built into EF Core; startup subscribes to `InfrastructureTelemetry.EntityFrameworkCoreMeterName` | +| 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`, flushed before the function returns | + +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: `TelemetryBehaviour` gives it a span and metrics. Its span is named after the request class. +2. To trace work inside Application or Infrastructure, start a child span from the layer's own `ActivitySource` with `using var activity = ApplicationTelemetry.ActivitySource.StartActivity("Name");`. Set tags only when `activity is { IsAllDataRequested: true }`, and use the [semantic convention](https://opentelemetry.io/docs/specs/semconv/) names where one exists. +3. To add a metric, add an instrument to `ApplicationTelemetry`, created from the `IMeterFactory` meter, with a unit and a description. Keep tag values to a small fixed set; never tag a metric with an id. +4. A new dependency in Infrastructure (a queue, an HTTP API) gets its spans from its own instrumentation package if a stable one exists. Subscribe to its source or meter name in the presentation layer's startup, and expose the name as a constant in `InfrastructureTelemetry`. +5. Use stable packages only. When the only instrumentation is a prerelease package, write the small piece we need, as `DatabaseCommandInterceptor` does, and add it to the watch list below. +6. Test spans with an `ActivityListener` that keeps only the test's own trace, and metrics with `MetricCollector` from `Microsoft.Extensions.Diagnostics.Testing` (`unit-tests`). The integration tests send a `traceparent` header and check the request, use case and database 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/TelemetryBehaviour.cs +using var activity = ApplicationTelemetry.ActivitySource.StartActivity(RequestName); + +if (activity is { IsAllDataRequested: true }) +{ + _ = activity.SetTag(ApplicationTelemetry.TagNames.RequestName, RequestName); + + foreach (var (key, value) in activity.Baggage) + { + _ = activity.SetTag(key, value); + } +} +``` + +```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`: replaces `DatabaseCommandInterceptor`. +- Profiles: there's no stable .NET SDK for the profiling signal. +- The OpenTelemetry Events API: until then, events are span events and `[LoggerMessage]` logs with event IDs. + +## 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 to get a signal. +- Put ids, tokens or personal data in span names, tags or metric tags. `db.query.text` is safe only because EF Core sends parameters, not values. +- Mark a span as an error for a validation failure or a missing entity. The caller got an answer; record a span event instead. +- 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" # behaviour, interceptor 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..e6f6adf 100644 --- a/Directory.Packages.props +++ b/Directory.Packages.props @@ -14,6 +14,7 @@ + @@ -21,12 +22,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..252925f 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, use case and SQL command, metrics from ASP.NET Core, the MCP SDK, EF Core and each use case, 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/Application.csproj b/src/Application/Application.csproj index 6bfaa72..dcb1c22 100644 --- a/src/Application/Application.csproj +++ b/src/Application/Application.csproj @@ -7,6 +7,7 @@ + diff --git a/src/Application/Common/Behaviours/TelemetryBehaviour.cs b/src/Application/Common/Behaviours/TelemetryBehaviour.cs new file mode 100644 index 0000000..8aac399 --- /dev/null +++ b/src/Application/Common/Behaviours/TelemetryBehaviour.cs @@ -0,0 +1,88 @@ +namespace CleanModelContextProtocol.Application.Common.Behaviours; + +using System.Diagnostics; +using Exceptions; +using FluentValidation; +using Mediator; +using Telemetry; + +/// +/// Gives every request a span named after it and records it on the request counter and duration histogram. Baggage +/// from the caller is copied onto the span as tags. Validation failures and missing entities become span events, +/// because the caller still gets an answer, and anything else marks the span as an error with the exception attached. +/// +/// The request being sent. +/// The response the handler returns. +/// Records the request metrics. +/// The clock that times each request. +public class TelemetryBehaviour(ApplicationTelemetry telemetry, TimeProvider timeProvider) : IPipelineBehavior + where TMessage : IMessage +{ + private static readonly string RequestName = typeof(TMessage).Name; + + public async ValueTask Handle(TMessage message, MessageHandlerDelegate next, CancellationToken cancellationToken) + { + using var activity = ApplicationTelemetry.ActivitySource.StartActivity(RequestName); + + if (activity is { IsAllDataRequested: true }) + { + _ = activity.SetTag(ApplicationTelemetry.TagNames.RequestName, RequestName); + + foreach (var (key, value) in activity.Baggage) + { + _ = activity.SetTag(key, value); + } + } + + var started = timeProvider.GetTimestamp(); + var outcome = ApplicationTelemetry.RequestOutcome.Handled; + + try + { + return await next(message, cancellationToken); + } + catch (ValidationException exception) + { + outcome = ApplicationTelemetry.RequestOutcome.Invalid; + + _ = activity?.AddEvent(new ActivityEvent("validation_failed", tags: new ActivityTagsCollection + { + [ApplicationTelemetry.TagNames.ValidationProperties] = string.Join(", ", exception.Errors.Select(e => e.PropertyName).Distinct()) + })); + + throw; + } + catch (NotFoundException exception) + { + outcome = ApplicationTelemetry.RequestOutcome.NotFound; + + _ = activity?.AddEvent(new ActivityEvent("not_found", tags: new ActivityTagsCollection + { + ["exception.message"] = exception.Message + })); + + throw; + } + catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested) + { + outcome = ApplicationTelemetry.RequestOutcome.Cancelled; + + throw; + } + catch (Exception exception) + { + outcome = ApplicationTelemetry.RequestOutcome.Error; + + _ = activity?.SetStatus(ActivityStatusCode.Error, exception.Message); + _ = activity?.AddException(exception); + + throw; + } + finally + { + _ = activity?.SetTag(ApplicationTelemetry.TagNames.RequestOutcome, outcome); + + telemetry.RecordRequest(RequestName, outcome, timeProvider.GetElapsedTime(started)); + } + } +} diff --git a/src/Application/Common/Telemetry/ApplicationTelemetry.cs b/src/Application/Common/Telemetry/ApplicationTelemetry.cs new file mode 100644 index 0000000..4f2fccd --- /dev/null +++ b/src/Application/Common/Telemetry/ApplicationTelemetry.cs @@ -0,0 +1,87 @@ +namespace CleanModelContextProtocol.Application.Common.Telemetry; + +using System.Diagnostics; +using System.Diagnostics.Metrics; + +/// +/// The spans and metrics the Application layer publishes. Both use the name in , which the +/// presentation layer's startup subscribes to. Nothing is recorded unless something is listening, so the layer stays +/// free of any telemetry package. +/// +public sealed class ApplicationTelemetry +{ + /// The name of the activity source and the meter. + public const string Name = "CleanModelContextProtocol.Application"; + + /// Starts a span for each use case. + internal static readonly ActivitySource ActivitySource = new(Name); + + private readonly Counter requests; + private readonly Histogram duration; + + /// Creates the meter and its instruments. + /// Owns the meter, so it's disposed with the container. + public ApplicationTelemetry(IMeterFactory meterFactory) + { + var meter = meterFactory.Create(Name); + + this.requests = meter.CreateCounter( + "application.requests", + "{request}", + "The use case requests sent through the pipeline."); + + this.duration = meter.CreateHistogram( + "application.request.duration", + "s", + "How long each use case request took.", + advice: new InstrumentAdvice { HistogramBucketBoundaries = [0.001, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10] }); + } + + /// Records one finished request on both instruments. + /// The request's type name. + /// How it ended, one of the values. + /// How long it took. + public void RecordRequest(string requestName, string outcome, TimeSpan elapsed) + { + var tags = new TagList + { + { TagNames.RequestName, requestName }, + { TagNames.RequestOutcome, outcome } + }; + + this.requests.Add(1, tags); + this.duration.Record(elapsed.TotalSeconds, tags); + } + + /// The tag names used on the spans and metrics. + public static class TagNames + { + /// The request's type name, such as GetMoviesQuery. + public const string RequestName = "application.request.name"; + + /// How the request ended. + public const string RequestOutcome = "application.request.outcome"; + + /// The properties that failed validation, comma separated. + public const string ValidationProperties = "application.validation.properties"; + } + + /// How a request ended. + public static class RequestOutcome + { + /// The handler returned a response. + public const string Handled = "handled"; + + /// The request failed validation. + public const string Invalid = "invalid"; + + /// What the request asked for doesn't exist. + public const string NotFound = "not_found"; + + /// The caller cancelled the request. + public const string Cancelled = "cancelled"; + + /// Something unexpected went wrong. + public const string Error = "error"; + } +} diff --git a/src/Application/DependencyInjection.cs b/src/Application/DependencyInjection.cs index b3d8a83..ada5bee 100644 --- a/src/Application/DependencyInjection.cs +++ b/src/Application/DependencyInjection.cs @@ -3,6 +3,7 @@ namespace CleanModelContextProtocol.Application; using System.Diagnostics.CodeAnalysis; using System.Reflection; using Common.Behaviours; +using Common.Telemetry; using FluentValidation; using Mediator; using Microsoft.Extensions.DependencyInjection; @@ -15,7 +16,11 @@ public static IServiceCollection AddApplication(this IServiceCollection services { _ = services.AddValidatorsFromAssembly(Assembly.GetExecutingAssembly(), ServiceLifetime.Transient); services.TryAddSingleton(TimeProvider.System); + _ = services.AddMetrics(); + _ = services.AddSingleton(); + // The first registered runs outermost: the span wraps the logs, and both see validation failures. + _ = services.AddScoped(typeof(IPipelineBehavior<,>), typeof(TelemetryBehaviour<,>)); _ = services.AddScoped(typeof(IPipelineBehavior<,>), typeof(LoggingBehaviour<,>)); _ = services.AddScoped(typeof(IPipelineBehavior<,>), typeof(ValidationBehaviour<,>)); diff --git a/src/Infrastructure/DependencyInjection.cs b/src/Infrastructure/DependencyInjection.cs index ea048c0..48ab376 100644 --- a/src/Infrastructure/DependencyInjection.cs +++ b/src/Infrastructure/DependencyInjection.cs @@ -10,6 +10,7 @@ namespace CleanModelContextProtocol.Infrastructure; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.DependencyInjection.Extensions; using Microsoft.Extensions.Diagnostics.HealthChecks; +using Telemetry; public static class DependencyInjection { @@ -23,10 +24,12 @@ public static IServiceCollection AddInfrastructure(this IServiceCollection servi // Registered through a factory, so the container owns it and closes its connection when the app stops. _ = services.AddSingleton(_ => new MovieReviewsDatabase(databaseConnectionString)); - // Nothing reads an entity to change it, so queries don't track by default. + // Nothing reads an entity to change it, so queries don't track by default. The interceptor gives each command a + // span when something is listening. _ = services.AddDbContext(options => options .UseSqlite(databaseConnectionString) - .UseQueryTrackingBehavior(QueryTrackingBehavior.NoTracking)); + .UseQueryTrackingBehavior(QueryTrackingBehavior.NoTracking) + .AddInterceptors(DatabaseCommandInterceptor.Instance)); _ = services.AddSingleton(); _ = services.AddScoped(); diff --git a/src/Infrastructure/Telemetry/DatabaseCommandInterceptor.cs b/src/Infrastructure/Telemetry/DatabaseCommandInterceptor.cs new file mode 100644 index 0000000..155cba9 --- /dev/null +++ b/src/Infrastructure/Telemetry/DatabaseCommandInterceptor.cs @@ -0,0 +1,215 @@ +namespace CleanModelContextProtocol.Infrastructure.Telemetry; + +using System.Buffers; +using System.Data.Common; +using System.Diagnostics; +using System.Runtime.CompilerServices; +using Microsoft.EntityFrameworkCore.Diagnostics; + +/// +/// Gives every database command EF Core runs a client span, following the OpenTelemetry database conventions. EF Core +/// publishes metrics but no spans, and the OpenTelemetry EF Core instrumentation is still a prerelease package, so +/// this stands in for it until that package is stable. The SQL is the parameterised text EF Core sends, so no values +/// are recorded. When nothing is listening, no span is started. +/// +internal sealed class DatabaseCommandInterceptor : DbCommandInterceptor +{ + /// The one instance every context shares; it holds no per-request state of its own. + public static readonly DatabaseCommandInterceptor Instance = new(); + + private static readonly SearchValues KeywordEnd = SearchValues.Create(" \t\r\n(;"); + + private readonly ConditionalWeakTable activities = []; + + #region Executing + + public override InterceptionResult ReaderExecuting(DbCommand command, CommandEventData eventData, InterceptionResult result) + { + this.Start(command, eventData); + + return result; + } + + public override ValueTask> ReaderExecutingAsync(DbCommand command, CommandEventData eventData, InterceptionResult result, CancellationToken cancellationToken = default) + { + this.Start(command, eventData); + + return ValueTask.FromResult(result); + } + + public override InterceptionResult NonQueryExecuting(DbCommand command, CommandEventData eventData, InterceptionResult result) + { + this.Start(command, eventData); + + return result; + } + + public override ValueTask> NonQueryExecutingAsync(DbCommand command, CommandEventData eventData, InterceptionResult result, CancellationToken cancellationToken = default) + { + this.Start(command, eventData); + + return ValueTask.FromResult(result); + } + + public override InterceptionResult ScalarExecuting(DbCommand command, CommandEventData eventData, InterceptionResult result) + { + this.Start(command, eventData); + + return result; + } + + public override ValueTask> ScalarExecutingAsync(DbCommand command, CommandEventData eventData, InterceptionResult result, CancellationToken cancellationToken = default) + { + this.Start(command, eventData); + + return ValueTask.FromResult(result); + } + + #endregion Executing + + #region Executed + + public override DbDataReader ReaderExecuted(DbCommand command, CommandExecutedEventData eventData, DbDataReader result) + { + this.Stop(command, null); + + return result; + } + + public override ValueTask ReaderExecutedAsync(DbCommand command, CommandExecutedEventData eventData, DbDataReader result, CancellationToken cancellationToken = default) + { + this.Stop(command, null); + + return ValueTask.FromResult(result); + } + + public override int NonQueryExecuted(DbCommand command, CommandExecutedEventData eventData, int result) + { + this.Stop(command, null); + + return result; + } + + public override ValueTask NonQueryExecutedAsync(DbCommand command, CommandExecutedEventData eventData, int result, CancellationToken cancellationToken = default) + { + this.Stop(command, null); + + return ValueTask.FromResult(result); + } + + public override object? ScalarExecuted(DbCommand command, CommandExecutedEventData eventData, object? result) + { + this.Stop(command, null); + + return result; + } + + public override ValueTask ScalarExecutedAsync(DbCommand command, CommandExecutedEventData eventData, object? result, CancellationToken cancellationToken = default) + { + this.Stop(command, null); + + return ValueTask.FromResult(result); + } + + #endregion Executed + + #region Failed + + public override void CommandFailed(DbCommand command, CommandErrorEventData eventData) + { + this.Stop(command, eventData.Exception); + } + + public override Task CommandFailedAsync(DbCommand command, CommandErrorEventData eventData, CancellationToken cancellationToken = default) + { + this.Stop(command, eventData.Exception); + + return Task.CompletedTask; + } + + public override void CommandCanceled(DbCommand command, CommandEndEventData eventData) + { + this.Stop(command, null); + } + + public override Task CommandCanceledAsync(DbCommand command, CommandEndEventData eventData, CancellationToken cancellationToken = default) + { + this.Stop(command, null); + + return Task.CompletedTask; + } + + #endregion Failed + + #region Spans + + private void Start(DbCommand command, CommandEventData eventData) + { + if (!InfrastructureTelemetry.ActivitySource.HasListeners()) + { + return; + } + + var system = SystemName(eventData.Context?.Database.ProviderName); + var operation = OperationName(command.CommandText); + var activity = InfrastructureTelemetry.ActivitySource.StartActivity(operation ?? system, ActivityKind.Client); + + if (activity is null) + { + return; + } + + if (activity.IsAllDataRequested) + { + _ = activity.SetTag("db.system.name", system); + _ = activity.SetTag("db.namespace", command.Connection?.Database); + _ = activity.SetTag("db.operation.name", operation); + _ = activity.SetTag("db.query.text", command.CommandText); + } + + this.activities.AddOrUpdate(command, activity); + } + + private void Stop(DbCommand command, Exception? exception) + { + if (!this.activities.TryGetValue(command, out var activity)) + { + return; + } + + _ = this.activities.Remove(command); + + if (exception is not null) + { + _ = activity.SetTag("error.type", exception.GetType().FullName); + _ = activity.SetStatus(ActivityStatusCode.Error, exception.Message); + _ = activity.AddException(exception); + } + + activity.Stop(); + } + + /// Maps the EF Core provider to the db.system.name the conventions use. + internal static string SystemName(string? providerName) + { + return providerName switch + { + "Microsoft.EntityFrameworkCore.Sqlite" => "sqlite", + "Microsoft.EntityFrameworkCore.SqlServer" => "microsoft.sql_server", + "Npgsql.EntityFrameworkCore.PostgreSQL" => "postgresql", + _ => "other_sql" + }; + } + + /// The SQL keyword the command starts with, such as SELECT, or null when there isn't one. + internal static string? OperationName(string? commandText) + { + var text = commandText.AsSpan().TrimStart(); + var end = text.IndexOfAny(KeywordEnd); + var keyword = end < 0 ? text : text[..end]; + + return keyword.IsEmpty ? null : keyword.ToString().ToUpperInvariant(); + } + + #endregion Spans +} diff --git a/src/Infrastructure/Telemetry/InfrastructureTelemetry.cs b/src/Infrastructure/Telemetry/InfrastructureTelemetry.cs new file mode 100644 index 0000000..10de815 --- /dev/null +++ b/src/Infrastructure/Telemetry/InfrastructureTelemetry.cs @@ -0,0 +1,18 @@ +namespace CleanModelContextProtocol.Infrastructure.Telemetry; + +using System.Diagnostics; + +/// +/// The spans and meters Infrastructure publishes, for the presentation layer's startup to subscribe to. +/// +public static class InfrastructureTelemetry +{ + /// The name of the activity source that gives each database command a span. + public const string Name = "CleanModelContextProtocol.Infrastructure"; + + /// The meter EF Core publishes itself: queries, saves, active contexts and the compiled query cache. + public const string EntityFrameworkCoreMeterName = "Microsoft.EntityFrameworkCore"; + + /// Starts a span for each database command. + internal static readonly ActivitySource ActivitySource = new(Name); +} diff --git a/src/Presentation/Extensions/WebApplicationBuilderExtensions.cs b/src/Presentation/Extensions/WebApplicationBuilderExtensions.cs index fe198bf..4704c5d 100644 --- a/src/Presentation/Extensions/WebApplicationBuilderExtensions.cs +++ b/src/Presentation/Extensions/WebApplicationBuilderExtensions.cs @@ -3,17 +3,24 @@ 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 Infrastructure.Telemetry; using Microsoft.AspNetCore.Authentication.JwtBearer; using Microsoft.AspNetCore.Authorization; using Microsoft.AspNetCore.Builder; 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 +28,68 @@ 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, InfrastructureTelemetry.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( + ApplicationTelemetry.Name, + InfrastructureTelemetry.EntityFrameworkCoreMeterName, + "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 +148,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/TelemetryBehaviourTests.cs b/tests/Application.Tests.Unit/Common/Behaviours/TelemetryBehaviourTests.cs new file mode 100644 index 0000000..25a87b4 --- /dev/null +++ b/tests/Application.Tests.Unit/Common/Behaviours/TelemetryBehaviourTests.cs @@ -0,0 +1,224 @@ +namespace CleanModelContextProtocol.Application.Tests.Unit.Common.Behaviours; + +using System.Diagnostics; +using System.Diagnostics.Metrics; +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; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Diagnostics.Metrics.Testing; +using Microsoft.Extensions.Time.Testing; +using NSubstitute; +using NSubstitute.ExceptionExtensions; +using Shouldly; +using Xunit; + +public sealed class TelemetryBehaviourTests : IDisposable +{ + private const string TestSourceName = "CleanModelContextProtocol.Application.Tests"; + + private static readonly ActivitySource TestSource = new(TestSourceName); + + private readonly ServiceProvider services = new ServiceCollection().AddMetrics().BuildServiceProvider(); + private readonly ActivityListener listener; + private readonly List spans = []; + private readonly FakeTimeProvider timeProvider = new(); + private readonly MetricCollector requests; + private readonly MetricCollector duration; + private readonly TelemetryBehaviour behaviour; + private readonly GetAuthorByIdQuery query = new() { Id = Guid.NewGuid() }; + private readonly MessageHandlerDelegate next = Substitute.For>(); + + public TelemetryBehaviourTests() + { + // 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); + + var meterFactory = this.services.GetRequiredService(); + + this.requests = new MetricCollector(meterFactory, ApplicationTelemetry.Name, "application.requests"); + this.duration = new MetricCollector(meterFactory, ApplicationTelemetry.Name, "application.request.duration"); + this.behaviour = new TelemetryBehaviour(new ApplicationTelemetry(meterFactory), this.timeProvider); + } + + [Fact] + public async Task Handle_ShouldRecordHandled_WhenNextSucceeds() + { + // Arrange + var author = new Author(Guid.NewGuid(), "Test", "Test", []); + + _ = this.next(default!, default).ReturnsForAnyArgs(_ => + { + this.timeProvider.Advance(TimeSpan.FromMilliseconds(12.5)); + return author; + }); + + using var parent = TestSource.StartActivity("Test")!; + + // Act + var result = await this.behaviour.Handle(this.query, this.next, CancellationToken.None); + + // Assert + result.ShouldBe(author); + + var span = this.SpanIn(parent); + span.DisplayName.ShouldBe("GetAuthorByIdQuery"); + span.ParentSpanId.ShouldBe(parent.SpanId); + span.Status.ShouldBe(ActivityStatusCode.Unset); + span.GetTagItem(ApplicationTelemetry.TagNames.RequestName).ShouldBe("GetAuthorByIdQuery"); + span.GetTagItem(ApplicationTelemetry.TagNames.RequestOutcome).ShouldBe(ApplicationTelemetry.RequestOutcome.Handled); + + var count = this.requests.LastMeasurement!; + count.Value.ShouldBe(1); + count.Tags[ApplicationTelemetry.TagNames.RequestName].ShouldBe("GetAuthorByIdQuery"); + count.Tags[ApplicationTelemetry.TagNames.RequestOutcome].ShouldBe(ApplicationTelemetry.RequestOutcome.Handled); + this.duration.LastMeasurement!.Value.ShouldBe(0.0125, 0.000001); + } + + [Fact] + public async Task Handle_ShouldCopyBaggage_ToSpanTags() + { + // Arrange + _ = this.next(default!, default).ReturnsForAnyArgs(new Author(Guid.NewGuid(), "Test", "Test", [])); + + using var parent = TestSource.StartActivity("Test")!; + _ = parent.AddBaggage("tenant.id", "acme"); + + // Act + _ = await this.behaviour.Handle(this.query, this.next, CancellationToken.None); + + // Assert + this.SpanIn(parent).GetTagItem("tenant.id").ShouldBe("acme"); + } + + [Fact] + public async Task Handle_ShouldRecordInvalid_WhenValidationFails() + { + // Arrange + _ = this.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.") + ])); + + using var parent = TestSource.StartActivity("Test")!; + + // Act + _ = await Should.ThrowAsync(async () => await this.behaviour.Handle(this.query, this.next, CancellationToken.None)); + + // Assert + var span = this.SpanIn(parent); + span.Status.ShouldBe(ActivityStatusCode.Unset); + span.GetTagItem(ApplicationTelemetry.TagNames.RequestOutcome).ShouldBe(ApplicationTelemetry.RequestOutcome.Invalid); + + var spanEvent = span.Events.ShouldHaveSingleItem(); + spanEvent.Name.ShouldBe("validation_failed"); + spanEvent.Tags.ShouldContain(new KeyValuePair(ApplicationTelemetry.TagNames.ValidationProperties, "Id, Name")); + + this.requests.LastMeasurement!.Tags[ApplicationTelemetry.TagNames.RequestOutcome].ShouldBe(ApplicationTelemetry.RequestOutcome.Invalid); + } + + [Fact] + public async Task Handle_ShouldRecordNotFound_WhenEntityIsMissing() + { + // Arrange + _ = this.next(default!, default).ThrowsAsyncForAnyArgs(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, this.next, CancellationToken.None)); + + // Assert + var span = this.SpanIn(parent); + span.Status.ShouldBe(ActivityStatusCode.Unset); + span.GetTagItem(ApplicationTelemetry.TagNames.RequestOutcome).ShouldBe(ApplicationTelemetry.RequestOutcome.NotFound); + + var spanEvent = span.Events.ShouldHaveSingleItem(); + spanEvent.Name.ShouldBe("not_found"); + spanEvent.Tags.ShouldContain(new KeyValuePair("exception.message", "The Author with the supplied id was not found.")); + + this.requests.LastMeasurement!.Tags[ApplicationTelemetry.TagNames.RequestOutcome].ShouldBe(ApplicationTelemetry.RequestOutcome.NotFound); + } + + [Fact] + public async Task Handle_ShouldRecordCancelled_WhenCallerCancels() + { + // Arrange + using var tokenSource = new CancellationTokenSource(); + await tokenSource.CancelAsync(); + + _ = this.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, this.next, tokenSource.Token)); + + // Assert + var span = this.SpanIn(parent); + span.Status.ShouldBe(ActivityStatusCode.Unset); + span.Events.ShouldBeEmpty(); + span.GetTagItem(ApplicationTelemetry.TagNames.RequestOutcome).ShouldBe(ApplicationTelemetry.RequestOutcome.Cancelled); + } + + [Fact] + public async Task Handle_ShouldRecordError_WhenExceptionIsUnexpected() + { + // Arrange + _ = this.next(default!, default).ThrowsAsyncForAnyArgs(new InvalidOperationException("Broken")); + + using var parent = TestSource.StartActivity("Test")!; + + // Act + _ = await Should.ThrowAsync(async () => await this.behaviour.Handle(this.query, this.next, CancellationToken.None)); + + // Assert + var span = this.SpanIn(parent); + span.Status.ShouldBe(ActivityStatusCode.Error); + span.StatusDescription.ShouldBe("Broken"); + span.GetTagItem(ApplicationTelemetry.TagNames.RequestOutcome).ShouldBe(ApplicationTelemetry.RequestOutcome.Error); + + var spanEvent = span.Events.ShouldHaveSingleItem(); + spanEvent.Name.ShouldBe("exception"); + spanEvent.Tags.ShouldContain(new KeyValuePair("exception.type", typeof(InvalidOperationException).FullName)); + + this.requests.LastMeasurement!.Tags[ApplicationTelemetry.TagNames.RequestOutcome].ShouldBe(ApplicationTelemetry.RequestOutcome.Error); + } + + public void Dispose() + { + this.listener.Dispose(); + this.requests.Dispose(); + this.duration.Dispose(); + this.services.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/Infrastructure.Tests.Integration/Telemetry/DatabaseCommandInterceptorTests.cs b/tests/Infrastructure.Tests.Integration/Telemetry/DatabaseCommandInterceptorTests.cs new file mode 100644 index 0000000..ab03620 --- /dev/null +++ b/tests/Infrastructure.Tests.Integration/Telemetry/DatabaseCommandInterceptorTests.cs @@ -0,0 +1,194 @@ +namespace CleanModelContextProtocol.Infrastructure.Tests.Integration.Telemetry; + +using System.Diagnostics; +using Infrastructure.Databases.MovieReviews; +using Infrastructure.Telemetry; +using Microsoft.Data.Sqlite; +using Microsoft.EntityFrameworkCore; +using Shouldly; +using Xunit; + +public sealed class DatabaseCommandInterceptorTests : IDisposable +{ + private const string TestSourceName = "CleanModelContextProtocol.Infrastructure.Tests"; + + private static readonly ActivitySource TestSource = new(TestSourceName); + + private readonly SqliteConnection connection = new("Data Source=:memory:"); + private readonly MovieReviewsDbContext context; + private readonly ActivityListener listener; + private readonly List spans = []; + + public DatabaseCommandInterceptorTests() + { + // 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 InfrastructureTelemetry.Name or TestSourceName, + Sample = (ref _) => ActivitySamplingResult.AllDataAndRecorded, + ActivityStopped = activity => + { + lock (this.spans) + { + this.spans.Add(activity); + } + } + }; + + ActivitySource.AddActivityListener(this.listener); + + this.connection.Open(); + + this.context = new MovieReviewsDbContext(new DbContextOptionsBuilder() + .UseSqlite(this.connection) + .AddInterceptors(DatabaseCommandInterceptor.Instance) + .Options); + + this.context.Database.Migrate(); + } + + [Fact] + public void Query_ShouldStartClientSpan_WithDatabaseTags() + { + // Arrange + using var parent = TestSource.StartActivity("Test")!; + + // Act + _ = this.context.Movies.ToList(); + + // Assert + var span = this.SpansIn(parent).ShouldHaveSingleItem(); + span.DisplayName.ShouldBe("SELECT"); + span.Kind.ShouldBe(ActivityKind.Client); + span.ParentSpanId.ShouldBe(parent.SpanId); + span.Status.ShouldBe(ActivityStatusCode.Unset); + span.GetTagItem("db.system.name").ShouldBe("sqlite"); + span.GetTagItem("db.namespace").ShouldBe("main"); + span.GetTagItem("db.operation.name").ShouldBe("SELECT"); + span.GetTagItem("db.query.text").ShouldBeOfType().ShouldContain("FROM \"Movies\""); + } + + [Fact] + public async Task QueryAsync_ShouldStartClientSpan() + { + // Arrange + using var parent = TestSource.StartActivity("Test")!; + + // Act + _ = await this.context.Movies.ToListAsync(); + + // Assert + this.SpansIn(parent).ShouldHaveSingleItem().DisplayName.ShouldBe("SELECT"); + } + + [Fact] + public async Task NonQuery_ShouldStartClientSpan_BothWays() + { + // Arrange + using var parent = TestSource.StartActivity("Test")!; + + // Act + _ = this.context.Database.ExecuteSqlRaw("DELETE FROM \"Reviews\""); + _ = await this.context.Database.ExecuteSqlRawAsync("UPDATE \"Movies\" SET \"Title\" = \"Title\""); + + // Assert + this.SpansIn(parent).Select(s => s.DisplayName).ShouldBe(["DELETE", "UPDATE"]); + } + + [Fact] + public async Task Scalar_ShouldStartClientSpan_BothWays() + { + // Arrange + using var parent = TestSource.StartActivity("Test")!; + + // Act + _ = this.context.Database.GetAppliedMigrations().ToList(); + _ = (await this.context.Database.GetAppliedMigrationsAsync()).ToList(); + + // Assert + this.SpansIn(parent).ShouldNotBeEmpty(); + } + + [Fact] + public async Task FailedCommand_ShouldMarkSpanAsError_BothWays() + { + // Arrange + using var parent = TestSource.StartActivity("Test")!; + + // Act + _ = Should.Throw(() => this.context.Database.ExecuteSqlRaw("SELECT * FROM \"Missing\"")); + _ = await Should.ThrowAsync(() => this.context.Database.ExecuteSqlRawAsync("SELECT * FROM \"Missing\"")); + + // Assert + var failed = this.SpansIn(parent); + failed.Count.ShouldBe(2); + + foreach (var span in failed) + { + span.Status.ShouldBe(ActivityStatusCode.Error); + span.GetTagItem("error.type").ShouldBe(typeof(SqliteException).FullName); + span.Events.ShouldContain(e => e.Name == "exception"); + } + } + + [Fact] + public void Query_ShouldNotStartSpan_WhenNothingIsListening() + { + // Arrange + this.listener.Dispose(); + + // Act + var movies = this.context.Movies.ToList(); + + // Assert + movies.ShouldBeEmpty(); + Activity.Current.ShouldBeNull(); + } + + [Theory] + [InlineData("Microsoft.EntityFrameworkCore.Sqlite", "sqlite")] + [InlineData("Microsoft.EntityFrameworkCore.SqlServer", "microsoft.sql_server")] + [InlineData("Npgsql.EntityFrameworkCore.PostgreSQL", "postgresql")] + [InlineData("Something.Else", "other_sql")] + [InlineData(null, "other_sql")] + public void SystemName_ShouldMap_Provider(string? providerName, string expected) + { + // Act + var result = DatabaseCommandInterceptor.SystemName(providerName); + + // Assert + result.ShouldBe(expected); + } + + [Theory] + [InlineData("SELECT * FROM \"Movies\"", "SELECT")] + [InlineData(" insert INTO x", "INSERT")] + [InlineData("WITH cte(x) AS (SELECT 1) SELECT x FROM cte", "WITH")] + [InlineData("PRAGMA foreign_keys;", "PRAGMA")] + [InlineData("VACUUM", "VACUUM")] + [InlineData("", null)] + [InlineData(null, null)] + public void OperationName_ShouldReturn_FirstKeyword(string? commandText, string? expected) + { + // Act + var result = DatabaseCommandInterceptor.OperationName(commandText); + + // Assert + result.ShouldBe(expected); + } + + public void Dispose() + { + this.listener.Dispose(); + this.context.Dispose(); + this.connection.Dispose(); + } + + private List SpansIn(Activity parent) + { + lock (this.spans) + { + return [.. this.spans.Where(s => s.TraceId == parent.TraceId && s.Source.Name == InfrastructureTelemetry.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..113ba91 --- /dev/null +++ b/tests/Presentation.Tests.Integration/Telemetry/TelemetryTests.cs @@ -0,0 +1,136 @@ +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 Infrastructure.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 or InfrastructureTelemetry.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"); + request.Headers.Add("baggage", "tenant.id=acme"); + + // Act + using var response = await client.SendAsync(request); + _ = await response.Content.ReadAsStringAsync(); + + // Assert + response.StatusCode.ShouldBe(HttpStatusCode.OK); + + var trace = this.SpansIn(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); + var commands = trace.Where(s => s.Source.Name == InfrastructureTelemetry.Name).ToList(); + + server.Kind.ShouldBe(ActivityKind.Server); + tool.DisplayName.ShouldContain("movies_search"); + useCase.DisplayName.ShouldBe("GetMoviesQuery"); + useCase.ParentSpanId.ShouldBe(tool.SpanId); + useCase.GetTagItem("tenant.id").ShouldBe("acme"); + commands.ShouldNotBeEmpty(); + commands.ShouldAllBe(c => c.ParentSpanId == useCase.SpanId); + } + + [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 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"); + } +} From 6d9111deca3bd58baa318ed0c7cf991f177701e6 Mon Sep 17 00:00:00 2001 From: Stephen Walsh <868017+stphnwlsh@users.noreply.github.com> Date: Wed, 4 Nov 2026 03:29:06 +0000 Subject: [PATCH 2/4] Describe the Lambda telemetry in the shared skills Keeps the telemetry and serilog skills identical across the five templates. --- .agents/skills/serilog/SKILL.md | 2 +- .agents/skills/telemetry/SKILL.md | 4 +++- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/.agents/skills/serilog/SKILL.md b/.agents/skills/serilog/SKILL.md index eae20d9..98f5448 100644 --- a/.agents/skills/serilog/SKILL.md +++ b/.agents/skills/serilog/SKILL.md @@ -15,7 +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` | Console, and OTLP through the collector to the Aspire dashboard | , or `docker compose logs` | -| Lambda, anywhere | Console, as compact JSON | CloudWatch Logs, or `docker compose logs` for the emulator | +| 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. diff --git a/.agents/skills/telemetry/SKILL.md b/.agents/skills/telemetry/SKILL.md index 2235d7e..4678f3b 100644 --- a/.agents/skills/telemetry/SKILL.md +++ b/.agents/skills/telemetry/SKILL.md @@ -35,7 +35,9 @@ What each presentation layer adds: | 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`, flushed before the function returns | +| 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. From 6136dbf8852ced2af6842a7172613595f8f67d26 Mon Sep 17 00:00:00 2001 From: Stephen Walsh <868017+stphnwlsh@users.noreply.github.com> Date: Wed, 4 Nov 2026 03:36:05 +0000 Subject: [PATCH 3/4] Wait for the request span before checking the trace The test server can return the response a moment before the ASP.NET Core request span stops, which failed the trace test in the template verification run. --- .../Telemetry/TelemetryTests.cs | 13 ++++++++++++- 1 file changed, 12 insertions(+), 1 deletion(-) diff --git a/tests/Presentation.Tests.Integration/Telemetry/TelemetryTests.cs b/tests/Presentation.Tests.Integration/Telemetry/TelemetryTests.cs index 113ba91..9f272a0 100644 --- a/tests/Presentation.Tests.Integration/Telemetry/TelemetryTests.cs +++ b/tests/Presentation.Tests.Integration/Telemetry/TelemetryTests.cs @@ -67,7 +67,7 @@ public async Task ToolCall_ShouldTrace_FromHttpThroughToolAndUseCaseToDatabase() // Assert response.StatusCode.ShouldBe(HttpStatusCode.OK); - var trace = this.SpansIn(traceId); + 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); @@ -126,6 +126,17 @@ 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) From 6e02ef809a5d70035784a6893dcf7a032292db7f Mon Sep 17 00:00:00 2001 From: Stephen Walsh <868017+stphnwlsh@users.noreply.github.com> Date: Wed, 4 Nov 2026 12:29:33 +0000 Subject: [PATCH 4/4] Trim the telemetry to one span per use case Drop the database command interceptor until the EF Core instrumentation is stable, and drop the telemetry behaviour and its metrics, which repeated what the ASP.NET Core instrumentation already records. LoggingBehaviour now starts the use case span, so there's one timer and Application needs no package. --- .agents/skills/mediator/SKILL.md | 5 +- .agents/skills/serilog/SKILL.md | 2 +- .agents/skills/telemetry/SKILL.md | 60 ++--- Directory.Packages.props | 1 - README.md | 2 +- src/Application/Application.csproj | 1 - .../Common/Behaviours/LoggingBehaviour.cs | 28 ++- .../Common/Behaviours/TelemetryBehaviour.cs | 88 ------- .../Common/Telemetry/ApplicationTelemetry.cs | 85 +------ src/Application/DependencyInjection.cs | 5 - src/Infrastructure/DependencyInjection.cs | 7 +- .../Telemetry/DatabaseCommandInterceptor.cs | 215 ----------------- .../Telemetry/InfrastructureTelemetry.cs | 18 -- .../WebApplicationBuilderExtensions.cs | 6 +- .../Behaviours/LoggingBehaviourTests.cs | 93 +++++++- .../Behaviours/TelemetryBehaviourTests.cs | 224 ------------------ .../DatabaseCommandInterceptorTests.cs | 194 --------------- .../Telemetry/TelemetryTests.cs | 9 +- 18 files changed, 166 insertions(+), 877 deletions(-) delete mode 100644 src/Application/Common/Behaviours/TelemetryBehaviour.cs delete mode 100644 src/Infrastructure/Telemetry/DatabaseCommandInterceptor.cs delete mode 100644 src/Infrastructure/Telemetry/InfrastructureTelemetry.cs delete mode 100644 tests/Application.Tests.Unit/Common/Behaviours/TelemetryBehaviourTests.cs delete mode 100644 tests/Infrastructure.Tests.Integration/Telemetry/DatabaseCommandInterceptorTests.cs diff --git a/.agents/skills/mediator/SKILL.md b/.agents/skills/mediator/SKILL.md index d3bb448..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. `TelemetryBehaviour` is registered first, so its span wraps everything else and the logs inside it carry its trace (`telemetry`). `LoggingBehaviour` comes next and times and logs everything inside it, validation failures included (`serilog`). `ValidationBehaviour` is last, 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 @@ -37,10 +37,7 @@ Behaviours run in the order they're registered. The first one registered is the // src/Application/DependencyInjection.cs _ = services.AddValidatorsFromAssembly(Assembly.GetExecutingAssembly(), ServiceLifetime.Transient); services.TryAddSingleton(TimeProvider.System); -_ = services.AddMetrics(); -_ = services.AddSingleton(); -_ = services.AddScoped(typeof(IPipelineBehavior<,>), typeof(TelemetryBehaviour<,>)); _ = 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 98f5448..ada5ea5 100644 --- a/.agents/skills/serilog/SKILL.md +++ b/.agents/skills/serilog/SKILL.md @@ -29,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 `Microsoft.EntityFrameworkCore.Database.Command` (each SQL command already has a span), 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: diff --git a/.agents/skills/telemetry/SKILL.md b/.agents/skills/telemetry/SKILL.md index 4678f3b..7067676 100644 --- a/.agents/skills/telemetry/SKILL.md +++ b/.agents/skills/telemetry/SKILL.md @@ -1,6 +1,6 @@ --- name: telemetry -description: How OpenTelemetry traces, metrics and logs work - the standard OTEL_* settings that switch exporting on, the TelemetryBehaviour span and metrics for every use case, the database command spans, baggage, span events, 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. +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 --- @@ -9,23 +9,22 @@ metadata: ## 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. 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. +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, each use case and each SQL command, plus outgoing HTTP calls | Presentation instrumentation, `TelemetryBehaviour`, `DatabaseCommandInterceptor` | -| Metrics | Request counts and durations per use case, EF Core's own meter, ASP.NET Core, HttpClient and runtime metrics, with exemplars linking a measurement to a trace | `ApplicationTelemetry`, `Microsoft.EntityFrameworkCore`, Presentation instrumentation | -| Logs | Every Serilog event, carrying the trace and span IDs of whatever was running when it was written | Serilog's OpenTelemetry sink (`serilog`) | -| Baggage | Propagated with the trace context, and copied onto each use case span as tags | W3C `baggage` header, `TelemetryBehaviour` | -| Events | Span events for validation failures and missing entities, and `exception` events for errors | `TelemetryBehaviour`, `DatabaseCommandInterceptor` | +| 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 and meter: a span per request, `application.requests` and `application.request.duration` | `System.Diagnostics` only, so Application stays free of telemetry packages | -| Infrastructure | `InfrastructureTelemetry.Name` activity source: a client span per database command, with `db.system.name`, `db.namespace`, `db.operation.name` and the parameterised `db.query.text` | `DatabaseCommandInterceptor`, an EF Core `DbCommandInterceptor` | -| Infrastructure | `Microsoft.EntityFrameworkCore` meter: queries, saves, active contexts, compiled query cache | Built into EF Core; startup subscribes to `InfrastructureTelemetry.EntityFrameworkCoreMeterName` | +| 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: @@ -45,29 +44,29 @@ Locally, Docker Compose runs the collector (`otel/opentelemetry-collector`) and ## Steps -1. A new use case needs nothing: `TelemetryBehaviour` gives it a span and metrics. Its span is named after the request class. -2. To trace work inside Application or Infrastructure, start a child span from the layer's own `ActivitySource` with `using var activity = ApplicationTelemetry.ActivitySource.StartActivity("Name");`. Set tags only when `activity is { IsAllDataRequested: true }`, and use the [semantic convention](https://opentelemetry.io/docs/specs/semconv/) names where one exists. -3. To add a metric, add an instrument to `ApplicationTelemetry`, created from the `IMeterFactory` meter, with a unit and a description. Keep tag values to a small fixed set; never tag a metric with an id. -4. A new dependency in Infrastructure (a queue, an HTTP API) gets its spans from its own instrumentation package if a stable one exists. Subscribe to its source or meter name in the presentation layer's startup, and expose the name as a constant in `InfrastructureTelemetry`. -5. Use stable packages only. When the only instrumentation is a prerelease package, write the small piece we need, as `DatabaseCommandInterceptor` does, and add it to the watch list below. -6. Test spans with an `ActivityListener` that keeps only the test's own trace, and metrics with `MetricCollector` from `Microsoft.Extensions.Diagnostics.Testing` (`unit-tests`). The integration tests send a `traceparent` header and check the request, use case and database spans join up. +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/TelemetryBehaviour.cs +// src/Application/Common/Behaviours/LoggingBehaviour.cs using var activity = ApplicationTelemetry.ActivitySource.StartActivity(RequestName); - -if (activity is { IsAllDataRequested: true }) +_ = activity?.SetTag(ApplicationTelemetry.RequestNameTag, RequestName); +... +catch (Exception exception) { - _ = activity.SetTag(ApplicationTelemetry.TagNames.RequestName, RequestName); + _ = activity?.SetTag(ApplicationTelemetry.RequestOutcomeTag, "error") + .SetStatus(ActivityStatusCode.Error, exception.Message) + .AddException(exception); - foreach (var (key, value) in activity.Baggage) - { - _ = activity.SetTag(key, value); - } + throw; } ``` @@ -91,24 +90,25 @@ exporters: 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`: replaces `DatabaseCommandInterceptor`. +- `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 span events and `[LoggerMessage]` logs with event IDs. +- 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 to get a signal. -- Put ids, tokens or personal data in span names, tags or metric tags. `db.query.text` is safe only because EF Core sends parameters, not values. -- Mark a span as an error for a validation failure or a missing entity. The caller got an answer; record a span event instead. +- 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" # behaviour, interceptor and end-to-end trace tests +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/Directory.Packages.props b/Directory.Packages.props index e6f6adf..4118819 100644 --- a/Directory.Packages.props +++ b/Directory.Packages.props @@ -14,7 +14,6 @@ - diff --git a/README.md b/README.md index 252925f..e30749c 100644 --- a/README.md +++ b/README.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. -- **Telemetry** is [OpenTelemetry](https://opentelemetry.io) all the way: a span for every request, tool call, use case and SQL command, metrics from ASP.NET Core, the MCP SDK, EF Core and each use case, 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`. +- **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/src/Application/Application.csproj b/src/Application/Application.csproj index dcb1c22..6bfaa72 100644 --- a/src/Application/Application.csproj +++ b/src/Application/Application.csproj @@ -7,7 +7,6 @@ - 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/Behaviours/TelemetryBehaviour.cs b/src/Application/Common/Behaviours/TelemetryBehaviour.cs deleted file mode 100644 index 8aac399..0000000 --- a/src/Application/Common/Behaviours/TelemetryBehaviour.cs +++ /dev/null @@ -1,88 +0,0 @@ -namespace CleanModelContextProtocol.Application.Common.Behaviours; - -using System.Diagnostics; -using Exceptions; -using FluentValidation; -using Mediator; -using Telemetry; - -/// -/// Gives every request a span named after it and records it on the request counter and duration histogram. Baggage -/// from the caller is copied onto the span as tags. Validation failures and missing entities become span events, -/// because the caller still gets an answer, and anything else marks the span as an error with the exception attached. -/// -/// The request being sent. -/// The response the handler returns. -/// Records the request metrics. -/// The clock that times each request. -public class TelemetryBehaviour(ApplicationTelemetry telemetry, TimeProvider timeProvider) : IPipelineBehavior - where TMessage : IMessage -{ - private static readonly string RequestName = typeof(TMessage).Name; - - public async ValueTask Handle(TMessage message, MessageHandlerDelegate next, CancellationToken cancellationToken) - { - using var activity = ApplicationTelemetry.ActivitySource.StartActivity(RequestName); - - if (activity is { IsAllDataRequested: true }) - { - _ = activity.SetTag(ApplicationTelemetry.TagNames.RequestName, RequestName); - - foreach (var (key, value) in activity.Baggage) - { - _ = activity.SetTag(key, value); - } - } - - var started = timeProvider.GetTimestamp(); - var outcome = ApplicationTelemetry.RequestOutcome.Handled; - - try - { - return await next(message, cancellationToken); - } - catch (ValidationException exception) - { - outcome = ApplicationTelemetry.RequestOutcome.Invalid; - - _ = activity?.AddEvent(new ActivityEvent("validation_failed", tags: new ActivityTagsCollection - { - [ApplicationTelemetry.TagNames.ValidationProperties] = string.Join(", ", exception.Errors.Select(e => e.PropertyName).Distinct()) - })); - - throw; - } - catch (NotFoundException exception) - { - outcome = ApplicationTelemetry.RequestOutcome.NotFound; - - _ = activity?.AddEvent(new ActivityEvent("not_found", tags: new ActivityTagsCollection - { - ["exception.message"] = exception.Message - })); - - throw; - } - catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested) - { - outcome = ApplicationTelemetry.RequestOutcome.Cancelled; - - throw; - } - catch (Exception exception) - { - outcome = ApplicationTelemetry.RequestOutcome.Error; - - _ = activity?.SetStatus(ActivityStatusCode.Error, exception.Message); - _ = activity?.AddException(exception); - - throw; - } - finally - { - _ = activity?.SetTag(ApplicationTelemetry.TagNames.RequestOutcome, outcome); - - telemetry.RecordRequest(RequestName, outcome, timeProvider.GetElapsedTime(started)); - } - } -} diff --git a/src/Application/Common/Telemetry/ApplicationTelemetry.cs b/src/Application/Common/Telemetry/ApplicationTelemetry.cs index 4f2fccd..d4dc95b 100644 --- a/src/Application/Common/Telemetry/ApplicationTelemetry.cs +++ b/src/Application/Common/Telemetry/ApplicationTelemetry.cs @@ -1,87 +1,22 @@ namespace CleanModelContextProtocol.Application.Common.Telemetry; using System.Diagnostics; -using System.Diagnostics.Metrics; /// -/// The spans and metrics the Application layer publishes. Both use the name in , which the -/// presentation layer's startup subscribes to. Nothing is recorded unless something is listening, so the layer stays -/// free of any telemetry package. +/// 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 sealed class ApplicationTelemetry +public static class ApplicationTelemetry { - /// The name of the activity source and the meter. + /// The name of the activity source. public const string Name = "CleanModelContextProtocol.Application"; - /// Starts a span for each use case. - internal static readonly ActivitySource ActivitySource = new(Name); - - private readonly Counter requests; - private readonly Histogram duration; - - /// Creates the meter and its instruments. - /// Owns the meter, so it's disposed with the container. - public ApplicationTelemetry(IMeterFactory meterFactory) - { - var meter = meterFactory.Create(Name); - - this.requests = meter.CreateCounter( - "application.requests", - "{request}", - "The use case requests sent through the pipeline."); - - this.duration = meter.CreateHistogram( - "application.request.duration", - "s", - "How long each use case request took.", - advice: new InstrumentAdvice { HistogramBucketBoundaries = [0.001, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10] }); - } - - /// Records one finished request on both instruments. - /// The request's type name. - /// How it ended, one of the values. - /// How long it took. - public void RecordRequest(string requestName, string outcome, TimeSpan elapsed) - { - var tags = new TagList - { - { TagNames.RequestName, requestName }, - { TagNames.RequestOutcome, outcome } - }; - - this.requests.Add(1, tags); - this.duration.Record(elapsed.TotalSeconds, tags); - } + /// The tag holding the request's type name, such as GetMoviesQuery. + public const string RequestNameTag = "application.request.name"; - /// The tag names used on the spans and metrics. - public static class TagNames - { - /// The request's type name, such as GetMoviesQuery. - public const string RequestName = "application.request.name"; + /// The tag holding how the request ended: handled, invalid, not_found, cancelled or error. + public const string RequestOutcomeTag = "application.request.outcome"; - /// How the request ended. - public const string RequestOutcome = "application.request.outcome"; - - /// The properties that failed validation, comma separated. - public const string ValidationProperties = "application.validation.properties"; - } - - /// How a request ended. - public static class RequestOutcome - { - /// The handler returned a response. - public const string Handled = "handled"; - - /// The request failed validation. - public const string Invalid = "invalid"; - - /// What the request asked for doesn't exist. - public const string NotFound = "not_found"; - - /// The caller cancelled the request. - public const string Cancelled = "cancelled"; - - /// Something unexpected went wrong. - public const string Error = "error"; - } + /// Starts a span for each use case. + internal static readonly ActivitySource ActivitySource = new(Name); } diff --git a/src/Application/DependencyInjection.cs b/src/Application/DependencyInjection.cs index ada5bee..b3d8a83 100644 --- a/src/Application/DependencyInjection.cs +++ b/src/Application/DependencyInjection.cs @@ -3,7 +3,6 @@ namespace CleanModelContextProtocol.Application; using System.Diagnostics.CodeAnalysis; using System.Reflection; using Common.Behaviours; -using Common.Telemetry; using FluentValidation; using Mediator; using Microsoft.Extensions.DependencyInjection; @@ -16,11 +15,7 @@ public static IServiceCollection AddApplication(this IServiceCollection services { _ = services.AddValidatorsFromAssembly(Assembly.GetExecutingAssembly(), ServiceLifetime.Transient); services.TryAddSingleton(TimeProvider.System); - _ = services.AddMetrics(); - _ = services.AddSingleton(); - // The first registered runs outermost: the span wraps the logs, and both see validation failures. - _ = services.AddScoped(typeof(IPipelineBehavior<,>), typeof(TelemetryBehaviour<,>)); _ = services.AddScoped(typeof(IPipelineBehavior<,>), typeof(LoggingBehaviour<,>)); _ = services.AddScoped(typeof(IPipelineBehavior<,>), typeof(ValidationBehaviour<,>)); diff --git a/src/Infrastructure/DependencyInjection.cs b/src/Infrastructure/DependencyInjection.cs index 48ab376..ea048c0 100644 --- a/src/Infrastructure/DependencyInjection.cs +++ b/src/Infrastructure/DependencyInjection.cs @@ -10,7 +10,6 @@ namespace CleanModelContextProtocol.Infrastructure; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.DependencyInjection.Extensions; using Microsoft.Extensions.Diagnostics.HealthChecks; -using Telemetry; public static class DependencyInjection { @@ -24,12 +23,10 @@ public static IServiceCollection AddInfrastructure(this IServiceCollection servi // Registered through a factory, so the container owns it and closes its connection when the app stops. _ = services.AddSingleton(_ => new MovieReviewsDatabase(databaseConnectionString)); - // Nothing reads an entity to change it, so queries don't track by default. The interceptor gives each command a - // span when something is listening. + // Nothing reads an entity to change it, so queries don't track by default. _ = services.AddDbContext(options => options .UseSqlite(databaseConnectionString) - .UseQueryTrackingBehavior(QueryTrackingBehavior.NoTracking) - .AddInterceptors(DatabaseCommandInterceptor.Instance)); + .UseQueryTrackingBehavior(QueryTrackingBehavior.NoTracking)); _ = services.AddSingleton(); _ = services.AddScoped(); diff --git a/src/Infrastructure/Telemetry/DatabaseCommandInterceptor.cs b/src/Infrastructure/Telemetry/DatabaseCommandInterceptor.cs deleted file mode 100644 index 155cba9..0000000 --- a/src/Infrastructure/Telemetry/DatabaseCommandInterceptor.cs +++ /dev/null @@ -1,215 +0,0 @@ -namespace CleanModelContextProtocol.Infrastructure.Telemetry; - -using System.Buffers; -using System.Data.Common; -using System.Diagnostics; -using System.Runtime.CompilerServices; -using Microsoft.EntityFrameworkCore.Diagnostics; - -/// -/// Gives every database command EF Core runs a client span, following the OpenTelemetry database conventions. EF Core -/// publishes metrics but no spans, and the OpenTelemetry EF Core instrumentation is still a prerelease package, so -/// this stands in for it until that package is stable. The SQL is the parameterised text EF Core sends, so no values -/// are recorded. When nothing is listening, no span is started. -/// -internal sealed class DatabaseCommandInterceptor : DbCommandInterceptor -{ - /// The one instance every context shares; it holds no per-request state of its own. - public static readonly DatabaseCommandInterceptor Instance = new(); - - private static readonly SearchValues KeywordEnd = SearchValues.Create(" \t\r\n(;"); - - private readonly ConditionalWeakTable activities = []; - - #region Executing - - public override InterceptionResult ReaderExecuting(DbCommand command, CommandEventData eventData, InterceptionResult result) - { - this.Start(command, eventData); - - return result; - } - - public override ValueTask> ReaderExecutingAsync(DbCommand command, CommandEventData eventData, InterceptionResult result, CancellationToken cancellationToken = default) - { - this.Start(command, eventData); - - return ValueTask.FromResult(result); - } - - public override InterceptionResult NonQueryExecuting(DbCommand command, CommandEventData eventData, InterceptionResult result) - { - this.Start(command, eventData); - - return result; - } - - public override ValueTask> NonQueryExecutingAsync(DbCommand command, CommandEventData eventData, InterceptionResult result, CancellationToken cancellationToken = default) - { - this.Start(command, eventData); - - return ValueTask.FromResult(result); - } - - public override InterceptionResult ScalarExecuting(DbCommand command, CommandEventData eventData, InterceptionResult result) - { - this.Start(command, eventData); - - return result; - } - - public override ValueTask> ScalarExecutingAsync(DbCommand command, CommandEventData eventData, InterceptionResult result, CancellationToken cancellationToken = default) - { - this.Start(command, eventData); - - return ValueTask.FromResult(result); - } - - #endregion Executing - - #region Executed - - public override DbDataReader ReaderExecuted(DbCommand command, CommandExecutedEventData eventData, DbDataReader result) - { - this.Stop(command, null); - - return result; - } - - public override ValueTask ReaderExecutedAsync(DbCommand command, CommandExecutedEventData eventData, DbDataReader result, CancellationToken cancellationToken = default) - { - this.Stop(command, null); - - return ValueTask.FromResult(result); - } - - public override int NonQueryExecuted(DbCommand command, CommandExecutedEventData eventData, int result) - { - this.Stop(command, null); - - return result; - } - - public override ValueTask NonQueryExecutedAsync(DbCommand command, CommandExecutedEventData eventData, int result, CancellationToken cancellationToken = default) - { - this.Stop(command, null); - - return ValueTask.FromResult(result); - } - - public override object? ScalarExecuted(DbCommand command, CommandExecutedEventData eventData, object? result) - { - this.Stop(command, null); - - return result; - } - - public override ValueTask ScalarExecutedAsync(DbCommand command, CommandExecutedEventData eventData, object? result, CancellationToken cancellationToken = default) - { - this.Stop(command, null); - - return ValueTask.FromResult(result); - } - - #endregion Executed - - #region Failed - - public override void CommandFailed(DbCommand command, CommandErrorEventData eventData) - { - this.Stop(command, eventData.Exception); - } - - public override Task CommandFailedAsync(DbCommand command, CommandErrorEventData eventData, CancellationToken cancellationToken = default) - { - this.Stop(command, eventData.Exception); - - return Task.CompletedTask; - } - - public override void CommandCanceled(DbCommand command, CommandEndEventData eventData) - { - this.Stop(command, null); - } - - public override Task CommandCanceledAsync(DbCommand command, CommandEndEventData eventData, CancellationToken cancellationToken = default) - { - this.Stop(command, null); - - return Task.CompletedTask; - } - - #endregion Failed - - #region Spans - - private void Start(DbCommand command, CommandEventData eventData) - { - if (!InfrastructureTelemetry.ActivitySource.HasListeners()) - { - return; - } - - var system = SystemName(eventData.Context?.Database.ProviderName); - var operation = OperationName(command.CommandText); - var activity = InfrastructureTelemetry.ActivitySource.StartActivity(operation ?? system, ActivityKind.Client); - - if (activity is null) - { - return; - } - - if (activity.IsAllDataRequested) - { - _ = activity.SetTag("db.system.name", system); - _ = activity.SetTag("db.namespace", command.Connection?.Database); - _ = activity.SetTag("db.operation.name", operation); - _ = activity.SetTag("db.query.text", command.CommandText); - } - - this.activities.AddOrUpdate(command, activity); - } - - private void Stop(DbCommand command, Exception? exception) - { - if (!this.activities.TryGetValue(command, out var activity)) - { - return; - } - - _ = this.activities.Remove(command); - - if (exception is not null) - { - _ = activity.SetTag("error.type", exception.GetType().FullName); - _ = activity.SetStatus(ActivityStatusCode.Error, exception.Message); - _ = activity.AddException(exception); - } - - activity.Stop(); - } - - /// Maps the EF Core provider to the db.system.name the conventions use. - internal static string SystemName(string? providerName) - { - return providerName switch - { - "Microsoft.EntityFrameworkCore.Sqlite" => "sqlite", - "Microsoft.EntityFrameworkCore.SqlServer" => "microsoft.sql_server", - "Npgsql.EntityFrameworkCore.PostgreSQL" => "postgresql", - _ => "other_sql" - }; - } - - /// The SQL keyword the command starts with, such as SELECT, or null when there isn't one. - internal static string? OperationName(string? commandText) - { - var text = commandText.AsSpan().TrimStart(); - var end = text.IndexOfAny(KeywordEnd); - var keyword = end < 0 ? text : text[..end]; - - return keyword.IsEmpty ? null : keyword.ToString().ToUpperInvariant(); - } - - #endregion Spans -} diff --git a/src/Infrastructure/Telemetry/InfrastructureTelemetry.cs b/src/Infrastructure/Telemetry/InfrastructureTelemetry.cs deleted file mode 100644 index 10de815..0000000 --- a/src/Infrastructure/Telemetry/InfrastructureTelemetry.cs +++ /dev/null @@ -1,18 +0,0 @@ -namespace CleanModelContextProtocol.Infrastructure.Telemetry; - -using System.Diagnostics; - -/// -/// The spans and meters Infrastructure publishes, for the presentation layer's startup to subscribe to. -/// -public static class InfrastructureTelemetry -{ - /// The name of the activity source that gives each database command a span. - public const string Name = "CleanModelContextProtocol.Infrastructure"; - - /// The meter EF Core publishes itself: queries, saves, active contexts and the compiled query cache. - public const string EntityFrameworkCoreMeterName = "Microsoft.EntityFrameworkCore"; - - /// Starts a span for each database command. - internal static readonly ActivitySource ActivitySource = new(Name); -} diff --git a/src/Presentation/Extensions/WebApplicationBuilderExtensions.cs b/src/Presentation/Extensions/WebApplicationBuilderExtensions.cs index 4704c5d..f49ede0 100644 --- a/src/Presentation/Extensions/WebApplicationBuilderExtensions.cs +++ b/src/Presentation/Extensions/WebApplicationBuilderExtensions.cs @@ -10,7 +10,6 @@ namespace CleanModelContextProtocol.Presentation.Extensions; using CleanModelContextProtocol.Presentation.Serialization; using CleanModelContextProtocol.Presentation.Telemetry; using Infrastructure; -using Infrastructure.Telemetry; using Microsoft.AspNetCore.Authentication.JwtBearer; using Microsoft.AspNetCore.Authorization; using Microsoft.AspNetCore.Builder; @@ -36,7 +35,7 @@ public static WebApplicationBuilder ConfigureApplicationBuilder(this WebApplicat var openTelemetry = builder.Services.AddOpenTelemetry() .ConfigureResource(resource => resource.AddAttributes(telemetry.ResourceAttributes)) .WithTracing(tracing => tracing - .AddSource(ApplicationTelemetry.Name, InfrastructureTelemetry.Name, "Experimental.ModelContextProtocol") + .AddSource(ApplicationTelemetry.Name, "Experimental.ModelContextProtocol") .AddAspNetCoreInstrumentation(options => { // Probes call the health endpoints every few seconds, so tracing them would bury everything else. @@ -46,8 +45,7 @@ public static WebApplicationBuilder ConfigureApplicationBuilder(this WebApplicat .AddHttpClientInstrumentation(options => options.RecordException = true)) .WithMetrics(metrics => metrics .AddMeter( - ApplicationTelemetry.Name, - InfrastructureTelemetry.EntityFrameworkCoreMeterName, + "Microsoft.EntityFrameworkCore", "Microsoft.AspNetCore.Authentication", "Microsoft.AspNetCore.Authorization", "Experimental.ModelContextProtocol") 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/Application.Tests.Unit/Common/Behaviours/TelemetryBehaviourTests.cs b/tests/Application.Tests.Unit/Common/Behaviours/TelemetryBehaviourTests.cs deleted file mode 100644 index 25a87b4..0000000 --- a/tests/Application.Tests.Unit/Common/Behaviours/TelemetryBehaviourTests.cs +++ /dev/null @@ -1,224 +0,0 @@ -namespace CleanModelContextProtocol.Application.Tests.Unit.Common.Behaviours; - -using System.Diagnostics; -using System.Diagnostics.Metrics; -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; -using Microsoft.Extensions.DependencyInjection; -using Microsoft.Extensions.Diagnostics.Metrics.Testing; -using Microsoft.Extensions.Time.Testing; -using NSubstitute; -using NSubstitute.ExceptionExtensions; -using Shouldly; -using Xunit; - -public sealed class TelemetryBehaviourTests : IDisposable -{ - private const string TestSourceName = "CleanModelContextProtocol.Application.Tests"; - - private static readonly ActivitySource TestSource = new(TestSourceName); - - private readonly ServiceProvider services = new ServiceCollection().AddMetrics().BuildServiceProvider(); - private readonly ActivityListener listener; - private readonly List spans = []; - private readonly FakeTimeProvider timeProvider = new(); - private readonly MetricCollector requests; - private readonly MetricCollector duration; - private readonly TelemetryBehaviour behaviour; - private readonly GetAuthorByIdQuery query = new() { Id = Guid.NewGuid() }; - private readonly MessageHandlerDelegate next = Substitute.For>(); - - public TelemetryBehaviourTests() - { - // 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); - - var meterFactory = this.services.GetRequiredService(); - - this.requests = new MetricCollector(meterFactory, ApplicationTelemetry.Name, "application.requests"); - this.duration = new MetricCollector(meterFactory, ApplicationTelemetry.Name, "application.request.duration"); - this.behaviour = new TelemetryBehaviour(new ApplicationTelemetry(meterFactory), this.timeProvider); - } - - [Fact] - public async Task Handle_ShouldRecordHandled_WhenNextSucceeds() - { - // Arrange - var author = new Author(Guid.NewGuid(), "Test", "Test", []); - - _ = this.next(default!, default).ReturnsForAnyArgs(_ => - { - this.timeProvider.Advance(TimeSpan.FromMilliseconds(12.5)); - return author; - }); - - using var parent = TestSource.StartActivity("Test")!; - - // Act - var result = await this.behaviour.Handle(this.query, this.next, CancellationToken.None); - - // Assert - result.ShouldBe(author); - - var span = this.SpanIn(parent); - span.DisplayName.ShouldBe("GetAuthorByIdQuery"); - span.ParentSpanId.ShouldBe(parent.SpanId); - span.Status.ShouldBe(ActivityStatusCode.Unset); - span.GetTagItem(ApplicationTelemetry.TagNames.RequestName).ShouldBe("GetAuthorByIdQuery"); - span.GetTagItem(ApplicationTelemetry.TagNames.RequestOutcome).ShouldBe(ApplicationTelemetry.RequestOutcome.Handled); - - var count = this.requests.LastMeasurement!; - count.Value.ShouldBe(1); - count.Tags[ApplicationTelemetry.TagNames.RequestName].ShouldBe("GetAuthorByIdQuery"); - count.Tags[ApplicationTelemetry.TagNames.RequestOutcome].ShouldBe(ApplicationTelemetry.RequestOutcome.Handled); - this.duration.LastMeasurement!.Value.ShouldBe(0.0125, 0.000001); - } - - [Fact] - public async Task Handle_ShouldCopyBaggage_ToSpanTags() - { - // Arrange - _ = this.next(default!, default).ReturnsForAnyArgs(new Author(Guid.NewGuid(), "Test", "Test", [])); - - using var parent = TestSource.StartActivity("Test")!; - _ = parent.AddBaggage("tenant.id", "acme"); - - // Act - _ = await this.behaviour.Handle(this.query, this.next, CancellationToken.None); - - // Assert - this.SpanIn(parent).GetTagItem("tenant.id").ShouldBe("acme"); - } - - [Fact] - public async Task Handle_ShouldRecordInvalid_WhenValidationFails() - { - // Arrange - _ = this.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.") - ])); - - using var parent = TestSource.StartActivity("Test")!; - - // Act - _ = await Should.ThrowAsync(async () => await this.behaviour.Handle(this.query, this.next, CancellationToken.None)); - - // Assert - var span = this.SpanIn(parent); - span.Status.ShouldBe(ActivityStatusCode.Unset); - span.GetTagItem(ApplicationTelemetry.TagNames.RequestOutcome).ShouldBe(ApplicationTelemetry.RequestOutcome.Invalid); - - var spanEvent = span.Events.ShouldHaveSingleItem(); - spanEvent.Name.ShouldBe("validation_failed"); - spanEvent.Tags.ShouldContain(new KeyValuePair(ApplicationTelemetry.TagNames.ValidationProperties, "Id, Name")); - - this.requests.LastMeasurement!.Tags[ApplicationTelemetry.TagNames.RequestOutcome].ShouldBe(ApplicationTelemetry.RequestOutcome.Invalid); - } - - [Fact] - public async Task Handle_ShouldRecordNotFound_WhenEntityIsMissing() - { - // Arrange - _ = this.next(default!, default).ThrowsAsyncForAnyArgs(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, this.next, CancellationToken.None)); - - // Assert - var span = this.SpanIn(parent); - span.Status.ShouldBe(ActivityStatusCode.Unset); - span.GetTagItem(ApplicationTelemetry.TagNames.RequestOutcome).ShouldBe(ApplicationTelemetry.RequestOutcome.NotFound); - - var spanEvent = span.Events.ShouldHaveSingleItem(); - spanEvent.Name.ShouldBe("not_found"); - spanEvent.Tags.ShouldContain(new KeyValuePair("exception.message", "The Author with the supplied id was not found.")); - - this.requests.LastMeasurement!.Tags[ApplicationTelemetry.TagNames.RequestOutcome].ShouldBe(ApplicationTelemetry.RequestOutcome.NotFound); - } - - [Fact] - public async Task Handle_ShouldRecordCancelled_WhenCallerCancels() - { - // Arrange - using var tokenSource = new CancellationTokenSource(); - await tokenSource.CancelAsync(); - - _ = this.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, this.next, tokenSource.Token)); - - // Assert - var span = this.SpanIn(parent); - span.Status.ShouldBe(ActivityStatusCode.Unset); - span.Events.ShouldBeEmpty(); - span.GetTagItem(ApplicationTelemetry.TagNames.RequestOutcome).ShouldBe(ApplicationTelemetry.RequestOutcome.Cancelled); - } - - [Fact] - public async Task Handle_ShouldRecordError_WhenExceptionIsUnexpected() - { - // Arrange - _ = this.next(default!, default).ThrowsAsyncForAnyArgs(new InvalidOperationException("Broken")); - - using var parent = TestSource.StartActivity("Test")!; - - // Act - _ = await Should.ThrowAsync(async () => await this.behaviour.Handle(this.query, this.next, CancellationToken.None)); - - // Assert - var span = this.SpanIn(parent); - span.Status.ShouldBe(ActivityStatusCode.Error); - span.StatusDescription.ShouldBe("Broken"); - span.GetTagItem(ApplicationTelemetry.TagNames.RequestOutcome).ShouldBe(ApplicationTelemetry.RequestOutcome.Error); - - var spanEvent = span.Events.ShouldHaveSingleItem(); - spanEvent.Name.ShouldBe("exception"); - spanEvent.Tags.ShouldContain(new KeyValuePair("exception.type", typeof(InvalidOperationException).FullName)); - - this.requests.LastMeasurement!.Tags[ApplicationTelemetry.TagNames.RequestOutcome].ShouldBe(ApplicationTelemetry.RequestOutcome.Error); - } - - public void Dispose() - { - this.listener.Dispose(); - this.requests.Dispose(); - this.duration.Dispose(); - this.services.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/Infrastructure.Tests.Integration/Telemetry/DatabaseCommandInterceptorTests.cs b/tests/Infrastructure.Tests.Integration/Telemetry/DatabaseCommandInterceptorTests.cs deleted file mode 100644 index ab03620..0000000 --- a/tests/Infrastructure.Tests.Integration/Telemetry/DatabaseCommandInterceptorTests.cs +++ /dev/null @@ -1,194 +0,0 @@ -namespace CleanModelContextProtocol.Infrastructure.Tests.Integration.Telemetry; - -using System.Diagnostics; -using Infrastructure.Databases.MovieReviews; -using Infrastructure.Telemetry; -using Microsoft.Data.Sqlite; -using Microsoft.EntityFrameworkCore; -using Shouldly; -using Xunit; - -public sealed class DatabaseCommandInterceptorTests : IDisposable -{ - private const string TestSourceName = "CleanModelContextProtocol.Infrastructure.Tests"; - - private static readonly ActivitySource TestSource = new(TestSourceName); - - private readonly SqliteConnection connection = new("Data Source=:memory:"); - private readonly MovieReviewsDbContext context; - private readonly ActivityListener listener; - private readonly List spans = []; - - public DatabaseCommandInterceptorTests() - { - // 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 InfrastructureTelemetry.Name or TestSourceName, - Sample = (ref _) => ActivitySamplingResult.AllDataAndRecorded, - ActivityStopped = activity => - { - lock (this.spans) - { - this.spans.Add(activity); - } - } - }; - - ActivitySource.AddActivityListener(this.listener); - - this.connection.Open(); - - this.context = new MovieReviewsDbContext(new DbContextOptionsBuilder() - .UseSqlite(this.connection) - .AddInterceptors(DatabaseCommandInterceptor.Instance) - .Options); - - this.context.Database.Migrate(); - } - - [Fact] - public void Query_ShouldStartClientSpan_WithDatabaseTags() - { - // Arrange - using var parent = TestSource.StartActivity("Test")!; - - // Act - _ = this.context.Movies.ToList(); - - // Assert - var span = this.SpansIn(parent).ShouldHaveSingleItem(); - span.DisplayName.ShouldBe("SELECT"); - span.Kind.ShouldBe(ActivityKind.Client); - span.ParentSpanId.ShouldBe(parent.SpanId); - span.Status.ShouldBe(ActivityStatusCode.Unset); - span.GetTagItem("db.system.name").ShouldBe("sqlite"); - span.GetTagItem("db.namespace").ShouldBe("main"); - span.GetTagItem("db.operation.name").ShouldBe("SELECT"); - span.GetTagItem("db.query.text").ShouldBeOfType().ShouldContain("FROM \"Movies\""); - } - - [Fact] - public async Task QueryAsync_ShouldStartClientSpan() - { - // Arrange - using var parent = TestSource.StartActivity("Test")!; - - // Act - _ = await this.context.Movies.ToListAsync(); - - // Assert - this.SpansIn(parent).ShouldHaveSingleItem().DisplayName.ShouldBe("SELECT"); - } - - [Fact] - public async Task NonQuery_ShouldStartClientSpan_BothWays() - { - // Arrange - using var parent = TestSource.StartActivity("Test")!; - - // Act - _ = this.context.Database.ExecuteSqlRaw("DELETE FROM \"Reviews\""); - _ = await this.context.Database.ExecuteSqlRawAsync("UPDATE \"Movies\" SET \"Title\" = \"Title\""); - - // Assert - this.SpansIn(parent).Select(s => s.DisplayName).ShouldBe(["DELETE", "UPDATE"]); - } - - [Fact] - public async Task Scalar_ShouldStartClientSpan_BothWays() - { - // Arrange - using var parent = TestSource.StartActivity("Test")!; - - // Act - _ = this.context.Database.GetAppliedMigrations().ToList(); - _ = (await this.context.Database.GetAppliedMigrationsAsync()).ToList(); - - // Assert - this.SpansIn(parent).ShouldNotBeEmpty(); - } - - [Fact] - public async Task FailedCommand_ShouldMarkSpanAsError_BothWays() - { - // Arrange - using var parent = TestSource.StartActivity("Test")!; - - // Act - _ = Should.Throw(() => this.context.Database.ExecuteSqlRaw("SELECT * FROM \"Missing\"")); - _ = await Should.ThrowAsync(() => this.context.Database.ExecuteSqlRawAsync("SELECT * FROM \"Missing\"")); - - // Assert - var failed = this.SpansIn(parent); - failed.Count.ShouldBe(2); - - foreach (var span in failed) - { - span.Status.ShouldBe(ActivityStatusCode.Error); - span.GetTagItem("error.type").ShouldBe(typeof(SqliteException).FullName); - span.Events.ShouldContain(e => e.Name == "exception"); - } - } - - [Fact] - public void Query_ShouldNotStartSpan_WhenNothingIsListening() - { - // Arrange - this.listener.Dispose(); - - // Act - var movies = this.context.Movies.ToList(); - - // Assert - movies.ShouldBeEmpty(); - Activity.Current.ShouldBeNull(); - } - - [Theory] - [InlineData("Microsoft.EntityFrameworkCore.Sqlite", "sqlite")] - [InlineData("Microsoft.EntityFrameworkCore.SqlServer", "microsoft.sql_server")] - [InlineData("Npgsql.EntityFrameworkCore.PostgreSQL", "postgresql")] - [InlineData("Something.Else", "other_sql")] - [InlineData(null, "other_sql")] - public void SystemName_ShouldMap_Provider(string? providerName, string expected) - { - // Act - var result = DatabaseCommandInterceptor.SystemName(providerName); - - // Assert - result.ShouldBe(expected); - } - - [Theory] - [InlineData("SELECT * FROM \"Movies\"", "SELECT")] - [InlineData(" insert INTO x", "INSERT")] - [InlineData("WITH cte(x) AS (SELECT 1) SELECT x FROM cte", "WITH")] - [InlineData("PRAGMA foreign_keys;", "PRAGMA")] - [InlineData("VACUUM", "VACUUM")] - [InlineData("", null)] - [InlineData(null, null)] - public void OperationName_ShouldReturn_FirstKeyword(string? commandText, string? expected) - { - // Act - var result = DatabaseCommandInterceptor.OperationName(commandText); - - // Assert - result.ShouldBe(expected); - } - - public void Dispose() - { - this.listener.Dispose(); - this.context.Dispose(); - this.connection.Dispose(); - } - - private List SpansIn(Activity parent) - { - lock (this.spans) - { - return [.. this.spans.Where(s => s.TraceId == parent.TraceId && s.Source.Name == InfrastructureTelemetry.Name)]; - } - } -} diff --git a/tests/Presentation.Tests.Integration/Telemetry/TelemetryTests.cs b/tests/Presentation.Tests.Integration/Telemetry/TelemetryTests.cs index 9f272a0..a77a683 100644 --- a/tests/Presentation.Tests.Integration/Telemetry/TelemetryTests.cs +++ b/tests/Presentation.Tests.Integration/Telemetry/TelemetryTests.cs @@ -5,7 +5,6 @@ namespace CleanModelContextProtocol.Presentation.Tests.Integration.Telemetry; using System.Net.Http.Headers; using System.Text; using Application.Common.Telemetry; -using Infrastructure.Telemetry; using Microsoft.Extensions.DependencyInjection; using OpenTelemetry.Metrics; using OpenTelemetry.Trace; @@ -25,7 +24,7 @@ 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 or InfrastructureTelemetry.Name, + ShouldListenTo = source => source.Name is AspNetCoreSourceName or McpSourceName or ApplicationTelemetry.Name, Sample = (ref _) => ActivitySamplingResult.AllDataAndRecorded, ActivityStopped = activity => { @@ -58,7 +57,6 @@ public async Task ToolCall_ShouldTrace_FromHttpThroughToolAndUseCaseToDatabase() 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"); - request.Headers.Add("baggage", "tenant.id=acme"); // Act using var response = await client.SendAsync(request); @@ -71,15 +69,12 @@ public async Task ToolCall_ShouldTrace_FromHttpThroughToolAndUseCaseToDatabase() 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); - var commands = trace.Where(s => s.Source.Name == InfrastructureTelemetry.Name).ToList(); server.Kind.ShouldBe(ActivityKind.Server); tool.DisplayName.ShouldContain("movies_search"); useCase.DisplayName.ShouldBe("GetMoviesQuery"); useCase.ParentSpanId.ShouldBe(tool.SpanId); - useCase.GetTagItem("tenant.id").ShouldBe("acme"); - commands.ShouldNotBeEmpty(); - commands.ShouldAllBe(c => c.ParentSpanId == useCase.SpanId); + useCase.GetTagItem(ApplicationTelemetry.RequestOutcomeTag).ShouldBe("handled"); } [Fact]