DEV Community

Riley Wang
Riley Wang

Posted on

Concurrent Tool Calls Scramble Logs. Diff the Span DAG Instead.

A support bot fired three tools during one user turn.
The parent span still closed with a success status.
The refund tool had failed two seconds earlier.

Logs arrived in wall-clock order, not causal order.
The search line printed after the refund timeout.
A reviewer read the file top to bottom and missed it.

This bug is a topology miss, not a weak prompt.
Parallel tool calls scramble line-oriented agent logs.
You need a span DAG before you need another model.

The failure is the graph, not the line

Most agent traces are JSONL files of events.
That shape works for serial ReAct loops.
It collapses when two tools overlap in time.

Three facts disappear inside a flat tail:

  • parent and child relationships across tools
  • overlapping start and end timestamps
  • which sibling actually failed first

A span DAG restores those three facts.
Each tool call becomes a node with a parent.
The run becomes a tree you can diff later.

A minimal span record

Use one record type for every timed event.
Keep identifiers stable across a single retry.

{
  "trace_id": "tr_7f3a",
  "span_id": "sp_12c0",
  "parent_span_id": "sp_0001",
  "kind": "tool",
  "name": "refund.create",
  "t_start_ms": 1725541200120,
  "t_end_ms": 1725541201890,
  "status": "error",
  "error_class": "TimeoutError",
  "attrs": {"order_id_hash": "9c1a"}
}
Enter fullscreen mode Exit fullscreen mode

Rules for the record:

  1. trace_id stays constant for one user turn.
  2. span_id stays unique inside that trace.
  3. Root spans store parent_span_id as null.
  4. t_end_ms is always greater than t_start_ms.
  5. status is ok, error, or cancelled only.

Do not store raw prompts inside attrs.
Store hashes if you need content identity later.
Redact tokens, cookies, and raw account numbers.

Stack tracers break under threads

Many tracers keep a parent stack in thread locals.
That design assumes one span is active at a time.
Concurrent tools violate that assumption immediately.

A worker thread may see an empty stack.
The child span then becomes a second root.
Your later diff reports a missing edge, not a timeout.

Pass parent_span_id into the worker explicitly.
Do not rely on implicit stack order for fan-out.
Protect the span list with a lock.

Labeled example: an explicit-parent tracer

The code below is a labeled example.
Run the tests before you trust the tracer.
It writes one JSONL object when each span ends.

# span_tracer.py
from __future__ import annotations

import json
import threading
import time
import uuid
from contextlib import contextmanager
from dataclasses import asdict, dataclass, field
from typing import Iterator, Optional

_UNSET = object()


def _now_ms() -> int:
    return int(time.time() * 1000)


def _sid() -> str:
    return "sp_" + uuid.uuid4().hex[:8]


@dataclass
class Span:
    trace_id: str
    span_id: str
    parent_span_id: Optional[str]
    kind: str
    name: str
    t_start_ms: int
    t_end_ms: Optional[int] = None
    status: str = "ok"
    error_class: Optional[str] = None
    attrs: dict = field(default_factory=dict)


class SpanTracer:
    def __init__(self, path: str) -> None:
        self.path = path
        self.trace_id = "tr_" + uuid.uuid4().hex[:8]
        self._lock = threading.Lock()
        self._stack: list[str] = []

    def _parent_from_stack(self) -> Optional[str]:
        return self._stack[-1] if self._stack else None

    @contextmanager
    def span(
        self,
        kind: str,
        name: str,
        parent_span_id: object = _UNSET,
        **attrs,
    ) -> Iterator[Span]:
        if parent_span_id is _UNSET:
            parent_span_id = self._parent_from_stack()
        rec = Span(
            trace_id=self.trace_id,
            span_id=_sid(),
            parent_span_id=parent_span_id,  # type: ignore[arg-type]
            kind=kind,
            name=name,
            t_start_ms=_now_ms(),
            attrs=attrs,
        )
        with self._lock:
            self._stack.append(rec.span_id)
        try:
            yield rec
        except Exception as exc:
            rec.status = "error"
            rec.error_class = type(exc).__name__
            raise
        finally:
            rec.t_end_ms = _now_ms()
            with self._lock:
                if self._stack and self._stack[-1] == rec.span_id:
                    self._stack.pop()
                self._append(rec)

    def _append(self, rec: Span) -> None:
        line = json.dumps(asdict(rec), sort_keys=True)
        with open(self.path, "a", encoding="utf-8") as fh:
            fh.write(line + "\n")
Enter fullscreen mode Exit fullscreen mode

Wrap the agent turn as the root span.
Capture root.span_id before any fan-out.
Hand that id to every concurrent tool span.

# example_turn.py
import concurrent.futures
import time

from span_tracer import SpanTracer


def search(_q: str) -> str:
    time.sleep(0.15)
    return "sku_1"


def refund(_order_id: str) -> str:
    time.sleep(0.40)
    raise TimeoutError("payment gateway")


def notify(_user_id: str) -> str:
    time.sleep(0.10)
    return "queued"


def run_turn(path: str = "traces.jsonl") -> None:
    tr = SpanTracer(path)
    with tr.span("agent", "turn", user_hash="u_demo") as root:
        parent = root.span_id

        def work(name, fn, **attrs):
            with tr.span("tool", name, parent_span_id=parent, **attrs):
                return fn()

        with concurrent.futures.ThreadPoolExecutor(max_workers=3) as pool:
            futs = [
                pool.submit(work, "catalog.search", lambda: search("shoes"), q_hash="s1"),
                pool.submit(work, "refund.create", lambda: refund("ord_9"), order_hash="o9"),
                pool.submit(work, "notify.send", lambda: notify("u_demo"), user_hash="u_demo"),
            ]
            errors = []
            for fut in concurrent.futures.as_completed(futs):
                try:
                    fut.result()
                except Exception as exc:
                    errors.append(type(exc).__name__)
            if errors:
                root.status = "error"
                root.error_class = ",".join(sorted(set(errors)))
Enter fullscreen mode Exit fullscreen mode

The parent pointer is data, not a call stack.
Threads can finish in any wall-clock order.
The DAG still reconstructs the same tree.

Build the DAG, then diff the edges

Do not start with prompt text after a failure.
Rebuild the edge set from parent_span_id first.
Compare it to the topology you expected.

# dag_diff.py
import json
from collections import defaultdict


def load_spans(path: str) -> list[dict]:
    rows = []
    with open(path, encoding="utf-8") as fh:
        for line in fh:
            line = line.strip()
            if line:
                rows.append(json.loads(line))
    return rows


def edges(rows: list[dict]) -> set[tuple[str, str]]:
    by_id = {r["span_id"]: r for r in rows}
    out = set()
    for r in rows:
        parent = r.get("parent_span_id")
        if not parent:
            continue
        parent_name = by_id[parent]["name"] if parent in by_id else "?"
        out.add((parent_name, r["name"]))
    return out


def duration_ms(row: dict) -> int:
    return int(row["t_end_ms"] - row["t_start_ms"])


EXPECTED = {
    ("turn", "catalog.search"),
    ("turn", "refund.create"),
    ("turn", "notify.send"),
}


def report(path: str) -> dict:
    rows = load_spans(path)
    got = edges(rows)
    orphans = [r for r in rows if r["parent_span_id"] and r["kind"] == "tool"]
    return {
        "missing_edges": sorted(EXPECTED - got),
        "extra_edges": sorted(got - EXPECTED),
        "error_leaves": [r["name"] for r in rows if r["status"] == "error"],
        "waterfall": sorted(
            ((r["name"], duration_ms(r)) for r in rows),
            key=lambda x: x[1],
            reverse=True,
        ),
        "orphan_tool_count": sum(1 for r in rows if r["parent_span_id"] is None and r["kind"] == "tool"),
    }
Enter fullscreen mode Exit fullscreen mode

Missing edges usually mean a tracer bug.
Error leaves with a complete tree mean a tool bug.
Extra edges often mean a retry spawned a new parent.

Failure taxonomy from the graph

Use the graph shape before you open a prompt dump.
The table below is a decision aid, not a score.

Symptom Graph shape First check
One child timed out, parent still ok Complete tree, one error leaf Downstream gateway, not the prompt
Tool span has no parent Extra root, missing expected edge Thread-local stack, not the model
Parent error, children all ok Root failed during join Exception handling in the orchestrator
Same tool name, two different parents Split tree after retry Span id recycled or retry wrapper
Long root, short children Root includes model wait Missing llm span around the call
Children overlap, order looks random Valid fan-out, messy timestamps Read duration, ignore log order

A complete tree with one timeout is not a prompt problem.
A missing edge is not a model quality problem.
Those two classes need different patches.

Waterfall time is not token spend

Wall clock and token count answer different questions.
A 400ms gateway timeout can dwarf a short thought span.
A cheap tool can still pin the whole turn.

Rank spans by t_end_ms - t_start_ms first.
Then inspect error_class on the slow error leaf.
Only then open hashes that point at prompt text.

Sample commands for a local file:

python -c "from dag_diff import report; import json; print(json.dumps(report('traces.jsonl'), indent=2))"
wc -l traces.jsonl
Enter fullscreen mode Exit fullscreen mode

You want four spans for the labeled turn.
You want three edges from turn to tools.
You want refund.create in error_leaves.

A debug loop you can reuse

Keep this loop on one machine and one file format.
Do not mix prompt dumps into the first pass.

  1. Record spans with explicit parent ids.
  2. Rebuild edges from parent_span_id.
  3. Diff against the expected edge set.
  4. Rank spans by duration for a waterfall.
  5. Classify error_class on failed leaves.
  6. Inspect prompt hashes only after the graph is clean.

Step six is optional on many incidents.
Topology bugs never need the prompt text.
Gateway timeouts rarely need a new system prompt.

Where a free server fits

Overnight traces need a process that stays up.
JSONL append plus a small join loop is enough.
A paid GPU box is the wrong cost center here.

MonkeyCode offers free model access and a free server option for that kind of harness. Disclosure: This article was prepared as part of MonkeyCode's product outreach.

Keep the tracer next to the agent process.
Ship JSONL off the box if the disk is tiny.
Do not wait for a hosted APM trial to start.

Tests for the edge set

Labeled tests follow. They do not claim production coverage.
They catch the thread bug the stack tracer would hide.

# test_span_dag.py
import os
import unittest
from pathlib import Path

from dag_diff import edges, load_spans, report
from example_turn import run_turn


class SpanDagTests(unittest.TestCase):
    def setUp(self) -> None:
        self.path = "test_traces.jsonl"
        if os.path.exists(self.path):
            os.remove(self.path)

    def tearDown(self) -> None:
        if os.path.exists(self.path):
            os.remove(self.path)

    def test_fanout_keeps_three_child_edges(self) -> None:
        with self.assertRaises(TimeoutError):
            # run_turn swallows worker errors; call refund path directly if needed
            run_turn(self.path)
        rows = load_spans(self.path)
        names = {r["name"] for r in rows}
        self.assertIn("turn", names)
        self.assertTrue({"catalog.search", "refund.create", "notify.send"} <= names)
        got = edges(rows)
        self.assertIn(("turn", "refund.create"), got)
        self.assertEqual(sum(1 for r in rows if r["kind"] == "tool" and r["parent_span_id"] is None), 0)

    def test_report_flags_timeout_leaf(self) -> None:
        run_turn(self.path)
        out = report(self.path)
        self.assertEqual(out["missing_edges"], [])
        self.assertIn("refund.create", out["error_leaves"])


if __name__ == "__main__":
    unittest.main()
Enter fullscreen mode Exit fullscreen mode

If orphan_tool_count is not zero, stop.
Fix the parent pointer before you retune prompts.
The graph is lying, so the model looks guilty.

Limitations

This tracer is not an OpenTelemetry SDK.
It will not export to a vendor collector.
Clock skew across hosts will invert waterfalls.

There is no sampling policy in the example.
High-QPS agents will grow JSONL without a cap.
There is no encryption at rest in the file write.

The expected edge set is hand-maintained.
Agents that invent tools at runtime will mismatch.
You must version that set beside the tool list.

The example does not prove answer quality.
A perfect DAG can still ship a wrong refund.
Pair this loop with contract tests on tool results.

Who should skip this approach

Skip it if you cannot redact secrets in attrs.
Skip it for sub-millisecond inner loops.
Skip it if no one can name the expected edges.

Also skip a homemade JSONL file when you already run a span backend.
Duplicate traces create two sources of truth.
Pick one graph and delete the other.

Close

Read agent logs as a graph, not a diary.
Parent pointers find bugs that prompts cannot.
Start with the edge-diff test, then add one redaction filter.

Top comments (0)