Operating It
The logs, metrics, traces and alerts the service needs, what to look at first when it is slow, and the checklist for the next change.
Counter<long> redirects = meter.CreateCounter<long>("shortly.redirects");Once the service is running, every question you will have is about a request you did not watch happen. Three kinds of record answer them. Logs describe single events. Metrics are numbers aggregated over time: how many requests, how many failed, how long they took. Traces follow one request through every component it touched, with timings.
What to record
Log with named values rather than sentences built by hand, so a log system can filter on them. Give every log line the trace id, so a log and a trace lead to each other. Never log an Authorization header, a password or a token.
Four metrics cover most of it: request rate, error rate, request duration as a histogram, and one number from the domain, here redirects served. ASP.NET Core already emits the first three under http.server.request.duration; the fourth you write yourself.
When it is slow
Look in this order. Is it every endpoint or one? Split the duration histogram by route. If one endpoint, open a slow trace and see where the time sits, which is usually a query. If all endpoints, suspect the thing they share: the database, the connection pool, CPU throttling, or a pod that keeps restarting.
Alerts
Alert on what a user would notice, not on what a machine is doing. High CPU is not an incident. An error rate above two percent for ten minutes is. Every alert needs a line saying what to do about it, or it will be ignored by the third time it fires.
Example
using System.Diagnostics.Metrics;
// A Meter is a named group of instruments. The name is what an exporter
// subscribes to, so it should name your component, not the machine.
Meter meter = new Meter("Shortly.Links");
Counter<long> redirects = meter.CreateCounter<long>(
name: "shortly.redirects",
unit: "{redirect}",
description: "Redirects served, by outcome.");
// A MeterListener is how a metrics exporter reads instruments. Writing one
// by hand shows what a Counter actually does: it publishes measurements.
using MeterListener listener = new();
listener.InstrumentPublished = (instrument, meterListener) =>
{
if (instrument.Meter.Name == "Shortly.Links")
{
meterListener.EnableMeasurementEvents(instrument);
}
};
listener.SetMeasurementEventCallback<long>((instrument, value, tags, state) =>
{
Console.WriteLine($"{instrument.Name} += {value} ({tags[0].Key}={tags[0].Value})");
});
listener.Start();
// A tag is a label on the measurement. Keep the number of possible values
// small: one tag value per link code would create millions of time series.
redirects.Add(1, new KeyValuePair<string, object?>("outcome", "found"));
redirects.Add(1, new KeyValuePair<string, object?>("outcome", "found"));
redirects.Add(1, new KeyValuePair<string, object?>("outcome", "expired"));
// Output:
// shortly.redirects += 1 (outcome=found)
// shortly.redirects += 1 (outcome=found)
// shortly.redirects += 1 (outcome=expired)When to use it
- Finding which endpoint got slower after a deploy.
- Proving an outage was the database rather than the service.
- Deciding whether an alert is worth waking someone for.
More examples
Sending logs, metrics and traces out of the process
This is the whole of observability wiring for a service like this one. OTLP is a vendor-neutral protocol, so the collector address is an environment variable and the same build sends data to a local dashboard in development and to whatever the company runs in production. AddNpgsql is the line that makes a slow trace show the actual SQL.
using OpenTelemetry.Logs;
using OpenTelemetry.Metrics;
using OpenTelemetry.Resources;
using OpenTelemetry.Trace;
WebApplicationBuilder builder = WebApplication.CreateBuilder(args);
builder.Logging.AddOpenTelemetry(logging =>
{
logging.IncludeScopes = true; // carries the request's scope values
logging.AddOtlpExporter(); // without this, logs never leave the process
});
builder.Services.AddOpenTelemetry()
// The service name is how every dashboard and trace will label this app.
.ConfigureResource(resource => resource.AddService("shortly-api"))
.WithMetrics(metrics => metrics
.AddAspNetCoreInstrumentation() // http.server.request.duration
.AddHttpClientInstrumentation()
.AddRuntimeInstrumentation() // garbage collection, thread pool
.AddMeter("Shortly.Links") // the Meter from the example above
.AddOtlpExporter())
.WithTracing(tracing => tracing
.AddAspNetCoreInstrumentation()
.AddNpgsql() // from the Npgsql.OpenTelemetry package
.AddOtlpExporter());
WebApplication app = builder.Build();
app.MapGet("/r/{code}", (string code) => TypedResults.Redirect("https://example.com"));
app.Run();A log message with a name and a shape
Use the source-generated form on hot paths, such as the redirect that runs on every visit, and the LogInformation call anywhere else. Note what is logged: the target host, not the full URL, and never the token. Logging the whole target would put user-supplied text straight into your log index.
using Microsoft.Extensions.Logging;
namespace Shortly.Api.Endpoints;
// A partial method with [LoggerMessage] has its body generated at compile time.
// The containing class must be partial; it does not have to be static. The class
// is static here only because these log methods take the ILogger as a parameter.
// It costs nothing when the level is disabled, because the arguments are never
// boxed into an array.
internal static partial class LinkLog
{
[LoggerMessage(
EventId = 1001,
Level = LogLevel.Information,
Message = "Redirected {Code} to {TargetHost}")]
public static partial void Redirected(ILogger logger, string code, string targetHost);
[LoggerMessage(
EventId = 1002,
Level = LogLevel.Warning,
Message = "Expired code {Code} requested, expired at {ExpiredAt}")]
public static partial void ExpiredRequested(
ILogger logger, string code, DateTimeOffset expiredAt);
}
// At the call site:
// LinkLog.Redirected(logger, code, "example.com");
//
// The longhand it replaces, which still works and is still common:
// logger.LogInformation("Redirected {Code} to {TargetHost}", code, targetHost);
//
// Both produce the same structured record: a message template plus named
// values, so a log system can search on Code without parsing the sentence.An alert and the runbook line that goes with it
Two alerts are enough to start, and both are written against the metric ASP.NET Core emits by default rather than anything custom. The runbook annotation is the part people skip and the part that matters at three in the morning: it names the first command to run, so whoever is woken does not have to rediscover the service.
groups:
- name: shortly-api
rules:
# Symptom, not cause: the share of requests the user sees fail.
- alert: ShortlyErrorRatioHigh
expr: |
sum(rate(http_server_request_duration_seconds_count{job="shortly-api",http_response_status_code=~"5.."}[5m]))
/
sum(rate(http_server_request_duration_seconds_count{job="shortly-api"}[5m]))
> 0.02
for: 10m
labels:
severity: page
annotations:
summary: "More than 2% of requests are failing"
runbook: "Check /healthz/ready on a pod, then Postgres connections. Roll back with kubectl rollout undo deployment/shortly-api if the error started at a deploy."
# The 99th percentile of request duration, in seconds.
- alert: ShortlyLatencyHigh
expr: |
histogram_quantile(0.99,
sum by (le) (rate(http_server_request_duration_seconds_bucket{job="shortly-api"}[5m]))
) > 1
for: 15m
labels:
severity: ticket
annotations:
summary: "p99 request duration above 1s"
runbook: "Split by http_route to find the endpoint, then open a slow trace and look at the Npgsql spans."
Discussion