Module 5 ended on an uncomfortable question: we have seven services deployed on Kubernetes with canary releases and GitOps, but if an order's saga gets stuck tomorrow, how will we know? In the monolith the answer was "look at the server log": one process, one file, one grep. At TechCorp there are now dozens of pods that start and die, a request crosses three or four services, and a saga stays alive minutes after the HTTP request has finished. This lesson builds the first two legs of observability —structured logs and metrics— on top of the @techcorp/common-http library and the manifests we already have, and leaves the third, traces, for 06-02.

1. The three pillars of observability, and why "look at the log" is no longer enough
2. Structured logging with pino: extending createLogger
3. What not to log: redacting sensitive data
4. Log collection in Kubernetes: Promtail/Alloy and Loki
5. LogQL queries: following ord-88213 across several services
6. Metrics: types, the RED method and the USE method
7. Instrumentation with prom-client: GET /metrics in the library
8. Business metrics: orders, saga and outbox
9. Prometheus on Kubernetes and basic PromQL queries
10. Grafana dashboards and logs ↔ metrics correlation
11. Cost and cardinality

Monitoring is checking that the system does what we expect (does POST /v1/orders respond? how fast?). Observability is being able to answer questions we had not anticipated ("why has Ana Ruiz's order been sitting in STOCK_RESERVED for 20 minutes?") from what the system emits. It rests on three complementary signals:

In the monolith, log and trace were almost the same thing: a request was one thread of execution inside one process. With microservices, three things change: there are many ephemeral processes (a kubectl logs shows only one pod, and the pods of a rolling update from 05-04 disappear along with their logs: they have to be shipped out of the container and centralized); one action crosses several services (POST /v1/orders goes through the gateway, Orders, Catalog and Customers, and the saga carries on through RabbitMQ in Inventory, Payments and Notifications: nothing can be read without a common identifier, the X-Request-Id from 03-01 and the eventId from 03-02); and volume (on Black Friday the catalog multiplies ×20: reading logs by hand does not scale, and metrics summarize millions of requests in a handful of numbers).

Rule of the module: logs tell the detail, metrics tell the trend, and traces tell the path. The three are tied together by common identifiers.

A "text" log (Order ord-88213 created for c-1024) is easy to read and almost impossible to query. A structured log is one JSON object per line: every field can be filtered and aggregated. In 04-02 the library already offered createLogger({service}) built on pino; now we settle its final shape:

Line by line:

• level: the threshold. It comes from LOG_LEVEL (04-03), info in production and debug locally. Below the threshold pino does not even serialize the object: lowering the level costs no CPU.
• base: fixed fields added to every line. service is mandatory (orders-service); version (the image tag, 05-03) lets us compare the canary with the stable version.
• messageKey: 'message' and formatters.level: we replace pino's terse msg and numeric level with full names and the level label, so the whole JSON reads consistently alongside our identifiers; an ISO timestamp is understood by Loki and Grafana without any configuration; redact is covered in section 3.

The levels and when to use them:

The standard fields the four teams agreed on, so that Loki queries look the same in every service:

To avoid repeating those fields on every call we use child loggers (logger.child(...)). This is how the use case from 04-04 ends up:

In the saga consumer (messaging/sagaConsumer.js) the child is created from the message: logger.child({ eventId: event.id, eventType: event.type, orderId: event.data.orderId, queue: 'orders.saga' }). Real output of one line (one per row, no line breaks):

Access logs with pino-http. One line per HTTP request, generated by the middleware and not by hand. It goes into the library template right after requestIdMiddleware() so that it uses the same req.id:

• genReqId: if we did not set it, pino-http would generate its own id and we would lose the correlation with X-Request-Id; autoLogging.ignore avoids logging the Kubernetes probes (05-02), which call /health/* every 5-10 s.
• customLogLevel: a 5xx shows up as error without anyone having to remember; the serializers reduce req/res to method, route and code (pino-http also adds responseTime in ms).

A centralized log is read by many people and kept for weeks. Whatever goes into it must be readable without special permissions. At TechCorp it is forbidden to log: personal data beyond the identifier (customerId yes; Ana Ruiz's name, email or address, no); payment data (card number, CVV, PSP tokens); credentials (the Authorization header, cookies, passwords, the full RABBITMQ_URL, which contains user and password); and full request bodies at info (at debug only if they go through redaction).

pino's redact option does it for us: any property matching paths is replaced with [REDACTED] before serializing. *.card means "a card key in any top-level object". An example:

Redaction is a safety net, not a license: the rule is not to pass that data to the logger at all. The full treatment (encryption, secrets, auditing) belongs to 07-03; here it is enough that the logger does not leak them.

Services write to stdout (decision from 05-01: twelve factors, no files inside the container). The kubelet stores that output in /var/log/containers/*.log on the node, and an agent deployed as a DaemonSet (one pod per node) reads it, adds the Kubernetes labels and ships it to the central store. At TechCorp the store is Loki (same family as Grafana and Prometheus; it indexes only labels and stores the text compressed: cheap and sufficient for our volume) and the agent is Promtail or its successor Grafana Alloy.

Excerpt of the Promtail configuration (Helm values.yaml, installed by the Platform team in the observability namespace):

• clients.url: where it pushes the lines; Loki is just another Service in the cluster. pipelineStages: cri strips the runtime wrapper; json extracts level and service; labels promotes only those to labels; the rest (requestId, orderId) stays in the text and is filtered at query time.
• extraRelabelConfigs: turns the pod labels app and version (the same ones from the Deployment in 05-02) into Loki labels. That is why we query by {app="orders-service"}.

Why not promote requestId to a label? Because every distinct value creates a new stream and Loki degrades with millions of them: labels for what has few values (app, version, level, namespace), text for what has infinitely many (requestId, orderId). The same rule will come back with Prometheus in section 11.

Equivalent alternatives, so you recognize them when they show up:

LogQL has two parts: a label selector in braces and a pipeline of filters. The queries Luis's team uses every day:

1. |= means "contains the text": the creation, the event in the outbox, each step of the saga.
2. | json parses the line and lets you filter by exact field; the result is the lines from the gateway, Orders, Catalog and Customers in chronological order. This is why 03-01 insisted on propagating X-Request-Id: without it, this query does not exist.
3. =~ is a regular expression over the label; line_format reduces each line to what matters.
4. If it returns nothing and Orders shows "event published", the problem lies between the outbox relay and the inventory.orders queue (03-02).
5. LogQL aggregates too; useful for exploring, but for what is watched permanently a real metric is better, which is what comes next.

A metric is a number with a name and labels, sampled periodically (Prometheus scrapes every service every 15-30 s). Prometheus defines four types:

Two methods tell us what to measure without making it up:

• RED, for services (what the Orders team does): Rate (requests/s), Errors (proportion of failures), Duration (latency, with percentiles). With these three per service and per route you see 90% of the problems.
• USE, for resources (what the Platform team watches): Utilization (% of CPU, memory, disk), Saturation (waiting queue: messages in RabbitMQ, connections waiting in the pg pool), Errors (errors of the resource). Kubernetes already exposes CPU and memory per pod through cAdvisor and kube-state-metrics; we contribute the RabbitMQ and pool ones.

prom-client is the official Prometheus library for Node.js. Just as we did with the logger, the HTTP instrumentation lives once in @techcorp/common-http and every service gets it:

Explanation:

• A dedicated Registry per service, with service as a default label: every series carries service="orders-service" without repeating it.
• collectDefaultMetrics adds process_cpu_seconds_total, nodejs_heap_size_used_bytes, nodejs_eventloop_lag_seconds… for free. That last one is gold in Node: if it rises, the single thread is blocked (06-04).
• http_requests_total{method, route, code}: the RED counter. The route label uses the Express template (/v1/orders/:id), never the real URL, or we would create one series per order (section 11). If no route matched (404), we label it unknown.
• http_request_duration_seconds: histogram with buckets from 10 ms to 5 s. The 2 s bucket matches HTTP_TIMEOUT_MS=2000 (03-01): that way we see how many requests brush against the limit.
• startTimer() returns a function that, when called with the labels, observes the elapsed seconds; it is called on finish, once the response has been sent. metricsHandler serves the text in Prometheus format.

In the template's createApp (04-02) the order becomes: requestIdMiddleware() → accessLogMiddleware({logger}) → metrics.middleware → routes → errorMiddleware({logger}), plus a route app.get('/metrics', metrics.metricsHandler). Output of curl localhost:3002/metrics (trimmed):

Each _bucket{le="0.25"} counts the requests that took ≤ 0.25 s (cumulative): 1,240 out of 1,287. That is where the p95 in section 9 comes from.

RED metrics say the service responds; business metrics say the store sells. They are declared in the service itself against the same registry:

• orders_created_total is incremented in the use case after the transaction commits; orders_cancelled_total{reason} in the saga consumer when it processes order.cancelled (only three values of reason: controlled cardinality).
• saga_duration_seconds: when the order is closed, sagaDuration.observe((now - order.created_at) / 1000); the buckets go up to 900 s because a reservation expires after 15 minutes (02-05); in 06-05 it will be the basis of the SLI "confirmed in < 60 s". outbox_pending with collect() queries the table when Prometheus scrapes: it is the metric that gives away a dead relay (orders are created but their events never leave).

RabbitMQ is measured with its rabbitmq_prometheus plugin (port 15692), which the Helm chart from 05-02 enables with metrics.enabled: true. It exposes, among others, rabbitmq_queue_messages_ready{queue="inventory.orders"} (messages waiting for a consumer) and the same for orders.saga.dlq. A DLQ with messages is always an anomaly (03-02), and in 06-05 it will be an alert.

Prometheus discovers what to scrape through the Kubernetes API. With the operator (kube-prometheus-stack, installed by Platform) you declare one ServiceMonitor per service, next to the Service from 05-02:

Without the operator, the alternative is annotations on the Pod (prometheus.io/scrape: "true", prometheus.io/port: "3002", prometheus.io/path: "/metrics") that the classic kubernetes_sd_configs configuration interprets. The ServiceMonitor goes into each service's Kustomize base; new services inherit it from the template.

The PromQL queries that answer the RED questions (all runnable in Grafana → Explore):

1. rate computes the slope of the counter over the window; 5 m smooths the noise. A raw counter is never graphed.
2. The numerator filters by code regex, the denominator is the total; both aggregated by the same label so the division matches.
3. The rate of each bucket is aggregated (le must be preserved) and histogram_quantile interpolates the percentile. It can be aggregated across pods because buckets are summable; with a summary we could not.
4. Returns only the series whose value exceeds 100: empty if all is well. That is the shape of an alert condition, which 06-05 will turn into a PrometheusRule.
5. increase is rate × window: it gives units, not units/s.
6. A DLQ with messages is always an anomaly (03-02).

Grafana reads Prometheus and Loki as datasources. We agree on two dashboards, versioned as JSON in techcorp/platform/observability/dashboards/ and loaded by a ConfigMap with the label grafana_dashboard: "1" (the chart's sidecar imports them):

Dashboard "RED per service" with a $service variable (values from label_values(http_requests_total, service)) and four panels: requests/s, % of 5xx, p50/p95/p99, and CPU/memory of the pod (USE) for correlation. The essentials of one panel's JSON:

expr is the query from section 9 with the variable; legendFormat names each line by route; thresholds paints red above 300 ms, the target that will be formalized in 06-05.

Dashboard "Orders saga" (Luis's team): orders created/h, cancelled by reason (stacked bars), p95 of saga_duration_seconds, outbox_pending, messages ready in inventory.orders/payments.stock/orders.saga and their DLQs, and a status panel with a direct SQL query against PostgreSQL (SELECT status, count(*) FROM orders WHERE created_at > now() - interval '1 hour' GROUP BY status), which shows how many orders sit in each status (PENDING, STOCK_RESERVED, PAID, CONFIRMED, CANCELLED). A growing pile in STOCK_RESERVED is the signature of "Payments is not responding".

Correlation. Metrics and logs share service/app and version (Kubernetes labels) and time. The typical flow: the errors panel rises at 10:21 → click on the point → "Explore" with {app="orders-service", level="error"} over the same window → the line with requestId and err.code=DEPENDENCY_UNAVAILABLE appears → second query by that requestId across the whole namespace → you see that Catalog returned 503. Grafana lets you configure that jump (metric → logs) as a data link on the panel; the jump from logs to traces (trace_id) is added in 06-02.

Every distinct combination of labels is a series that Prometheus keeps in memory. http_requests_total with 6 methods × 15 routes × 8 codes × 20 pods is 14,400 series: fine. If someone adds orderId as a label, with 3,000 orders/day that is 3,000 new series every day per pod: within a month Prometheus runs out of memory. Rules:

• Labels with few known values (service, template route, code, reason, queue). Never identifiers (orderId, customerId, requestId, eventId), full URLs or bodies.
• Identifiers go into the log (text, not a Loki label) and into the trace (06-02). That split is the reason the three signals exist.
• Watch the cost: count({__name__=~".+"}) in Prometheus gives the total number of series; Loki volume is kept in check with retention (30 days at TechCorp), by not logging /health, and with LOG_LEVEL=info by default (debug in production multiplies volume by 10-50 and is only switched on briefly through a ConfigMap change).

• Concatenating into the message what should be a field (log.info('order ' + id + ' created')). Afterwards you cannot filter by orderId. The message is constant; the context goes in the object.
• Losing the requestId along the way. If a service generates its own instead of propagating the one it received, the cross-service LogQL query breaks right there. requestIdMiddleware() reuses the incoming one; the HTTP clients (04-04) forward it; events carry eventId and, in addition, the originating requestId in headers.
• Logging the probes and /metrics. Thousands of useless lines per day per pod.
• Real URLs as the route label. Cardinality explosion. Use the Express template and unknown for 404s.
• Tip: in development, LOG_LEVEL=debug and node src/server.js | npx pino-pretty to read logs in a human-friendly form without changing the production format.

The inventory.orders consumer receives order.created and reserves stock. Write the snippet that creates the child logger with the standard fields from section 2 and emits: an info on receipt, a warn if the reservation fails for lack of stock (with productId and requested/available), and an error if the database fails. Then write the LogQL query that shows only the stock shortages for product p-501 in the last hour.

Marta asks: "if the Orders outbox relay dies but the pod stays alive, which panel would show it and which query proves it?". Answer with the metric, the PromQL query and the LogQL query that would confirm the cause.

Exercise 1

(The "last hour" time range is chosen in Grafana; it is not needed in the query.)

Exercise 2

The metric is outbox_pending (gauge with collect()): it keeps growing because POST /v1/orders keeps inserting rows and nobody publishes them. Query: outbox_pending{service="orders-service"} > 100 (or its slope: deriv(outbox_pending[10m]) > 0). Complementary: rate(orders_created_total[5m]) > 0 while at the same time rabbitmq_queue_messages_ready{queue="inventory.orders"} == 0 for minutes. On the saga dashboard you would see the outbox_pending panel climbing and the status panel with all new orders in PENDING. Cause in Loki: {app="orders-service"} | json | message=~"relay.*" would show the last "batch published" too long ago, or an error from the RabbitMQ channel; if the relay died without logging, the absence of lines is the clue. In 06-05 this will become an alert.

We have given TechCorp its first two observability signals. Logs are structured JSON with pino, with common fields (service, version, level, requestId, orderId, eventId), redaction of sensitive data and one access line per request via pino-http; they go out through stdout, Promtail/Alloy labels them with app/version and Loki stores them, so that {namespace="techcorp"} | json | requestId="..." reconstructs a request across several services. Metrics live in @techcorp/common-http (http_requests_total, http_request_duration_seconds on GET /metrics) and in each service (orders_created_total, orders_cancelled_total{reason}, saga_duration_seconds, outbox_pending), Prometheus scrapes them through a ServiceMonitor and Grafana shows them on the RED and saga dashboards; the price to pay is cardinality discipline: identifiers in the logs, never in the labels. What we still cannot see is the path: we know POST /v1/orders takes 250 ms at the p95, but not how much of that time went to Catalog, to Customers or to PostgreSQL, nor how to join the HTTP request with the saga that continues through RabbitMQ. That is the third signal, distributed traces with OpenTelemetry, and it is the next lesson.