feature: Explainable Alerts
This commit is contained in:
voltsrage
@@ -0,0 +1,479 @@
|
||||
# Guide 3: Structured Logging with Serilog + Seq
|
||||
|
||||
## What Are Serilog and Seq?
|
||||
|
||||
**Logging** is how your application records what it's doing — "user logged in," "observation saved," "database connection failed." Every application needs logging for debugging, auditing, and monitoring.
|
||||
|
||||
**Serilog** is a logging library for .NET that replaces the built-in `Microsoft.Extensions.Logging`. The key difference: Serilog captures log data as **structured events** (with named fields you can query) rather than flat text strings. It sends these events to one or more **sinks** — destinations like the console, a file, or a log server.
|
||||
|
||||
**Seq** is a log server with a web UI. It receives structured log events from Serilog over HTTP, stores them, and lets you search and filter them through a browser interface. Think of it as a specialized search engine for your application's logs.
|
||||
|
||||
---
|
||||
|
||||
## Why Structured Logging?
|
||||
|
||||
Traditional text logs look like this:
|
||||
|
||||
```
|
||||
[2026-06-24 14:23:01] WARNING: Critical threshold breach for encounter 3fa85f64-5717-4562-b3fc-2c963f66afa6
|
||||
```
|
||||
|
||||
You can grep for the encounter ID, but you can't query "show me all critical breaches in the last hour" without parsing free-form text. Structured logging captures each piece of information as a named property:
|
||||
|
||||
```json
|
||||
{
|
||||
"Timestamp": "2026-06-24T14:23:01Z",
|
||||
"Level": "Warning",
|
||||
"MessageTemplate": "Critical threshold breach. Code={Code} Value={Value} AlertId={AlertId}",
|
||||
"Properties": {
|
||||
"Code": "HEART_RATE",
|
||||
"Value": 182.0,
|
||||
"AlertId": "9b2a1c3d-...",
|
||||
"EncounterId": "3fa85f64-...",
|
||||
"PatientId": "7e4b2a1f-...",
|
||||
"CorrelationId": "abc-123-def",
|
||||
"MachineName": "dev-laptop",
|
||||
"ThreadId": 14
|
||||
}
|
||||
}
|
||||
```
|
||||
|
||||
Now you can filter by `Code = "HEART_RATE"`, group by `EncounterId`, or correlate across services using `CorrelationId`.
|
||||
|
||||
---
|
||||
|
||||
## Architecture
|
||||
|
||||
```
|
||||
Application Code
|
||||
│
|
||||
│ _logger.LogInformation("...", ...)
|
||||
▼
|
||||
Serilog Pipeline
|
||||
│
|
||||
├── Enrichers (automatically add extra properties to every event)
|
||||
│
|
||||
├──► Console Sink (prints to your terminal during development)
|
||||
│
|
||||
└──► Seq Sink ──────► Seq Server (http://localhost:5345)
|
||||
│
|
||||
└── Web UI: search, filter, dashboards
|
||||
```
|
||||
|
||||
**What is a sink?** A sink is a destination where Serilog sends log events. Think of it like plumbing — log events flow from your code through the pipeline and out to one or more sinks. You can have multiple sinks active simultaneously (the same event goes to the console AND to Seq).
|
||||
|
||||
**What is an enricher?** An enricher automatically attaches extra properties to every log event as it flows through the pipeline. For example, the `MachineName` enricher adds the computer's hostname to every event without you writing any extra code.
|
||||
|
||||
---
|
||||
|
||||
## Step 1: NuGet Packages
|
||||
|
||||
```xml
|
||||
<!-- VigilCareClinicalAPI.csproj -->
|
||||
<PackageReference Include="Serilog.AspNetCore" Version="10.0.0" />
|
||||
<PackageReference Include="Serilog.Enrichers.Environment" Version="2.3.0" />
|
||||
<PackageReference Include="Serilog.Enrichers.Thread" Version="3.1.0" />
|
||||
<PackageReference Include="Serilog.Sinks.Console" Version="6.1.1" />
|
||||
<PackageReference Include="Serilog.Sinks.Seq" Version="9.1.0" />
|
||||
```
|
||||
|
||||
| Package | Purpose |
|
||||
|---------|---------|
|
||||
| `Serilog.AspNetCore` | Integrates Serilog with the ASP.NET Core host, replaces the default Microsoft logger |
|
||||
| `Serilog.Enrichers.Environment` | Adds `MachineName` to every log event |
|
||||
| `Serilog.Enrichers.Thread` | Adds `ThreadId` to every log event |
|
||||
| `Serilog.Sinks.Console` | Writes to stdout (visible in the terminal during `dotnet run`) |
|
||||
| `Serilog.Sinks.Seq` | Ships structured events to the Seq server over HTTP |
|
||||
|
||||
---
|
||||
|
||||
## Step 2: Configuration
|
||||
|
||||
Serilog is configured in two places: `appsettings.json` (declarative) and `Program.cs` (code).
|
||||
|
||||
### appsettings.json
|
||||
|
||||
```json
|
||||
{
|
||||
"Serilog": {
|
||||
"Using": ["Serilog.Sinks.Console", "Serilog.Sinks.Seq"],
|
||||
"MinimumLevel": {
|
||||
"Default": "Information",
|
||||
"Override": {
|
||||
"Microsoft.AspNetCore": "Warning",
|
||||
"Microsoft.EntityFrameworkCore.Database.Command": "Information"
|
||||
}
|
||||
},
|
||||
"WriteTo": [
|
||||
{ "Name": "Console" },
|
||||
{
|
||||
"Name": "Seq",
|
||||
"Args": {
|
||||
"serverUrl": "http://localhost:5345"
|
||||
}
|
||||
}
|
||||
],
|
||||
"Enrich": ["FromLogContext", "WithMachineName", "WithThreadId"]
|
||||
}
|
||||
}
|
||||
```
|
||||
|
||||
Key settings:
|
||||
|
||||
- **`MinimumLevel.Default: Information`**: Log levels from lowest to highest are: Debug < Information < Warning < Error < Fatal. This setting means "log Information and above, but drop Debug-level events." Debug events are very chatty and usually only turned on temporarily when investigating a specific issue.
|
||||
- **`Override: Microsoft.AspNetCore: Warning`**: The ASP.NET Core framework generates its own logs ("Request starting HTTP/1.1 GET /api/...", "Request finished ..."). At the Information level, this creates a flood of framework noise that drowns out your application's logs. Setting it to Warning means you only see framework logs when something goes wrong.
|
||||
- **`Override: Microsoft.EntityFrameworkCore.Database.Command: Information`**: An exception to the rule above — this keeps EF Core SQL command logging visible. During development, it's useful to see the actual SQL queries being generated by your LINQ code.
|
||||
- **`WriteTo`**: Two sinks run simultaneously. Every log event goes to both Console (your terminal) and Seq (the log server). This is one of Serilog's superpowers — the same event, multiple destinations, with no extra code.
|
||||
- **`Enrich`**: Three enrichers automatically attach properties to every event: `FromLogContext` (reads any properties pushed by your code), `WithMachineName` (computer hostname), `WithThreadId` (which thread is running).
|
||||
|
||||
### Program.cs
|
||||
|
||||
```csharp
|
||||
if (!builder.Environment.IsEnvironment("Testing"))
|
||||
{
|
||||
builder.Host.UseSerilog((ctx, services, config) =>
|
||||
config.ReadFrom.Configuration(ctx.Configuration)
|
||||
.ReadFrom.Services(services)
|
||||
.Enrich.FromLogContext()
|
||||
.Enrich.WithMachineName()
|
||||
.Enrich.WithThreadId());
|
||||
}
|
||||
```
|
||||
|
||||
The `if (!Testing)` guard is needed because Serilog's setup is a one-time operation per process. Integration tests can create multiple fake servers within a single test run, and initializing Serilog a second time would throw an error.
|
||||
|
||||
`ReadFrom.Configuration` reads the `Serilog` section from appsettings.json. This means you can change logging settings (add sinks, change levels) by editing config files without recompiling your code.
|
||||
|
||||
---
|
||||
|
||||
## Step 3: Request Logging
|
||||
|
||||
Every time someone calls your API (e.g., `POST /api/encounters/123/observations`), ASP.NET Core's default logger writes multiple log events: "request starting," "reading headers," "writing response," "request finished." That's 4+ events per request — noisy and hard to read. Serilog replaces all of those with a single, compact summary event:
|
||||
|
||||
```csharp
|
||||
app.UseSerilogRequestLogging(options =>
|
||||
{
|
||||
options.MessageTemplate =
|
||||
"HTTP {RequestMethod} {RequestPath} responded {StatusCode} in {Elapsed:0.000}ms";
|
||||
});
|
||||
```
|
||||
|
||||
This produces one structured event per request with properties:
|
||||
- `RequestMethod` (GET, POST, PATCH)
|
||||
- `RequestPath` (/api/encounters/123/observations)
|
||||
- `StatusCode` (200, 400, 500)
|
||||
- `Elapsed` (milliseconds)
|
||||
|
||||
The `{Elapsed:0.000}` format shows 3 decimal places (microsecond precision).
|
||||
|
||||
---
|
||||
|
||||
## Step 4: Correlation IDs
|
||||
|
||||
**What is a correlation ID?** When a single user action (like recording a vital sign) triggers work across multiple services — the API, Kafka consumers, the notification system — each service writes its own logs. A correlation ID is a unique identifier that ties all of these log entries together. By searching for one correlation ID in Seq, you can see every log event from every service that was involved in processing that one request. Without it, you'd have no way to connect "observation ingested" in the API to "qSOFA evaluated" in the sepsis engine to "page sent" in the notification service.
|
||||
|
||||
**What is middleware?** In ASP.NET Core, middleware is code that runs on every HTTP request, in a pipeline. Each middleware component can inspect the request, do some work, and pass it to the next middleware in the chain. Think of it like a series of checkpoints at an airport — each checkpoint does one thing (check ID, scan bags, stamp passport).
|
||||
|
||||
The `CorrelationIdMiddleware` adds a `CorrelationId` property to every log event within a request:
|
||||
|
||||
```csharp
|
||||
public sealed class CorrelationIdMiddleware
|
||||
{
|
||||
private const string Header = "X-Correlation-Id";
|
||||
private readonly RequestDelegate _next;
|
||||
|
||||
public CorrelationIdMiddleware(RequestDelegate next) => _next = next;
|
||||
|
||||
public async Task InvokeAsync(HttpContext ctx)
|
||||
{
|
||||
var correlationId = ctx.Request.Headers[Header].FirstOrDefault()
|
||||
?? Guid.NewGuid().ToString();
|
||||
|
||||
ctx.Response.Headers[Header] = correlationId;
|
||||
|
||||
using (LogContext.PushProperty("CorrelationId", correlationId))
|
||||
{
|
||||
await _next(ctx);
|
||||
}
|
||||
}
|
||||
}
|
||||
```
|
||||
|
||||
How it works:
|
||||
1. Check if the incoming HTTP request has an `X-Correlation-Id` header (callers like the ward gateway can set this so their ID propagates)
|
||||
2. If no header is present, generate a new GUID (a random unique identifier)
|
||||
3. Echo the ID back in the response header so the caller can use it for their own logging
|
||||
4. Push it onto Serilog's `LogContext` — this is the key part. `LogContext.PushProperty` makes the correlation ID appear automatically on every `_logger.Log*()` call within this request, without passing it explicitly as a parameter
|
||||
|
||||
The `using` block ensures the property is removed when the request completes. Without this, the property could "leak" into the next request handled on the same thread, causing logs to have the wrong correlation ID.
|
||||
|
||||
Registered in the middleware pipeline in `Program.cs`:
|
||||
|
||||
```csharp
|
||||
app.UseMiddleware<CorrelationIdMiddleware>();
|
||||
app.UseMiddleware<FhirApiKeyOrJwtMiddleware>();
|
||||
app.UseMiddleware<ExceptionHandlerMiddleware>();
|
||||
```
|
||||
|
||||
Order matters — `CorrelationIdMiddleware` runs first so that all subsequent middleware and handlers have the correlation ID in their log context.
|
||||
|
||||
---
|
||||
|
||||
## Step 5: Adding Context to Logs with LogContext.PushProperty
|
||||
|
||||
The correlation ID middleware adds context to the entire request. But sometimes you want to add context for just part of the request — for example, when processing a specific encounter. `LogContext.PushProperty` lets you push additional named properties that automatically appear on all log events within a `using` block:
|
||||
|
||||
```csharp
|
||||
// In ObservationService.IngestAsync
|
||||
using (LogContext.PushProperty("EncounterId", encounterId))
|
||||
using (LogContext.PushProperty("PatientId", encounter.PatientId))
|
||||
{
|
||||
// Every log call within this block automatically includes
|
||||
// EncounterId and PatientId as structured properties
|
||||
|
||||
_logger.LogInformation(
|
||||
"Observation {ObservationId} ingested for encounter {EncounterId}. AlertCreated={AlertCreated}",
|
||||
observation.Id, encounterId, alert is not null);
|
||||
}
|
||||
```
|
||||
|
||||
The `{EncounterId}` in the message template creates a property from the parameter. The `LogContext.PushProperty("EncounterId", encounterId)` adds it as ambient context — even if a called method doesn't pass it explicitly, it appears on the log event.
|
||||
|
||||
---
|
||||
|
||||
## Step 6: Exception Handling Middleware
|
||||
|
||||
The `ExceptionHandlerMiddleware` catches all unhandled exceptions and logs them at the appropriate level:
|
||||
|
||||
```csharp
|
||||
public async Task InvokeAsync(HttpContext context)
|
||||
{
|
||||
try
|
||||
{
|
||||
await _next(context);
|
||||
}
|
||||
catch (NotFoundException ex)
|
||||
{
|
||||
_logger.LogWarning("{Message}", ex.Message);
|
||||
await WriteAsync(context, 404,
|
||||
ApiResponse<object>.Fail(404, ex.Message, ex.ErrorCode));
|
||||
}
|
||||
catch (BadRequestException ex)
|
||||
{
|
||||
_logger.LogWarning("{Message}", ex.Message);
|
||||
await WriteAsync(context, 400,
|
||||
ApiResponse<object>.Fail(400, ex.Message, ex.ErrorCode));
|
||||
}
|
||||
catch (ValidationException ex)
|
||||
{
|
||||
_logger.LogWarning("{Message}", ex.Message);
|
||||
await WriteAsync(context, 422,
|
||||
ApiResponse<object>.Fail(422, ex.Message, ex.ErrorCode));
|
||||
}
|
||||
catch (ConflictException ex)
|
||||
{
|
||||
_logger.LogWarning("{Message}", ex.Message);
|
||||
await WriteAsync(context, 409,
|
||||
ApiResponse<object>.Fail(409, ex.Message, ex.ErrorCode));
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.LogError(ex, "Unhandled exception");
|
||||
await WriteAsync(context, 500,
|
||||
ApiResponse<object>.Fail(500, "An unexpected error occurred", "INTERNAL_ERROR"));
|
||||
}
|
||||
}
|
||||
```
|
||||
|
||||
Design decisions:
|
||||
- **Client errors (4xx)** are logged as `Warning` — they're expected and don't indicate system problems
|
||||
- **Server errors (5xx)** are logged as `Error` with the full exception — these need investigation
|
||||
- The exception object is passed as the first argument to `LogError(ex, ...)`, which captures the stack trace as a structured property in Seq
|
||||
- The response body never leaks exception details to the client — it returns a generic "An unexpected error occurred" message
|
||||
|
||||
---
|
||||
|
||||
## Step 7: Logging Patterns in Background Services
|
||||
|
||||
Background services log lifecycle events and errors with consistent patterns:
|
||||
|
||||
### Startup Announcement
|
||||
|
||||
```csharp
|
||||
// OutboxRelayService
|
||||
_logger.LogInformation("Outbox relay started. PollInterval={Interval}ms",
|
||||
_options.OutboxPollIntervalMs);
|
||||
|
||||
// TrendAnalyzerService
|
||||
_logger.LogInformation("TrendAnalyzerService started — consumer group: trend-analyzer");
|
||||
```
|
||||
|
||||
### Error Recovery
|
||||
|
||||
```csharp
|
||||
// OutboxRelayService - logs and continues to next poll cycle
|
||||
catch (Exception ex) when (ex is not OperationCanceledException)
|
||||
{
|
||||
_logger.LogError(ex, "Outbox relay error — will retry on next poll cycle");
|
||||
}
|
||||
```
|
||||
|
||||
The `when (ex is not OperationCanceledException)` filter is a C# exception filter. `OperationCanceledException` is thrown when the application is shutting down — it's expected and normal, not an error. Without this filter, every graceful shutdown would log a scary-looking error message.
|
||||
|
||||
### Retry with Backoff
|
||||
|
||||
```csharp
|
||||
// ThresholdCacheLoader - retries Redis 3 times with exponential backoff
|
||||
catch (RedisException ex)
|
||||
{
|
||||
_logger.LogWarning(ex,
|
||||
"Redis unavailable during threshold cache load — attempt {Attempt}/{Max}",
|
||||
attempt + 1, maxAttempts);
|
||||
}
|
||||
|
||||
// After all retries exhausted:
|
||||
_logger.LogError(
|
||||
"Failed to load thresholds into Redis after {Max} attempts — " +
|
||||
"application will start without cache; observation ingest falls back to PostgreSQL",
|
||||
maxAttempts);
|
||||
```
|
||||
|
||||
The warning-then-error pattern: retryable failures are `Warning` (not alarming), final failure is `Error` (needs attention).
|
||||
|
||||
### Patient Safety Logs
|
||||
|
||||
```csharp
|
||||
// AlertsUnacknowledgedCollector
|
||||
if (count > 0)
|
||||
_logger.LogWarning(
|
||||
"[PATIENT-SAFETY] alerts_unacknowledged_gauge={Count} " +
|
||||
"(CRITICAL alerts open > 5 min)", count);
|
||||
```
|
||||
|
||||
The `[PATIENT-SAFETY]` prefix is a convention for logs that indicate clinical risk. In Seq, you can create a saved search for this prefix.
|
||||
|
||||
### Clinical Event Logs
|
||||
|
||||
```csharp
|
||||
// ObservationService - critical threshold breach
|
||||
_logger.LogWarning(
|
||||
"Critical threshold breach. Code={Code} Value={Value} AlertId={AlertId}",
|
||||
req.ObservationCode, req.Value, alert.Id);
|
||||
|
||||
// ObservationService - every observation ingest
|
||||
_logger.LogInformation(
|
||||
"Observation {ObservationId} ingested for encounter {EncounterId}. AlertCreated={AlertCreated}",
|
||||
observation.Id, encounterId, alert is not null);
|
||||
|
||||
// Duplicate detection
|
||||
_logger.LogInformation(
|
||||
"Duplicate idempotency key {Key} for encounter {EncounterId} — returning original",
|
||||
req.IdempotencyKey, encounterId);
|
||||
```
|
||||
|
||||
---
|
||||
|
||||
## Step 8: Structured Property Naming Conventions
|
||||
|
||||
The project follows consistent naming patterns:
|
||||
|
||||
| Pattern | Example | When to use |
|
||||
|---------|---------|-------------|
|
||||
| `{EntityId}` | `{ObservationId}`, `{AlertId}` | Primary key of the entity being processed |
|
||||
| `{EntityProperty}` | `{Code}`, `{Value}`, `{Status}` | Properties of the entity |
|
||||
| `{Count}` | `{Count}` | Numeric counts |
|
||||
| `{Attempt}/{Max}` | `{Attempt}/{Max}` | Retry tracking |
|
||||
| `[TAG]` prefix | `[PATIENT-SAFETY]`, `[RECONCILIATION]` | Category markers for saved searches |
|
||||
|
||||
Always use **message templates** with named placeholders, never C# string interpolation:
|
||||
|
||||
```csharp
|
||||
// CORRECT — creates structured properties
|
||||
_logger.LogInformation("Observation {ObservationId} ingested", observation.Id);
|
||||
|
||||
// WRONG — creates a flat string, loses structured queryability
|
||||
_logger.LogInformation($"Observation {observation.Id} ingested");
|
||||
```
|
||||
|
||||
These look similar but behave very differently. The first form uses Serilog's **message template** syntax — the `{ObservationId}` placeholder creates a named property that Seq can index, filter, and group by. The second form uses C#'s `$""` string interpolation, which bakes the value directly into the message text before Serilog ever sees it. Seq can only do full-text search on it, not structured queries. This is the single most important rule to follow with structured logging.
|
||||
|
||||
---
|
||||
|
||||
## Seq: The Log Aggregation Server
|
||||
|
||||
### Docker Setup
|
||||
|
||||
```yaml
|
||||
seq:
|
||||
image: datalust/seq:latest
|
||||
environment:
|
||||
ACCEPT_EULA: "Y"
|
||||
SEQ_FIRSTRUN_ADMINPASSWORD: "admin"
|
||||
ports:
|
||||
- "5345:80"
|
||||
volumes:
|
||||
- seq_data:/data
|
||||
```
|
||||
|
||||
### Accessing Seq
|
||||
|
||||
Open `http://localhost:5345` in a browser. Login: admin / admin.
|
||||
|
||||
### What You Can Do in Seq
|
||||
|
||||
- **Search by property**: `CorrelationId = "abc-123"` shows every log event from a single request across all services
|
||||
- **Filter by level**: Click "Warning" to see only warnings and errors
|
||||
- **Filter by source**: `SourceContext like "OutboxRelay%"` shows only outbox relay logs
|
||||
- **Time range**: Narrow to a specific time window when an incident occurred
|
||||
- **Live tail**: Watch logs stream in real time during replay simulation
|
||||
|
||||
### Useful Seq Queries
|
||||
|
||||
```
|
||||
# All critical threshold breaches
|
||||
AlertId is not null and @Level = 'Warning' and @MessageTemplate like '%threshold breach%'
|
||||
|
||||
# All patient safety events
|
||||
@Message like '[PATIENT-SAFETY]%'
|
||||
|
||||
# Trace a single request across the system
|
||||
CorrelationId = 'your-correlation-id-here'
|
||||
|
||||
# All errors in the last hour
|
||||
@Level = 'Error' and @Timestamp > Now() - 1h
|
||||
|
||||
# All observation ingests for a specific encounter
|
||||
EncounterId = '3fa85f64-5717-4562-b3fc-2c963f66afa6'
|
||||
|
||||
# Outbox relay problems
|
||||
SourceContext like 'OutboxRelay%' and @Level in ['Warning', 'Error']
|
||||
```
|
||||
|
||||
---
|
||||
|
||||
## Log Level Guidelines
|
||||
|
||||
| Level | When to Use | Example |
|
||||
|-------|-------------|---------|
|
||||
| `Debug` | Detailed diagnostic info, noisy, off by default | Kafka lag collection failures, ES debug upserts |
|
||||
| `Information` | Normal operations worth recording | Service started, observation ingested, batch processed |
|
||||
| `Warning` | Unexpected but handled situations | Duplicate idempotency key, Redis retry, threshold breach, client errors (4xx) |
|
||||
| `Error` | Failures that need investigation | Unhandled exceptions, max retries exhausted, service crashes |
|
||||
|
||||
---
|
||||
|
||||
## Enrichers Summary
|
||||
|
||||
Every log event automatically includes these properties:
|
||||
|
||||
| Property | Source | Example Value |
|
||||
|----------|--------|---------------|
|
||||
| `CorrelationId` | `CorrelationIdMiddleware` | `"a1b2c3d4-e5f6-..."` |
|
||||
| `MachineName` | `Serilog.Enrichers.Environment` | `"dev-laptop"` |
|
||||
| `ThreadId` | `Serilog.Enrichers.Thread` | `14` |
|
||||
| `SourceContext` | Serilog (automatic from `ILogger<T>`) | `"ObservationService"` |
|
||||
| `RequestMethod` | `UseSerilogRequestLogging` | `"POST"` |
|
||||
| `RequestPath` | `UseSerilogRequestLogging` | `"/api/encounters/123/observations"` |
|
||||
| `StatusCode` | `UseSerilogRequestLogging` | `201` |
|
||||
|
||||
Plus any ambient properties pushed via `LogContext.PushProperty` (like `EncounterId`, `PatientId`).
|
||||
Reference in New Issue
Block a user