The trace as a feedback loop

The loop is short. Run it. Open the trace. Read the check that failed. Change one thing. Run again.

Level 0, lesson 4About 8 minutes

By the end

• Read a failure from its trace without rerunning it.
• Name which of the four questions the failure left open.
• Describe the loop: run, read, change one thing, run again.

Before you start

• What a test leaves behind (lesson 3).
• Nothing installed. The archives are on this site.

The scenario

A test failed in CI and the log shows one line of output. You cannot attach a debugger to the runner, and rerunning the job tells you the same thing. The trace is what is left of the run: what it wrapped, what it recorded, and what the check read.

The four drills in this level end in exactly that kind of check. Reading one is the skill this level has been building towards.

The loop

1. Run the suite.
2. Open the trace at the test that failed.
3. Read the failing check: what it expected, what it read, and which call it judged.
4. Change one thing in the test or the composition.
5. Run again and compare the two traces.

The change is small on purpose. If you change three things and the test passes, the next failure is harder to read.

Worked example: visibility

The drill sent an empty project name and asserted the status:

using var response = await Proto.Context.Rest()
    .Body(new CreateProjectRequest(""))
    .PostAsync("/api/v1/projects");

response.Should.HaveHttpStatus(HttpStatusCode.Created);

The check failed with Expected HTTP status 201 (Created), but received 400 (BadRequest). The response body named validation_failed and the empty parameter, and the test never looked at it. The trace holds the body as an attachment, so the reader can see the answer in the failed run itself.

The fix asserts what the application said, and the same failure would now name the code:

response
    .Should.HaveHttpStatus(HttpStatusCode.BadRequest)
    .Should.MatchShape(new
    {
        code = ProblemCodes.ValidationFailed,
        message = JsonValue.StringContaining("name")
    });

Two checks, both recorded, both readable from the trace.

Worked example: environment

The environment drill is the other direction: the trace names the failure and stops there. The test execution span ran about two seconds, failed with a connection error and recorded no request at all. The call happened outside the run, so nothing wrapped it; the missing operation is the diagnosis. The fix is to call through Proto.Context.Rest() like every other journey.

Compare the two runs

The last step of the loop is the comparison, and this is what it looks like. Each pair below is one journey run twice: the drill on the left failed on purpose, and the test beside it holds. Every name, duration and message is the recording's own, and each pane links that test's own archive.

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.

Open the Environment pair for the case above: the left pane holds one entry and a message, the right pane holds an ordinary request.

The four failures as one sentence each

• Time: a real wait does not move the test clock. The fix advances the clock.
• State: the id belonged to no test in the run. The fix creates and reads its own data.
• Environment: the address was hardcoded. The fix takes it from the composition.
• Visibility: the test read the status and ignored the body. The fix asserts the body.

When a failure looks random, walk the four questions in order. A trace usually answers three of them, and the one it stays silent on is the one to fix.

Checkpoint

The environment drill failed with a connection error and its trace holds no request. The visibility drill failed on the status alone, and its trace holds the response body as an attachment. Both fixes call the composed client. What did each drill fail to answer?

Verify

Compare l0-environment-drill.prototrace and l0-visibility-drill.prototrace in the viewer, then read the two fixes.

What you learned

• The trace turns a failed run into a list of facts you can act on.
• The four questions say where to look; the trace stays silent on the answer that is missing.
• One change per run keeps the next trace readable.

Keep exploring