Skip to main content

Read the trace

Your first journey passed. The trace holds what it actually did: what the run composed, what setup provisioned, what the test called, what each check read, and what teardown released.

Level 1, lesson 3About 10 minutes
By the end
  • Walk a test trace layer by layer: run, setup, execution, teardown.
  • Find the same layers in a trace your own test wrote.
  • Read a failure message that names the property and both values.
Before you start
  • Write your first test (lesson 2). Keep MyFirstJourney.cs if you want your own trace to compare, and for the Level 6 exercises that reuse it.
  • Nothing installed if you read the archive; running needs the sample from lesson 1.

The scenario​

A passing test is the easy case. The hard case is the same test failing at 3 a.m., where the only witness is the trace. This lesson reads one test slowly, then finds the same shape in the trace your own test wrote.

The walk below reads the clock journey from Level 0, because it holds one of each layer. Your first journey has the same shape with fewer entries.

One test, layer by layer​

One test, layer by layerFailureDrills.TheTestClockClosesTheDueWindow
  1. Runbefore the first test

    What the run composed, and where the application ran. This is what the viewer shows on the run screen.

    Recorded operations (4)
    • REST, GraphQL, ASP.NET Core, SQL, Data, Sheets, Playwrightcapability · the capabilities the composition declared
    • ProtoTest.SampleApp.Programserver · in-process, lifetime PerRun
    • Northstar web on a loopback listenerapplication · readiness /health, 1 attempt, waited 84 ms
    • .NET 8.0.31 on Windows 10.0.26200, X64environment
  2. Setup508.4 ms

    Everything before the test body: hooks, attributes, clients, the database connection and the state the test asked for.

    Recorded operations (5)
    • Setuptest.setup · 508.4 ms
    • Rest, GraphQL, and the web clientclient.initialize · each client initializes once, with its address recorded
    • Open SqliteConnectionsql.connection.open · 0.05 ms
    • Application, NorthstarTenantattribute.before · the tenant attribute provisions a TenantResponse in 151.7 ms
    • SignedInAs, NorthstarMemberattribute.before · the sign-in is recorded as state, not as a log line
  3. Execution286.8 ms

    The test body. New entries nest under test.execution; the clock move is an event on it.

    Recorded operations (10)
    • Test executiontest.execution · 286.8 ms, succeeded
    • Create · IssueInvoiceRequestdata.create · 165.8 ms
    • Provision · IssueInvoiceRequest to InvoiceResponsedata.provision · 164.5 ms
    • Clock advanced by 8:0:00:00clock.advance · event on test.execution, from the test side
    • invoice.issueNorthstar.Domain · reported by the application itself
    • REST · GET /api/v1/organizationhttp.request · 65.3 ms
    • Assert status · 200 OKassert.http.status · the check that decided the request
    • Assert response shapeassert.json.shape · 7.5 ms, the property the test depended on
    • REST · POST /api/v1/invoices/{invoiceId}/payhttp.request · 35.0 ms
    • Assert response shapeassert.json.shape · the paid status
  4. Teardown40.6 ms

    What the test leaves behind, and what the run releases for it. The trace records the releases, so a leaked resource would show here.

    Recorded operations (4)
    • Teardowntest.teardown · 40.6 ms
    • 5 REST artifacts and the scenario summaryattachment.publish · request, response and expected shape for each call
    • Cleanup · TenantResponsedata.cleanup · 8.9 ms, the provisioned tenant is removed
    • Application services, database connection, messaging consumerresource.release · released in order, each with its own release time

What this trace cannot see

Test sideObservedApplication

The run recorded values from the test side and from the application itself. Nothing was recorded as observed in a response, so the trace does not claim to have seen a value the test did not read. These are the edges of that picture.

  • Work outside the composition

    The environment drill used a raw HttpClient against a fixed address. Its test.execution span ran 2.05 s and recorded no operation at all; the entry holds the connection failure, and the call it never wrapped cannot appear in the trace.

  • Work inside the application

    invoice.issue and invoice.pay are there because the demo application reports that activity source. A step the application does not report has no span, however much it did.

  • Wall time

    The clock item records the delta and the moment the clock stands at. It cannot tell you how long anything would have taken on the real clock.

Read from the test that moves the clock instead of waiting in docs/static/lessons/l0-time-fix.prototrace. The viewer draws the same trace from that archive (download it and drop it on the viewer).

The same layers in your own trace​

Your first journey leaves a smaller trace with the same four layers. From l1-first-journey.prototrace:

  • Run: the capabilities the composition declared, the in-process application, and the loopback instance the browser journey follows.
  • Setup: each client initializes once (Initialize · Rest:Northstar, GraphQL:Northstar, and the rest), the SQL connection opens, NorthstarTenant provisions the tenant with data.create · ProvisionTenantRequest, and SignedInAs sets the member identity.
  • Execution: POST /api/v1/projects leaves the request, the response and the expected shape as artifacts; the auth handlers apply; the application reports its own project.create; and the two checks record what they read.
  • Teardown: four attachments publish, data.cleanup · TenantResponse removes the tenant, and each owned resource releases in order.

When your test passes, that list is the proof of what it did. When it fails, the same list tells you which step to read first.

When a check fails​

The checks are the part to read first, because each one records what it compared. A status check names the status it expected and the one it received. A shape check names the JSON path and both values:

[$.status]: Values did not match. (Expected: "past_due", Actual: "active")

That is the clock drill from Level 0. The message says which property, what the test expected and what the application sent. Read the call the check judged and its inputs. The fix is one value or one clock move.

The two places that hold those values are the runner output and the trace. The trace records the failed assert.json.shape entry and, beside it, the expected shape as an artifact, so the shape the test asked for is in the file too. The reports are the run's verdict: report.html marks the test failed and report.json carries the coverage and traffic rows. Neither one carries the expected and actual values, so a report is the place to confirm that a test failed, not the place to find out why.

Checkpoint​

Change the shape assertion to expect a different name, for example name = "someone-else". Before you run it, predict what the failure message will name.

Verify
Run the filtered test and read the failure message the runner prints, then open the trace and find the same failed check inside it. Restore the assertion and run again.

What you learned​

  • A trace answers what ran, where it ran, and what each check read.
  • Setup and teardown are part of the story, not noise around it.
  • A failing shape check names the property and both values, so the fix is visible in the message.

Keep exploring​