Observability — Structured Logs, Metrics, Traces, and the Four Golden Signals
Understand observability as distinct from basic monitoring: structured JSON logging, metrics, and distributed traces as the three pillars; correlation/request IDs that tie a single logical operation together across log lines and services; OpenTelemetry as the vendor-neutral standard for traces, including how to create a span from PHP code; Sentry-style error tracking; and the operational split between health checks, readiness probes, and liveness probes, framed around the four golden signals (latency, traffic, errors, saturation).
A PHP-FPM pool sitting behind a load balancer, calling two other internal services and a database, fails in ways that a single error_log() line can never fully explain. Which request triggered it? Which of the three downstream calls was slow? Was the whole fleet degraded or just one worker? Observability is the practice of instrumenting a system so those questions can be answered AFTER the fact, from data the system already emits, rather than requiring you to have predicted the exact question in advance and wired up a bespoke dashboard for it. Monitoring tells you THAT something is wrong (a dashboard, an alert); observability lets you ask WHY, using the same underlying data -- logs, metrics, and traces -- without redeploying new instrumentation mid-incident. This lesson builds the practical vocabulary and PHP-level mechanics behind that idea.
The Three Pillars: Logs, Metrics, and Traces
Logs are discrete, timestamped events -- 'user 42 logged in', 'payment failed: card declined' -- each one a fact about something that happened at a specific instant. They are the richest and most flexible pillar (a log line can carry arbitrary context) but also the most expensive to store and search at high volume, and the hardest to correlate across many instances unless every line carries a shared identifier.
Metrics are aggregated numeric time series -- a counter of requests handled, a gauge of current queue depth, a histogram of response-time buckets -- sampled or accumulated over fixed intervals. They are cheap to store and graph over long time ranges precisely because they throw away per-event detail in exchange for aggregate shape: a metric can tell you the error rate jumped from 0.1% to 4% at 14:02, but not which specific request failed or why.
Traces capture the causal, timed structure of a single logical operation as it moves through a system -- a root span for the incoming HTTP request, child spans for the database query and the two downstream service calls it makes, each with its own start time and duration. A trace answers 'where did the time for THIS one slow request actually go' in a way neither a log line nor an aggregate metric can, because it preserves the parent-child timing relationships between the individual steps.
• Logs -- discrete events with rich, arbitrary context; expensive to store/search at scale. • Metrics -- cheap, aggregated numeric time series; great for dashboards and alerting thresholds, poor for root-causing one specific request. • Traces -- the causal, timed chain of work for one logical operation across functions and services. • Real observability stacks correlate all three via shared identifiers (request ID, trace ID) rather than treating them as separate silos.
The Four Golden Signals: Latency, Traffic, Errors, Saturation
Popularized by Google's SRE practice, the four golden signals are the minimum set of measurements that, tracked well, cover most of what matters about a running service's health. Latency is how long requests take -- and crucially, the DISTRIBUTION matters far more than the average: a p50 of 80ms hides a p99 of 4 seconds that a meaningful fraction of real users are actually experiencing, so production dashboards track percentiles (p50/p95/p99), not just a mean.
Traffic (throughput) is demand on the system -- requests per second, jobs processed per minute -- the denominator against which everything else should be read; an error rate that looks stable can still represent a rapidly growing absolute count of failing requests if traffic is climbing. Errors is the fraction of requests that failed, whether that's an HTTP 5xx, an uncaught exception, or a job that ended in a failed state rather than success.
Saturation is how 'full' a limited resource is -- PHP-FPM's active-workers-over-max-children ratio, a queue's backlog depth, memory usage against the configured limit, database connection-pool utilization. Saturation is the leading indicator that predicts the other three getting worse: a pool creeping toward 100% busy workers is the early warning that latency and errors are about to spike, well before either actually does.
• Latency -- track percentiles (p50/p95/p99), not just the average; the tail is where users feel pain. • Traffic -- requests/sec or jobs/min; the context that makes error counts and latency meaningful. • Errors -- 5xx rate, uncaught exception rate, failed-job rate. • Saturation -- how full a bounded resource is (FPM workers, queue depth, memory, connection pool); the earliest warning sign.
Structured Logging: JSON Logs and Correlation IDs
A plain-text log line like 'User 42 not found' is easy for a human to read once and nearly useless for a machine to query across millions of lines. A structured log line encodes the same event as a JSON object with consistent field names -- timestamp, level, message, and a context object -- so a log aggregator (Loki, Elasticsearch, CloudWatch Logs Insights) can filter, group, and count on those fields directly: 'show me every ERROR-level line where context.user_id = 42 in the last hour' is a real, fast query against structured logs and an approximation-at-best regex hunt against plain text.
The field that makes structured logs genuinely powerful in a distributed system is a correlation ID -- often called a request ID -- generated once at the edge of the system (the first service that receives the incoming request) and threaded through every subsequent log line, and forwarded as an HTTP header (commonly X-Request-Id) to every downstream service call that request triggers. Every log line, from every service, that was involved in handling that one user action then shares the same request_id value, turning 'grep the request ID across every service's logs' into a complete, chronological picture of exactly what happened for that one request -- something no single service's logs alone could show.
• Structured (JSON) logs have consistent, queryable fields instead of free-form text. • A correlation/request ID is generated once at the system's edge and propagated via an HTTP header to every downstream call. • Every log line for one logical request, across every service it touches, shares that one ID. • Without a correlation ID, reconstructing a multi-service incident means manually guessing which lines in each service's logs belong together by timestamp alone.
Distributed Tracing and OpenTelemetry in PHP
A trace is made of spans: a span represents one unit of work with a start time, a duration, and (usually) a parent span, forming a tree -- the root span is the whole incoming request, and child spans nest inside it for the database query, the cache lookup, the outbound HTTP call to another service. A span carries attributes (key-value metadata, like db.statement or http.status_code) and can record exceptions and status. Trace context -- which trace and which parent span a new span belongs to -- propagates across service boundaries via the W3C traceparent HTTP header, the same basic mechanism as a correlation ID but standardized and carrying binary trace/span identifiers rather than an opaque string.
OpenTelemetry (OTel) is the vendor-neutral standard for producing this data: an API for instrumenting code, an SDK that implements it and exports to a backend, and exporters for specific platforms (Jaeger, Tempo, Honeycomb, Datadog, and others all accept OTel data). In PHP, the open-telemetry/api and open-telemetry/sdk Composer packages provide Tracer, SpanBuilder, and Span objects; most real applications lean on auto-instrumentation packages (for PDO, Guzzle, common frameworks) that create spans automatically, reserving hand-written spans for application-specific logic worth seeing on its own in a trace view.
Creating a span manually follows a consistent shape regardless of what it wraps: get a tracer, start a span (which makes it the active span), do the work inside a try/finally so the span reliably ends even on an exception, and record any exception on the span before it propagates. The second example below shows this pattern around a database call.
• A span = one unit of work with start time, duration, attributes, and a parent (forming a tree = the trace). • Trace context propagates across services via the W3C traceparent header. • OpenTelemetry = vendor-neutral API + SDK + exporters; PHP uses the open-telemetry/api and open-telemetry/sdk packages. • Prefer auto-instrumentation for common infrastructure calls; hand-write spans only for application logic worth seeing distinctly in a trace.
Error Tracking, Health Checks, and Readiness vs Liveness
A dedicated error-tracking service (Sentry is the most common shape of this, though the pattern generalizes) captures each uncaught exception with its full stack trace, the request context that triggered it, breadcrumbs (a trail of recent events leading up to the error), and tags like release version and environment -- then GROUPS occurrences of what is structurally the same error (same exception class, same top stack frame) into one issue with an occurrence count, instead of drowning the team in one alert per individual failure. This grouping is what makes error tracking practical at any real traffic volume: a bug affecting 1% of requests generates one issue to triage, not thousands of identical alerts.
A health check endpoint answers a narrower, operational question: 'should traffic be sent to this instance right now?' Kubernetes (and most orchestrators) distinguish two variants that serve genuinely different purposes. Liveness asks 'is this process alive and functioning, or should it be killed and restarted?' -- it should be a cheap, minimal check (the process can respond to HTTP at all) because a failing liveness probe causes a RESTART, and restarting on something that will fix itself without a restart just adds churn. Readiness asks 'can this specific instance currently handle real traffic?' -- it should check the things that would make THIS instance unable to serve requests right now even though the process itself is fine, like a lost database connection or an in-progress startup/warm-up -- and a failing readiness probe simply pulls the instance out of load-balancer rotation TEMPORARILY, with no restart, until it reports ready again.
Conflating the two is a common production mistake: wiring liveness to check downstream database health means a transient database blip restarts every application pod simultaneously (making the outage worse and slower to recover from) instead of just quietly draining traffic away from them via readiness until the database recovers.
• Error tracking groups occurrences of the same underlying bug into one issue with a count, rather than one alert per occurrence. • Liveness -- 'is the process alive?' Failing it causes a RESTART. Keep it cheap and minimal. • Readiness -- 'can this instance serve traffic right now?' Failing it causes temporary REMOVAL from load-balancer rotation, no restart. • Checking downstream dependencies (DB, cache) belongs in readiness, not liveness.
Code Examples
Every log line this class emits carries the same request_id, either inherited from an upstream X-Request-Id header or freshly minted if this service is the first to see the request -- so grepping one ID across every service's stdout logs reconstructs the full story of one user action. Writing JSON to STDOUT (not a local file) is the standard pattern in containerized deployments, where the container runtime or a sidecar log shipper is responsible for forwarding stdout to the aggregation platform. Expected result: {"timestamp":"2026-01-15T10:22:01.104+00:00","level":"info","message":"order lookup started","service":"orders-api","request_id":"a13f9c02de44b8f1","context":{"order_id":4821}} {"timestamp":"2026-01-15T10:22:01.109+00:00","level":"error","message":"order lookup failed","service":"orders-api","request_id":"a13f9c02de44b8f1","context":{"order_id":4821,"exception":"order not found"}}
$requestId = $_SERVER['HTTP_X_REQUEST_ID'] ?? bin2hex(random_bytes(8));
spanBuilder()->startSpan() creates the span and records its start time; activate() makes it the parent for any nested spans created further down the call stack (so a span created inside the PDO call itself, by auto-instrumentation, would nest under this one). The try/finally block is not optional decoration -- without it, a thrown exception would skip $scope->detach() and $span->end(), leaving the span open forever from the exporter's point of view and corrupting the trace timeline.
$scope = $span->activate();
Common mistake: Calling $span->end() only on the success path and forgetting the finally block -- any exception then leaves the span permanently unclosed in the exported trace, which typically shows up as a span with no duration or one that never appears in the trace view at all.
livenessCheck() never touches the database or cache -- it only proves the PHP process can accept and answer an HTTP request at all, because a failure here triggers a restart, and a restart won't fix a database outage (it would just make the outage worse by cycling every instance). readinessCheck() is where dependency health belongs, because a 503 from it only removes this one instance from rotation until the dependency recovers.
http_response_code($allHealthy ? 200 : 503);
<?php
declare(strict_types=1);
final class RequestLogger
{
public function __construct(
private readonly string $requestId,
private readonly string $service = 'orders-api',
) {}
public static function fromIncomingRequest(): self
{
// Reuse an inbound correlation ID from an upstream service if present,
// otherwise mint a new one -- this request becomes the edge of the trail.
$requestId = $_SERVER['HTTP_X_REQUEST_ID'] ?? bin2hex(random_bytes(8));
return new self($requestId);
}
public function info(string $message, array $context = []): void
{
$this->write('info', $message, $context);
}
public function error(string $message, array $context = []): void
{
$this->write('error', $message, $context);
}
private function write(string $level, string $message, array $context): void
{
$line = [
'timestamp' => (new DateTimeImmutable())->format(DateTimeInterface::RFC3339_EXTENDED),
'level' => $level,
'message' => $message,
'service' => $this->service,
'request_id' => $this->requestId,
…<?php
declare(strict_types=1);
use OpenTelemetry\API\Globals;
use OpenTelemetry\API\Trace\SpanKind;
use OpenTelemetry\API\Trace\StatusCode;
function fetchUser(PDO $pdo, int $id): array
{
$tracer = Globals::tracerProvider()->getTracer('orders-api.users');
$span = $tracer->spanBuilder('db.fetchUser')
->setSpanKind(SpanKind::KIND_CLIENT)
->startSpan();
$scope = $span->activate(); // makes this span the "current" one for any nested spans
try {
$span->setAttribute('db.system', 'mysql');
$span->setAttribute('db.statement', 'SELECT * FROM users WHERE id = ?');
$span->setAttribute('db.user_id', $id);
$stmt = $pdo->prepare('SELECT * FROM users WHERE id = ?');
$stmt->execute([$id]);
$user = $stmt->fetch(PDO::FETCH_ASSOC) ?: [];
$span->setAttribute('db.rows_returned', $user === [] ? 0 : 1);
return $user;
} catch (\Throwable $e) {
$span->recordException($e);
$span->setStatus(StatusCode::STATUS_ERROR, $e->getMessage());
throw $e;
} finally {
$scope->detach(); // always detach, even on exception
$span->end(); // always end, so duration is rec
…<?php
declare(strict_types=1);
// GET /healthz/live -- cheap, minimal: "is the PHP process itself responding?"
// A failure here should trigger a container RESTART.
function livenessCheck(): void
{
http_response_code(200);
header('Content-Type: application/json');
echo json_encode(['status' => 'alive']);
}
// GET /healthz/ready -- checks real dependencies this instance needs to serve
// traffic. A failure here should pull this instance out of LB rotation, no restart.
function readinessCheck(PDO $pdo, Redis $redis): void
{
$checks = [];
$allHealthy = true;
try {
$pdo->query('SELECT 1');
$checks['database'] = 'ok';
} catch (\Throwable) {
$checks['database'] = 'unreachable';
$allHealthy = false;
}
try {
$redis->ping();
$checks['cache'] = 'ok';
} catch (\Throwable) {
$checks['cache'] = 'unreachable';
$allHealthy = false;
}
http_response_code($allHealthy ? 200 : 503);
header('Content-Type: application/json');
echo json_encode(['status' => $allHealthy ? 'ready' : 'not_ready', 'checks' => $checks]);
}The observability data path
The three pillars are produced independently but correlated by shared identifiers (request_id, trace_id); the platform is what turns raw logs/metrics/traces into alerts that page someone, dashboards that show trend, and a debugging workflow that lets you jump from 'this alert fired' to 'here is the exact trace and log lines that explain why'.
Application (PHP)
|
| emits, per request
v
+-----------+ +-----------+ +-----------+
| Logs | | Metrics | | Traces | each tagged with the same
| (JSON, | | (counters,| | (spans, | request_id / trace_id
| request_ | | gauges, | | parent- |
| id field) | | histograms| | child) |
+-----------+ +-----------+ +-----------+
\ | /
\ | /
'-------------v-------------'
Observability Platform
(e.g. Grafana+Loki+Tempo, Datadog, Honeycomb)
|
+-------------+-------------+
v v v
Alerts Dashboards Debugging
(on-call gets (golden signal (jump from an
paged when a trends over alert straight
threshold is time) to the exact
crossed) trace/logs)Important Rules
Track latency as a distribution (p50/p95/p99), never as a single average.
Generate one correlation/request ID per incoming request, at the edge, and propagate it to every downstream call via an HTTP header.
Structured (JSON) logs over plain text for anything that needs to be queried or aggregated later.
Always end() a span in a finally block, and recordException() before rethrowing.
Liveness checks the process; readiness checks dependencies. Never let a downstream dependency failure trigger a restart via liveness.
Group error-tracking issues by underlying cause, not by individual occurrence, to keep on-call alerting meaningful.
Why This Matters in Production
During a real incident, the difference between 'we have logs' and 'we have observability' is whether an engineer can go from 'checkout is failing for some users' to 'here is the exact trace showing the payment service's 3rd retry timing out, and here are the 40 other requests sharing the same failure signature' in minutes rather than hours of grepping unrelated log files across five services by hand. The four golden signals dashboard is usually the first thing opened during an incident precisely because saturation trending up is often the earliest, clearest signal that something is about to break, well before error rate or latency confirms it.
error_log("User {$id} not found in database");
$logger->error('user lookup failed', ['user_id' => $id, 'reason' => 'not_found']);
The plain-text version is fine for a human reading one server's log file by eye, but cannot be reliably filtered, grouped, or correlated with other services' logs at scale. The structured version has a stable field name (user_id) a log platform can query directly, and -- combined with a shared request_id -- can be correlated with every other log line from the same request across every service.
readinessProbe: { path: '/healthz' } livenessProbe: { path: '/healthz' } // same endpoint checks the database for both readinessProbe: { path: '/healthz/ready' } // checks DB/cache livenessProbe: { path: '/healthz/live' } // process-only, no dependencies
Pointing both probes at one endpoint that checks the database means a transient database outage restarts every pod simultaneously (liveness failing), instead of simply draining traffic away from them via readiness while the process itself stays up and recovers the instant the database does.
[multiple-choice] Which of the four golden signals is typically the earliest warning that latency and error rate are about to get worse? A. Traffic B. Saturation C. Errors D. Latency
B. Saturation — Saturation (how full a bounded resource like the PHP-FPM worker pool or a queue is) tends to trend upward before it actually causes visible latency or error spikes, making it the leading indicator of the four.
[multiple-choice] A readiness probe for a PHP service is failing because the database is temporarily unreachable. What SHOULD happen? A. The container is restarted immediately B. The instance is temporarily removed from load-balancer rotation, with no restart, until it reports ready again C. Nothing -- readiness failures are ignored by orchestrators D. The liveness probe is automatically disabled
B. The instance is temporarily removed from load-balancer rotation, with no restart, until it reports ready again — Readiness failures pull an instance out of traffic rotation without restarting it, because the process itself is fine -- only its ability to serve traffic right now is impaired. Restarting would not fix a database outage and would just add unnecessary churn.
[multiple-choice] What is the primary purpose of a correlation/request ID? A. To encrypt log data in transit B. To let every log line and span produced while handling one logical request, across every service involved, be tied back together C. To replace the need for metrics entirely D. To identify which PHP version generated a log line
B. To let every log line and span produced while handling one logical request, across every service involved, be tied back together — A correlation ID generated at the edge and propagated to every downstream call is what lets an engineer reconstruct the full cross-service story of one request, by searching for that one shared value across every service's logs and traces.
Your 'orders' service calls a 'payments' service over HTTP for every checkout. Design (in words, referencing the concepts in this lesson) how you would let an engineer trace one failed checkout all the way from the orders service's log line through to the specific payments-service span that caused it.
The orders service generates a request_id (or, if using OpenTelemetry, a trace ID) when the checkout request arrives, attaches it to every log line it writes, creates a span for the call to the payments service, and sends the trace context (a traceparent header, or at minimum the request_id) on the outbound HTTP call. The payments service reads that header, uses it as the parent for its own spans and as the request_id on its own log lines, so both services' logs and both services' spans share the identifier -- an engineer can then search either service's logs by that one ID, or open the trace in the tracing UI and see both services' spans in one connected timeline.
Think about what has to be generated once, what has to be propagated via a header, and what both services need to attach to every log line and span they emit.