VereskLearn

Module 9 · Running it for real

Lesson 9.2

Tracing and logs

A trace records each step of one request, with its start time, duration, and outcome.

Lesson 55 of 622 min read

The problem

Why it matters

Without it

A failed request leaves no record of its steps. Nobody can tell whether retrieval, generation, or citing failed.

With it

Each request writes one span per step. A failed step is visible by name, with its time.

How it works

  • A span records one step

    A span holds a request id, a step name, a start time, a duration, and an ok flag. The generate span in the sample starts at 40 milliseconds and lasts 900 milliseconds. Its ok flag is false, so it failed.

    FieldValue
    requestIdreq-0042
    stepgenerate
    startMs40
    durationMs900
    okfalse
    The fields of the generate span.

  • The clock adds up the durations

    The clock starts at zero and moves forward by each duration. A step starts where the previous step ended. The retrieve step takes 40 milliseconds, so generate starts at 40, and cite starts at 940.

    How long each step of the sample request took.

  • Each span is one JSON line

    JSON.stringify turns a span into one line of text. A log file holds one line per span. A reader can then search the lines by requestId or by step name.

    const span = {  requestId: "req-0042",  step: "generate",  startMs: 40,  durationMs: 900,  ok: false,};console.log(JSON.stringify(span));

    Output

    {"requestId":"req-0042","step":"generate","startMs":40,"durationMs":900,"ok":false}

  • The ok flag finds the failure

    Filtering the lines on ok set to false finds the failed step. The sample log has two lines, and only the generate line is marked as failed. Its duration then shows whether the failure was also slow.

    const lines = [  '{"step":"retrieve","ok":true}',  '{"step":"generate","ok":false}',];for (const line of lines) {  const span = JSON.parse(line);  if (!span.ok) console.log("Failed step: " + span.step);}

    Output

    Failed step: generate

Full code

Read the program

See the full code

Common mistakes

What goes wrong

  • Logging without a request id. Lines from many requests then mix together.
  • Logging only failures. Without normal timings, a failure has nothing to compare with.
  • Writing full user text into the log. Logs are read by many people, so keep them small.

Use it when and skip it when

Is it the right tool?

Use it when

  • A request passes through several steps, and any one of them may fail.
  • You need to find out why a request was slow.

Skip it when

  • The system has one step with no failure cases, and a single counter is enough.

Words to know

Terms in this lesson

Trace
The full set of spans for one request.
Span
The record of one step, with its start time and duration.
Log
A file or stream of records written as the system runs.
JSON line
One JSON object written on its own line.
Full code