A successful response says the invoice workflow finished. It does not explain where the request spent its time. Lab 07 explores that gap through a Go service that loads an invoice, reserves inventory, calculates commission, generates a PDF, and sends a notification.
The useful question is not just “Is the endpoint working?” It is “What happened inside this request, and which dependency explains its latency or failure?”
One workflow, two levels of visibility
The unsafe service executes the same five dependency operations but exposes only a coarse completion duration or a generic failure log. Its HTTP response can still contain a request ID. What is missing is the service-level breakdown needed to investigate the request.
The safe service adds structured logs, Prometheus metrics, and OpenTelemetry spans around the workflow. This changes the evidence available during investigation; it does not make the business operations themselves faster.
The demo dependencies simulate work using configurable delays and errors. A delay waits on a timer while also listening for context cancellation. These are controlled diagnostic scenarios, not measurements of a real database, inventory service, or PDF engine.
Logs, metrics, and traces answer different questions
Logs describe discrete events. The safe service emits a structured event when a dependency completes, with its component, operation, duration, and outcome. On failure, the event also carries an error.
Metrics summarize many requests. Request counters describe traffic, duration histograms describe latency, error counters describe failures, and an in-flight gauge describes active requests. The gauge is a concurrency signal; it is not a complete measurement of CPU capacity or resource saturation.
Traces explain a particular execution. A server span contains an invoice-processing span, which contains one span for each dependency operation. That hierarchy connects the HTTP request to the work performed inside it.
A latency histogram can reveal a shift across requests. A trace can identify the slow operation in one request. A structured log can provide the event details at that operation. None replaces the other two.
Make the slow step visible
The demo's normal configuration assigns 20 ms to invoice loading, 15 ms to inventory, 10 ms to commission, 30 ms to PDF generation, and 20 ms to notification. The configured delays sum to approximately 95 ms before runtime and instrumentation overhead.
In the slow-PDF scenario, PDF generation receives a 4,800 ms delay. Keeping the other fake dependencies unchanged gives a configured total of approximately 4,865 ms. This is scenario arithmetic, not a benchmark result. An HTTP notification client also changes the execution path when enabled.
The point of the scenario is the contrast between “the request took several seconds” and “pdf.generate consumed most of the request.” A total-duration log provides the first statement. Dependency spans provide the second.
POST /invoices/{id}/process
invoice.process
database.load_invoice
inventory.reserve
commission.calculate
pdf.generate
notification.send
This is the hierarchy for the five-dependency workflow. A real HTTP notification call adds transport and downstream spans when those boundaries are instrumented.
Carry context through every dependency
The safe service starts a span for each dependency and passes that span's context into the dependency call. The context carries the causal relationship and cancellation signal together.
On a dependency failure, the implementation records the error on the dependency span and the invoice-processing span, marks them as failed, observes an error outcome, and returns a wrapped error identifying the component and operation. Processing stops at that failed step.
The HTTP handler then maps a processing error to a response: a deadline becomes 504, cancellation becomes 499, and other processing failures become 502. The response uses the generic message “invoice processing failed” and includes the request ID. Detailed failure information stays in telemetry.
These are mappings implemented by this lab, rather than a universal status-code policy.
Correlate events without turning IDs into metric labels
ContextLogger attaches request_id and, when an active span is valid, trace_id and span_id. The request ID helps connect the HTTP response to logs. The trace ID groups spans in one execution. The span ID identifies the active operation within that trace.
The correlation fields are useful in logs, but they are deliberately absent from metric labels. Request metrics use method, a route template, and status class. Dependency metrics use component, operation, and outcome.
The route label is /invoices/{id}/process, rather than a separate label value for each invoice URL. The registry tests also check that request IDs and invoice IDs do not leak into label values.
That distinction preserves aggregate metrics while leaving request-level investigation to logs and traces. The fixture tests check selected sensitive keys in emitted logs; they do not implement a general-purpose redaction system.
Read the metric names as an investigation map
The collector exposes six metric families:
| Metric | What it records |
|---|---|
| lab07_http_requests_total | Requests by method, route, and status class |
| lab07_http_request_duration_seconds | Request duration observations |
| lab07_http_request_errors_total | Processing errors at the HTTP boundary |
| lab07_http_in_flight_requests | Currently active requests for the route |
| lab07_dependency_duration_seconds | Dependency duration by component, operation, and outcome |
| lab07_dependency_errors_total | Dependency failures |
Histograms store duration observations in seconds. Structured dependency logs report duration_ms. Keep those units explicit when comparing the two.
The missing-ID branch records a 4xx request but does not increment the processing-error counter. The name “request errors” therefore needs to be read alongside the implementation's accounting rules.
Cross an HTTP boundary without losing the trace
The handler extracts incoming W3C trace context before starting its server span. The demo configures TraceContext and Baggage propagation globally.
For outgoing notifications, HTTPNotificationClient creates a request with the current context and uses an OpenTelemetry HTTP transport. The transport propagates trace context, while the client explicitly copies X-Request-ID from the context into the downstream request.
The default notification client has a five-second timeout. A supplied client is copied before its transport is wrapped, and an already instrumented transport is not wrapped again. Request cancellation still reaches the outgoing HTTP call through its context.
The local /notifications endpoint lets the demo exercise this HTTP boundary. It runs in the same demo process; this is not evidence of a deployed multi-service production system.
Exercise specific failure modes
The demo supports normal, slow-pdf, slow-database, slow-external, and pdf-error scenarios. They isolate different dependency delays or a PDF failure so the resulting telemetry can be inspected.
For example, with the demo and its configured telemetry services running:
curl -X POST 'http://localhost:8087/invoices/INV-007/process?scenario=slow-pdf' -H 'X-Request-ID: lab07-slow-pdf'
The corresponding unsafe route is /unsafe/invoices/INV-007/process. Comparing the routes makes the difference in diagnostic detail visible.
Use a stable request ID to find the relevant logs, inspect the request's dependency spans, and compare request-level duration observations with dependency duration observations. The useful outcome is an explanation of the configured scenario, not merely confirmation that an endpoint returned a response.
Treat telemetry behavior as a contract
The tests inspect span hierarchy, shared trace IDs, incoming trace-context extraction, outgoing propagation, request-ID preservation, structured log fields, and metric accounting.
The fake-dependency hierarchy test expects seven ended spans: one HTTP server span, one invoice-processing span, and five dependency spans. The HTTP notification path has additional instrumentation and should not be forced into that seven-span expectation.
The slow-PDF test uses a shorter, 10 ms delay and checks the recorded PDF span. Concurrent-request tests check mixed success and error responses, matching counters, and an in-flight gauge that returns to zero.
There is also a test for response-encoding failures. Such failures are logged with correlation fields, but the implementation has already recorded success accounting before encoding the successful response. That limitation matters when interpreting metrics.
These observations come from reading the source and its assertions. The Go tests were not executed in this content-generation environment.
The mental model
Observability is useful when the evidence explains a request: what happened, where its time went, and which operation failed. This lab makes that idea concrete by connecting dependency events, aggregate measurements, and a causal trace through one invoice workflow.
A system should explain what happened, where time was spent, and why it was slow or failed.
Repository: https://github.com/lukman-ss/software-engineering-lab/tree/main/labs/07-observability
Top comments (0)