Investigating with Production Signals

In the previous lesson, production gave us an incident: a Customer intended to create one Order, the first request appeared unsuccessful, the Customer retried, and two Orders became visible. We deliberately did not jump to a fix. Now we investigate, and our goal is:

Reconstruct what happened using independent production signals before declaring a root cause.

This is where the observability work of Module 11 becomes operationally useful. We have several evidence sources: PostgreSQL state, the ECS structured logs with their requestId, orderId and customerId fields, payment attempts, HTTP and application metrics, health, and the runtime's own information. Each tells us something different, and no single signal automatically becomes the whole incident story.

The log lines, metrics and query results in this lesson are real output from release 1.6.0 running with its production configuration (LOGGING_STRUCTURED_FORMAT_CONSOLE=ecs, SPRING_APPLICATION_VERSION=1.6.0, Prometheus on management port 8081) against PostgreSQL 18.

Evidence Before Explanation

A weak investigation starts with "we think the retry created the duplicate, let's implement idempotency". A stronger one starts with four questions: what can we prove, what can we correlate, what are we inferring, and what remains unknown? That distinction prevents us from building a fix for the wrong failure mode. We work through the previous lesson's checklist, and each signal should narrow its questions.

Signal 1: PostgreSQL, the System of Record

We start with the durable system of record, because our transaction design established that committed database state is authoritative for whether an Order exists. The Customer's app may say "request failed"; PostgreSQL tells us whether an Order committed.

Support gave us the Customer, customer-742. Our Order history index from 6.10, idx_orders_customer_created_id on (customer_id, created_at DESC, id DESC), serves exactly this question, so the query is cheap even on a large orders table:

SELECT id, status, created_at
FROM orders
WHERE customer_id = 'customer-742'
ORDER BY created_at DESC, id DESC
LIMIT 20;

                  id                  | status |          created_at
--------------------------------------+--------+-------------------------------
 24b1a51f-82fa-4380-a151-fecc5c083046 | UNPAID | 2026-10-22 22:14:27.014091+00
 6a74b0a7-7d88-4d17-bebf-885d8d6b5868 | UNPAID | 2026-10-22 22:14:13.008425+00
(2 rows)

O1 is 6a74b0a7-… and O2 is 24b1a51f-…. Then we compare their OrderItems. OrderItem has the composite identity (order_id, product_id) and no independent ID, so we query by Order and join the Product names for readability:

SELECT i.order_id, p.name, i.quantity, i.unit_price_cents
FROM order_items i
JOIN products p ON p.id = i.product_id
WHERE i.order_id IN ('6a74b0a7-7d88-4d17-bebf-885d8d6b5868',
                     '24b1a51f-82fa-4380-a151-fecc5c083046')
ORDER BY p.name, i.order_id;

               order_id               |        name         | quantity | unit_price_cents
--------------------------------------+---------------------+----------+------------------
 24b1a51f-82fa-4380-a151-fecc5c083046 | Mechanical Keyboard |        2 |             8990
 6a74b0a7-7d88-4d17-bebf-885d8d6b5868 | Mechanical Keyboard |        2 |             8990
 24b1a51f-82fa-4380-a151-fecc5c083046 | USB-C Dock          |        1 |             6950
 6a74b0a7-7d88-4d17-bebf-885d8d6b5868 | USB-C Dock          |        1 |             6950
(4 rows)

The prices are the purchase-time prices OrderItem captured (4.06), so a later price change cannot distort this reconstruction. For the same reason, current Product state does not rewrite history: "the Product is inactive now" does not mean it was inactive when O1 was created.

Similarity Is Correlation, Not Identity

The two Orders share the Customer, the Products, the quantities and the prices. That is strong evidence that they are related; it does not prove that they are duplicates, because a Customer may intentionally place the same purchase twice. Same content is correlation evidence, not an operation identity.

The timestamps are 14 seconds apart, and the retry hypothesis becomes stronger. But 14 seconds does not prove retry semantics either: time proximity is useful evidence, never a safe deduplication rule.

One property of created_at matters for the timeline. CreateOrderUseCase sets it with Instant.now(clock) when it builds the Order, before it consumes Inventory and before the commit. So created_at tells us when the workflow started building the Order, not when the Order became durable. We come back to that gap with the logs.

Both Orders Committed

Both Orders are queryable after the incident, so both transactions reached durable committed state. That immediately rules out one hypothesis: "the first Order rolled back and the UI accidentally showed it". Application logs need no "COMMIT succeeded" line for every transaction: a row that persists after the incident proves its transaction committed.

Inventory Without a Ledger

Successful Order creation decreases Inventory, so we inspect the consequences. Our schema stores the current available_quantity, not an Inventory movement ledger, so we cannot read the history directly and must not pretend the schema contains an audit trail. What we can do is relate the current stock to the Orders that consumed it:

SELECT p.name, sum(i.quantity) AS ordered, inv.available_quantity
FROM order_items i
JOIN orders o ON o.id = i.order_id
JOIN products p ON p.id = i.product_id
JOIN inventory inv ON inv.product_id = i.product_id
WHERE o.status <> 'CANCELLED'
  AND i.product_id IN ('9ed4c9a9-8761-4e4f-9f50-aef83f14c13d',
                       'e7065e8f-d5fc-4bf3-85c3-c42cf5ed4457')
GROUP BY p.name, inv.available_quantity
ORDER BY p.name;

        name         | ordered | available_quantity
---------------------+---------+--------------------
 Mechanical Keyboard |       4 |                 16
 USB-C Dock          |       2 |                  8
(2 rows)

Only O1 and O2 contain these Products, so 4 keyboards and 2 docks were consumed. The administrator's last Inventory change had set 20 and 10, and 16 and 8 remain: the state is consistent with two committed Create Order workflows, each consuming 2 and 1. This is not duplicated presentation. Note what we combined: Order state, current Inventory and an operational fact about the last stock change. The schema alone could not have told us.

Payment State

Create Order and payment are separate workflows, but production impact can cross them, so we check whether either Order entered payment:

SELECT order_id, status, created_at
FROM payment_attempts
WHERE order_id IN ('6a74b0a7-7d88-4d17-bebf-885d8d6b5868',
                   '24b1a51f-82fa-4380-a151-fecc5c083046');

 order_id | status | created_at
----------+--------+------------
(0 rows)

No payment attempt exists for either Order, and both are UNPAID, so no Customer money is involved yet and both Orders are still cancellable; had both been paid, the Customer may have been charged twice. The payment.attempts counter cannot answer this question: it counts provider outcomes for all Orders together, by design without an orderId tag.

Which Order Is the "Duplicate"?

It is tempting to say "the second Order is the duplicate". Imagine instead that O1 committed, the Customer never saw it, O2 succeeded visibly and the Customer then paid O2. Chronologically O2 is later, yet the unwanted business record would be O1. "Duplicate" is a business interpretation, not "the later row".

Identity needs no such interpretation: Create Order takes the Customer from the token's subject (8.02), so both Orders were created under the same authenticated Customer, stored as orders.customer_id.

Signal 2: Structured Logs

Now we search the centralized logs. Because 11.01 made the event name a field, the query is precise: event.action is order_created and customerId is customer-742. The platform returns two events, shown here with the fields we need:

{"@timestamp":"2026-10-22T22:14:24.492828Z","process":{"pid":31794},"service":{"version":"1.6.0"},"message":"Order created","requestId":"8c02300b-67d2-41d2-b94e-ec3b243db224","event":{"action":"order_created"},"orderId":"6a74b0a7-7d88-4d17-bebf-885d8d6b5868","customerId":"customer-742","itemCount":2,"totalCents":24930}
{"@timestamp":"2026-10-22T22:14:27.015883Z","process":{"pid":31794},"service":{"version":"1.6.0"},"message":"Order created","requestId":"a52345be-1635-4d3e-b593-c860277f1e9f","event":{"action":"order_created"},"orderId":"24b1a51f-82fa-4380-a151-fecc5c083046","customerId":"customer-742","itemCount":2,"totalCents":24930}

This is powerful. O1 was created by request R1 (8c02300b-…) and O2 by request R2 (a52345be-…). The requestId came from 11.02's filter through the MDC, without any application code passing it. So the two Orders did not arise from one accidental duplicate persistence inside a single request; they came from two request executions.

Request IDs Clarify Execution Boundaries

A request ID groups one execution (11.02); it cannot say that two executions were one Customer intention. Still, knowing that R1 and R2 are different executions lets us investigate each one separately.

Searching for R1's requestId returns exactly one event: the order_created above. There is no error, no warning and no stack trace for R1, and no ERROR event at all in the incident window. There is also no "request received" event, because 11.01 deliberately does not log ordinary request traffic. The logs tell us that R1 created O1 and that nothing failed inside the application; they do not tell us when R1 arrived or how it ended. R2's search looks the same.

There is one more asymmetry. The Customer can give support the X-Request-Id of R2, which returned a response with the header. For R1 the app received nothing at all, so the request ID of the request that "failed" can only be found from the server side, by searching for the Order or the Customer.

Structured Fields Beat Message Searching

Because our events carry stable fields (11.01), we can move between dimensions, each query answering a different question:

A free-text search for "Order created" answers none of these reliably. A search by Customer still needs care: legitimate activity must not be labeled incident-related automatically.

Logs Are Not the Source of Truth

Had R1's order_created event been missing, that would not prove O1 never committed: O1 is in PostgreSQL, so a missing log could mean an instrumentation gap, a delivery problem or a process interruption. Logs explain execution; they do not redefine committed state. Log timing needs interpretation too: 11.01 logs order_created inside the transaction, just before the commit, so a success log is slightly weaker evidence of durable success than the committed row. Here both agree.

Now compare R1's two timestamps. O1's created_at is 22:14:13.008, but its order_created event was written at 22:14:24.493. Between building the Order and saving it, R1 spent about 11.5 seconds inside CreateOrderUseCase, where the only remaining steps are consuming Inventory and persisting. R2 needed 2 milliseconds for the same steps. Something made R1 unusually slow, and slowness is exactly what makes a client give up.

Signal 3: HTTP Metrics

Metrics answer aggregate questions for the incident window: did POST /api/v1/orders latency increase, did 5xx responses appear, did volume spike, was there a general application problem? The Prometheus endpoint on port 8081 shows the series for Create Order:

http_server_requests_seconds_count{error="none",exception="none",method="POST",outcome="SUCCESS",status="201",uri="/api/v1/orders",version="1.6.0"} 5
http_server_requests_seconds_sum{error="none",exception="none",method="POST",outcome="SUCCESS",status="201",uri="/api/v1/orders",version="1.6.0"} 11.692175791
http_server_requests_seconds_max{error="none",exception="none",method="POST",outcome="SUCCESS",status="201",uri="/api/v1/orders",version="1.6.0"} 11.523266333
order_creations_total{outcome="success",version="1.6.0"} 5.0

Five Create Order requests ended with 201, including other Customers', and there is no SERVER_ERROR series. The maximum is 11.52 seconds, while the five requests together took 11.69: one request took almost all of the time, and it matches R1's 11.5 seconds inside the use case. http_server_requests_seconds_max is a recent maximum that Micrometer rotates after a few minutes, so Prometheus's stored history of it, not one scrape days later, is what an investigation reads. The version="1.6.0" tag (12.05) tells us which release served these requests.

The most important finding is the status: the server recorded R1 as 201 SUCCESS. order.creations agrees, with success counted only after the commit (11.04). The Customer's app, however, reported an error. If the client gave up before 11.5 seconds, the server finished the work and wrote a response nobody read; the next lesson tests that hypothesis on purpose.

Metrics cannot tell us whose request was slow, because identifiers are deliberately not metric tags (11.04): metrics answer "is there a pattern?", logs answer "what happened to O1?".

Had the metrics shown a 500 around R1 while O1 exists, we must not have concluded "Order creation failed": it would mean a failure after the commit, such as in response serialization, a valuable branch of its own. A 201 points the investigation at the delivery of the response instead.

Signal 4: Health

Readiness on the management port includes readinessState and the database (11.03), so readiness history around the incident answers: was the application ready, was PostgreSQL healthy, did readiness drop, did the process restart? The platform's probe records show readiness UP throughout the incident window, the same answer a probe gets now:

curl -s -w ' %{http_code}\n' http://localhost:8081/actuator/health/readiness

{"status":"UP"} 200

That makes a broad PostgreSQL outage unlikely as the trigger, though not a transient issue such as one slow row lock. Health has a limited scope by design: it says whether the instance can serve traffic, not whether R1 was idempotent, and a healthy application can have a business correctness bug.

Signal 5: Runtime and Deployment

Next we check what happened to the application instance around R1: a container restart, a deployment rollout, a process termination, an instance replacement. One possible timeline is "the Order commits, the process terminates, the response never reaches the client". If the runtime showed a restart right after O1's commit, that would be strong contributing evidence.

The logs already answer part of this. Both events carry process.pid 31794 and service.version 1.6.0: the same process of the same release handled R1 and R2, with no restart and no rollout between them, which rules out the deployment-change hypotheses. The artifact traceability we built in Module 12 has become evidence. Even a confirmed restart would only have explained the lost response, not why the retry created another Order; 13.03 separates the two.

A Working Timeline

Combining the evidence, we can draft a provisional timeline in which every line names its source:

This helps reviewers tell fact from inference. Why R1 was slow, and exactly when the Customer's app gave up, are still open.

Triangulation

Triangulation means combining independent signals, as the timeline just did: PostgreSQL, the application log, the metrics and the Customer's report each confirm a different part, and together they tell a much stronger story than any single source.

The same discipline applies to tooling. A dashboard is a view over telemetry, with sampling, aggregation, query mistakes and delayed data, never "truth" by itself. And "enable DEBUG everywhere" or Hibernate SQL logging in production creates volume, overhead and sensitive-data exposure; use targeted diagnostics, such as one package's level through the environment (11.01), if the structured signals are not enough.

Was R2 Really a Retry?

The evidence supporting it: the same Customer, the same item composition, 14 seconds apart, the support report, and possibly client logs or frontend telemetry if they exist. But our backend alone cannot know logical client intent, because that is exactly the missing operation identity. We can reach a high-confidence conclusion without proving intent, and the incident review should say so honestly.

Correlation is not causation either: R2 could have been a manual second tap, a frontend retry or a refresh and resubmit. For the backend fix, the exact mechanism may not matter; the same logical operation must be repeatable safely.

Looking for Other Affected Customers

One Customer establishes the possibility; impact analysis asks whether it happened elsewhere. Incident urgency does not justify a full-table cross join against production. We use indexes, a bounded time window, read-only queries and the database team's operational practices, so the investigation itself does not become an outage. This query looks for pairs of Orders by the same Customer with identical lines within five minutes, inside a two-hour window:

WITH order_contents AS (
    SELECT o.id, o.customer_id, o.created_at,
           string_agg(i.product_id || ' x' || i.quantity, ', '
                      ORDER BY i.product_id) AS items
    FROM orders o
    JOIN order_items i ON i.order_id = o.id
    WHERE o.created_at >= TIMESTAMPTZ '2026-10-22 21:00:00+00'
      AND o.created_at <  TIMESTAMPTZ '2026-10-22 23:00:00+00'
    GROUP BY o.id
)
SELECT a.customer_id, a.id AS earlier_order, b.id AS later_order,
       b.created_at - a.created_at AS gap
FROM order_contents a
JOIN order_contents b
  ON b.customer_id = a.customer_id
 AND b.items = a.items
 AND b.created_at > a.created_at
 AND b.created_at - a.created_at < INTERVAL '5 minutes'
ORDER BY a.created_at;

 customer_id  |            earlier_order             |             later_order              |       gap
--------------+--------------------------------------+--------------------------------------+-----------------
 customer-305 | b7bdcd82-10be-4cfe-8bb0-14b0543936a2 | 0ecd76a2-abfb-4eb2-9296-48194f5c8a7b | 00:00:59.637302
 customer-742 | 6a74b0a7-7d88-4d17-bebf-885d8d6b5868 | 24b1a51f-82fa-4380-a151-fecc5c083046 | 00:00:14.005666
(2 rows)

The result is a candidate list, not a confirmed duplicate list. customer-305 bought two Wireless Mice twice, a minute apart. That may be another incident or two deliberate purchases, and nothing in our data can tell: neither request failed on the server, both were fast, and no complaint exists. Each candidate needs additional evidence, such as the logs of its requests, support contact or client telemetry.

An Observability Gap or a Model Gap?

We now realize something important: from backend data alone, we cannot reliably tell whether R1 and R2 represented the same logical operation. Metrics show five successful Order creations; they cannot know that two of them were one intended purchase, because that logical operation identity does not exist yet. Observability cannot infer a concept the application never modeled.

So we must classify the gap correctly. An observability gap would be "the request ID existed but was not emitted in logs"; more or better logging fixes it. A business model or API gap is "Create Order has no idempotency or operation key"; more logging does not solve it. Better logs help us detect and investigate duplicate Orders, but they do not stop them. Corrective work must address the operation's semantics.

The same reasoning stops a tempting idea: a "duplicate Order metric". How would the application know two Orders are duplicates without first defining "same logical operation"? A metric based on "same Customer, same items, 30 seconds" would count customer-305 as an incident, a false positive. Correct modeling must come before reliable telemetry.

Updating the Incident Document

A practical investigation record gives everyone a common factual baseline. It must also be reproducible: another engineer should be able to follow the queries, log filters, request IDs, Order IDs, time window and application version, instead of "I looked at the dashboard and it seemed weird". Our incident document now reads:

## Status
Investigating

## Evidence (reproducible)
- Time window: 2026-10-22 22:10–22:20 UTC, release 1.6.0, process 31794.
- Orders: O1 6a74b0a7-… (created_at 22:14:13.008), O2 24b1a51f-… (22:14:27.014).
- Requests: R1 8c02300b-… created O1; R2 a52345be-… created O2.
- Log filter: event.action:order_created AND customerId:customer-742.
- Queries: Order history, OrderItems, Inventory, payment_attempts, candidates.

## Confirmed
- Two distinct Orders committed, same Customer, equivalent items and prices.
- Each Order was created by a different HTTP request.
- Inventory is consistent with two consumptions (20/10 → 16/8).
- No payment attempts; both Orders UNPAID.
- R1 took about 11.5 s on the server and was recorded as 201; no ERROR events;
  readiness UP; no restart or rollout between R1 and R2.

## Reported
- The Customer did not observe success for the first request and retried.

## Under Investigation
- Why R1 was slow, and why its response did not reach the Customer.
- Other candidates (customer-305: two identical Orders 60 s apart).

## Emerging System Gap
Create Order has no stable logical-operation identifier shared across retries.

Logs have limited retention, so the document keeps such references. It holds no tokens, Authorization headers, credentials, raw personal data or huge log dumps: our observability safety rules apply to internal documents too.

Impact stays measurable: how many Customers, candidates, PAID Orders and units of Inventory, since when, and is it still ongoing?

When Do We Have Enough Evidence?

We do not need perfect knowledge of every packet. We need enough to explain which durable effects occurred, which executions caused them, why the second was allowed and what assumption was missing. Why R1's response did not reach the Customer (a client timeout, a proxy timeout, a broken connection) may stay partly unknown, and we can still fix the repeat-execution weakness.

But preserve the unknown. The incident review should say: "The exact mechanism that prevented the Customer from observing R1's success has not been conclusively determined." That is stronger engineering than invented certainty.

What We Have Narrowed Down

The evidence confirms two committed Orders from two separate executions of the same Customer with equivalent content; the server recorded R1 as a success, and nothing shows corruption or duplicate persistence inside one transaction. That rules out several explanations: JPA inserting the same Order twice, the database duplicating one INSERT, one transaction persisting two Orders, an OrderId collision and an Inventory rollback failure. Two distinct request IDs, two distinct OrderIds and two independently valid committed workflows fit the evidence far better.

The central question becomes:

Why did the application treat R2 as a completely new Order creation when the Customer considered it a retry of R1?

The answer is beginning to emerge: the server had no durable identity for the logical Create Order operation across HTTP retries.

Practice Exercise 1: Find a Lost Response From the Server Side

Solutions: lesson 13.11.

Keep the module 12 project and the Orders from 13.01's Exercise 2, but restart the application with ECS logs: LOGGING_STRUCTURED_FORMAT_CONSOLE=ecs ./gradlew bootRun --args='--spring.profiles.active=local'. Let Ben order one stand and two mice, then let Ana order one mouse with curl -s -o /dev/null ..., so her client never sees the response. Without that response, find Ana's newest Order in PostgreSQL, the request that created it in the log, and its trace in http_server_requests_seconds_count on port 8081. Then run the lesson's candidate query with o.created_at >= now() - INTERVAL '1 hour' as its window, and predict first whether Ben's Order shows up.

Practice Exercise 2: Which Signal Answers It?

For each question, name the signal that answers it, or say that none of ours can:

1. Did O2 commit?
2. Which request created O2?
3. Were Create Order requests slower than usual that evening?
4. Did the instance restart between R1 and R2?
5. Did the Customer mean R2 as a retry of R1?

Knowledge Check

Question 1

Why is O1's created_at not the moment O1 became durable, and what did that gap reveal?

Question 2

O1's row exists, but its order_created event is missing. What do you conclude?

Question 3

Why can the metrics show that one Create Order took 11.5 seconds but not whose it was?

Question 4

Why would more logging not prevent the next duplicate Order?

Knowledge Check Answers

Answer 1

CreateOrderUseCase sets it when it builds the Order, before consuming Inventory and committing. Comparing it with the order_created timestamp showed that R1 spent 11.5 seconds inside the use case.

Answer 2

That O1 committed: the row is the source of truth. The missing event points at a logging or delivery gap, not at a rolled-back Order.

Answer 3

Identifiers are deliberately not metric tags, to keep cardinality bounded. Metrics show the pattern; the logs, searched by orderId or requestId, show the individual request.

Answer 4

The gap is in the model, not in the telemetry: nothing in the request says that two executions are one logical operation, so no log line can record it or stop the second Order.

Engineering Principle

Use multiple production signals to reconstruct behavior. PostgreSQL tells you what committed, logs tell you what executed, request IDs group one execution, metrics reveal patterns, and health and runtime signals provide environmental context.

Summary

• PostgreSQL is authoritative: both Orders committed, with the same Customer, items and purchase-time prices, 14 seconds apart. Similarity and timing are correlation, not operation identity, and created_at marks when the Order was built, not when it committed.
• Current Inventory (16/8, not a ledger) and payment_attempts (none) show two consumptions and no payment yet; which Order is the "duplicate" is a business decision, not chronology.
• The ECS order_created events map O1 to request R1 and O2 to R2: two executions. R1 has no error event, and its created_at and log timestamp are 11.5 seconds apart.
• http.server.requests recorded R1 as 201 SUCCESS with an 11.52-second maximum, order.creations counted both, readiness stayed UP, and the same 1.6.0 process handled both requests: the server succeeded twice while the client saw a failure.
• Bounded, indexed queries find candidate duplicates (including a legitimate-looking customer-305 pair); candidates are not confirmed duplicates.
• Observability cannot infer a logical operation the application never modeled; this is an API and model gap, and more logging would not prevent duplicate Orders.
• The incident record is reproducible and safe, keeps unknowns explicit, and points away from transaction corruption toward repeated execution of a non-idempotent Create Order.

In the next lesson, Reconstructing the Failure Timeline and Finding the Root Cause, we turn two committed Orders, two request executions and one reported logical operation into a precise failure model: we reproduce the slow first request and the client giving up, and we separate trigger, root cause, contributing factors, detection gap and impact before designing the idempotency fix.