Skip to main content

Read a failing trace

A failed run ends with a check you can read. The four drills in the sample fail on purpose, each next to the test that runs the same journey the right way, so the difference is one practice and the trace shows it.

Level 4, lesson 1About 10 minutes
By the end
  • Read the check that failed and the call it judged.
  • Name the fix from the failure message and the paired test.
  • Tell a failure the trace explains from work the trace cannot see.
Before you start
  • Level 3 (parallel safety).
  • Nothing installed. The archives are on this site.

The scenario​

The suite in CI reports one failing check. You cannot attach a debugger to that runner, and the log holds a single line. What is left of the run is the trace, and the trace records both halves of the comparison that failed.

The four pairs below are the same failures the [Level 0 tour](/learn/why-integration-tests-get-hard/the-trace-as-the-feedback-loop) showed, this time read the way you would read a failure of your own. Set ProtoTest__Sample__Drills=true and both halves run and leave their traces.

The same journey, two runs​

Every pair runs one journey twice: the drill fails on purpose, the test beside it holds. The panes carry the records from a recording of the sample with the drills enabled, and each one links the archive a reader can download.

Who moves the clock?

The drillfailed
ARealWaitDoesNotCloseTheDueWindow1.25 s
Recorded operations (3)
  • data.createCreate · IssueInvoiceRequestsucceeded152.2 ms, provisioned in the test tenant
  • http.requestREST · GET /api/v1/organizationsucceeded74.0 ms, HTTP 200
  • assert.json.shapeAssert response shapefailedShape mismatch failed with 1 error(s): • [$.status]: Values did not match. (Expected: "past_due", Actual: "active")
Download this run's archive
The test that holdssucceeded
TheTestClockClosesTheDueWindow286.8 ms
Recorded operations (6)
  • clock.advanceClock advanced by 8:0:00:00succeededrecorded on test.execution, from the test side
  • data.createCreate · IssueInvoiceRequestsucceeded165.8 ms, provisioned in the test tenant
  • http.requestREST · GET /api/v1/organizationsucceeded65.3 ms, HTTP 200
  • assert.json.shapeAssert response shapesucceededthe same property, now past_due
  • http.requestREST · POST /api/v1/invoices/{invoiceId}/paysucceeded35.0 ms, HTTP 200
  • assert.json.shapeAssert response shapesucceededstatus paid
Download this run's archive

What changesMove the test clock instead of waiting on real time.

Every name, duration and message is from a recording of samples/Northstar.ProtoTest with the drills enabled. The drill failed on purpose; the test beside it runs the same journey and passes. Each pane links that test's own archive.

Read a failed check in four questions​

  1. Which check failed? The failed entry names the assertion, such as Assert response shape or Assert status · 201 Created.
  2. What did it expect, and what did it read? The message carries both, and a shape check carries the JSON path: [$.status]: Values did not match. (Expected: "past_due", Actual: "active").
  3. Which call did it judge? The request sits one entry up, with its status, its duration and its attachments.
  4. What differs in the paired test? The fix changes one habit: the clock, the data, the address or the assertion.

One pair, worked through​

The time pair is the clearest:

The drillThe test that holds
Before the readan invoice is provisionedan invoice is provisioned, then the clock moves eight days
The callREST GET /api/v1/organization, 74.0 ms, HTTP 200the same call, 65.3 ms, HTTP 200
The checkshape failed: $.status expected past_due, read activeshape succeeded, then the invoice is paid

The call succeeded in both runs. The application answered quickly, with a subscription that was still active, because nothing had moved the clock the application reads. The drill waited a real second, and that changed nothing. The fix advanced the test clock, and the same shape check passed. One failure, four answers, and the pair writes the fix down.

When the trace is silent​

The environment pair is the other direction. Its execution layer holds a single test.execution entry of 2.05 s and no request at all. The entry records the failure, a connection error, and nothing about the call: the raw client ran outside the composition, so the run never wrapped it. That missing operation is the diagnosis. The fix takes the address from the composition, and the same call turns into an ordinary request entry.

Checkpoint​

The visibility drill failed on "Expected HTTP status 201 (Created), but received 400 (BadRequest)". Its trace still holds the response body. What did the drill fail to do, and what does the fix do instead?

Verify
Read the Visibility pair in the diff above, download l0-visibility-drill.prototrace and l0-visibility-fix.prototrace, and open both in the viewer.

What you learned​

  • A failed check names what it expected and what it read, and the call it judged sits one entry up.
  • The drill and the fix run the same journey, so the pair names the fix.
  • Silence in the execution layer is evidence too: it says the work ran outside the run.

Keep exploring​