DEV Community

Sam Sun
Sam Sun

Posted on

Unpromoted Tool Logs Cannot Close a Debug Loop

An agent debug session that starts in stdout is already looking at a side channel. The unit that can be compared, retried, and blamed is a closed span with events. A tool log line that never promotes into that span is not extra context. It is a failed observation.

Most coding agents still print what they did. The printer is convenient. It is also a shuffle. Two tools that run in parallel write overlapping chunks, a retry writes a second success after a timeout, and the model summary then narrates a single story. None of those three artifacts share a join key unless you force one into the child process that actually ran the tool.

Think of the log file as a loading dock and the span tree as inventory. Boxes that never get a pallet tag do not belong on the warehouse floor. You do not keep them nearby in case they help. You fail the receiving check and stop talking about root cause.

Promotion is a copy, not a reading of the chat

Promotion is mechanical. Each tool start and tool exit must carry a stable tool_call_id. That id is the pallet tag. The span with the same id is the pallet. The log line becomes a span event whose time comes from the tracer, not from the laptop clock that printed the line.

If the id is missing, the line stays on the dock. The run is incomplete. That is the entire method. It does not score the model and it does not parse English. After ingest, the only question is whether any tool-shaped log line remains.

Agents often shell out. The child inherits environment, or it does not. If the id lives only in the parent's memory, the child's stdout is already unjoinable. Put the id where the child can echo it, then refuse pretty paragraphs as the record of record.

export AGENT_RUN_ID="run_7f3c"
export TOOL_CALL_ID="call_19"
python tools/grep_repo.py --pattern "TODO" --json
Enter fullscreen mode Exit fullscreen mode

The tool should write one NDJSON object to a side file or to stderr, not a prose status line:

{"event":"tool.exit","run_id":"run_7f3c","tool_call_id":"call_19","status":"ok","bytes_out":412}
Enter fullscreen mode Exit fullscreen mode

The tracer records the same ids on the span. Progress bars, token streams, and colored diffs are optional. They are also discardable. Do not use wall-clock order as a substitute key. Two parallel grep calls can finish inside the same millisecond window on a loaded machine, and clocks jump. Ids do not.

Completeness is a test, not a dashboard

Dashboards forgive holes. Tests do not. The checker below reads a span dump and a raw tool log, promotes what it can join, and fails the process if anything tool-shaped remains. Treat it as a proposed gate. It is not a production tracer. It assumes NDJSON spans and one regex for tool lines, and both must change when your agent format changes.

#!/usr/bin/env python3
"""Promote tool log lines into span events. Fail on leftovers.

Proposed checker. Point SPAN_PATH and LOG_PATH at real dumps
before treating an exit code as evidence about an agent.
"""
from __future__ import annotations

import json
import os
import re
import sys
from typing import Any

TOOL_LINE = re.compile(
    r"tool\.(start|exit)\s+id=(?P<id>[A-Za-z0-9_\-]+)"
    r"(?:\s+status=(?P<status>\w+))?"
)

def load_ndjson(path: str) -> list[dict[str, Any]]:
    rows = []
    with open(path, encoding="utf-8") as fh:
        for line_no, line in enumerate(fh, 1):
            line = line.strip()
            if not line:
                continue
            try:
                rows.append(json.loads(line))
            except json.JSONDecodeError as exc:
                raise SystemExit(f"{path}:{line_no}: {exc}") from exc
    return rows

def index_spans(spans: list[dict[str, Any]]) -> dict[str, dict[str, Any]]:
    by_tool = {}
    for span in spans:
        attrs = span.get("attributes") or {}
        tool_id = attrs.get("tool_call_id")
        if not tool_id:
            continue
        if tool_id in by_tool:
            raise SystemExit(f"duplicate tool_call_id on spans: {tool_id}")
        span.setdefault("events", [])
        by_tool[tool_id] = span
    return by_tool

def promote(spans_by_tool: dict[str, dict[str, Any]], log_path: str) -> list[str]:
    leftovers = []
    with open(log_path, encoding="utf-8") as fh:
        for line_no, raw in enumerate(fh, 1):
            raw = raw.rstrip("\n")
            m = TOOL_LINE.search(raw)
            if not m:
                continue
            tool_id = m.group("id")
            span = spans_by_tool.get(tool_id)
            if span is None:
                leftovers.append(f"{log_path}:{line_no}: no span for {tool_id}")
                continue
            span["events"].append(
                {
                    "name": f"tool.{m.group(1)}",
                    "attributes": {
                        "tool_call_id": tool_id,
                        "status": m.group("status"),
                        "log_line": line_no,
                    },
                }
            )
    return leftovers

def closed_without_exit(spans_by_tool: dict[str, dict[str, Any]]) -> list[str]:
    missing = []
    for tool_id, span in spans_by_tool.items():
        names = {ev.get("name") for ev in span.get("events") or []}
        if "tool.exit" not in names:
            missing.append(
                f"span {span.get('span_id')} tool_call_id={tool_id} has no tool.exit"
            )
    return missing

def main() -> int:
    span_path = os.environ.get("SPAN_PATH", "spans.jsonl")
    log_path = os.environ.get("LOG_PATH", "tools.log")
    spans = load_ndjson(span_path)
    by_tool = index_spans(spans)
    leftovers = promote(by_tool, log_path)
    missing_exits = closed_without_exit(by_tool)
    report = {
        "spans": len(spans),
        "tool_spans": len(by_tool),
        "promoted_events": sum(len(s.get("events") or []) for s in by_tool.values()),
        "leftover_tool_lines": leftovers,
        "spans_missing_exit": missing_exits,
    }
    json.dump(report, sys.stdout, indent=2)
    sys.stdout.write("\n")
    if leftovers or missing_exits:
        return 2
    return 0

if __name__ == "__main__":
    raise SystemExit(main())
Enter fullscreen mode Exit fullscreen mode

A fixture pair makes the failure mode obvious. Save this as dump/spans.jsonl:

{"span_id":"s1","parent_span_id":null,"start_unix_nano":1000,"end_unix_nano":4000,"attributes":{"tool_call_id":"call_19"},"events":[]}
{"span_id":"s2","parent_span_id":"s0","start_unix_nano":1500,"end_unix_nano":3900,"attributes":{"tool_call_id":"call_20"},"events":[]}
Enter fullscreen mode Exit fullscreen mode

And this as dump/tools.log:

tool.start id=call_19
tool.exit id=call_19 status=ok
tool.start id=call_20
tool.exit id=call_21 status=ok
Enter fullscreen mode Exit fullscreen mode

call_21 has no pallet. The gate should refuse to open.

export SPAN_PATH=./dump/spans.jsonl
export LOG_PATH=./dump/tools.log
python promote_tool_logs.py
echo $?
Enter fullscreen mode Exit fullscreen mode

Exit code 2 means the debug loop must not start. There is nothing to interpret yet. The model may have printed a confident summary. The summary is downstream of missing evidence, the way a shipping label is downstream of an empty bay.

Parallel tools still have no timeline

Promotion does not give you order. Two events on different spans are concurrent unless a parent link or an explicit span link says otherwise. Concatenating tools.log after the fact is a lexical sort of a race. A second helper should make that refusal explicit. It does not invent happens-before edges.

def concurrent_pairs(spans: list[dict[str, Any]]) -> list[tuple[str, str]]:
    """Return tool_call_id pairs whose intervals overlap.

    Overlap means neither span is parent of the other and each
    starts before the other ends. Proposed helper, not a scheduler.
    """
    tools = []
    for span in spans:
        attrs = span.get("attributes") or {}
        tid = attrs.get("tool_call_id")
        if not tid:
            continue
        tools.append(
            (
                tid,
                int(span["start_unix_nano"]),
                int(span["end_unix_nano"]),
                span.get("parent_span_id"),
                span.get("span_id"),
            )
        )
    pairs = []
    for i, a in enumerate(tools):
        for b in tools[i + 1 :]:
            overlap = a[1] < b[2] and b[1] < a[2]
            related = a[3] == b[4] or b[3] == a[4]
            if overlap and not related:
                pairs.append((a[0], b[0]))
    return pairs
Enter fullscreen mode Exit fullscreen mode

If that function returns a pair, any narrative that says "then" between those two tools is unsupported. Stop asking the model which file it edited first. The span tree already answered: both, or neither, with no order. Git is the same shape. A merge commit message is not a linear history until you pick a topology. Logs are the message. Spans are the graph.

The debug order that stays honest is therefore short, and it is the opposite of how terminals train you. Diff closed tool spans against the previous green run. Inspect concurrent pairs before you trust any "then." Only after those two steps read the model summary, and only as a hypothesis. The terminal shows words first. The span file is quieter. Quiet is the point. Words that cannot join a span were never observations.

Where a dump host actually helps

You still need an agent that emits the two files. A laptop loop mixes local clock noise with remote tool time, and it often skips the side file because the terminal looked sufficient.

Disclosure: This article was prepared as part of MonkeyCode's product outreach.

MonkeyCode's free model access and free server option matter here only as a way to run the agent so spans.jsonl and tools.log land on one host. The checker does not depend on that host. If you already have traces, skip the product. If you do not, a free server is scaffolding for the dump, not a substitute for the join key, and a UI summary is not a span. Export NDJSON. Run the gate. Then read anything written in English.

Who should not use this gate

The loop will not tell you the model was wrong. Incomplete traces and wrong answers are different bugs. Mixing them produces a session that oscillates between adding more logs and changing the prompt, which feels like progress and measures nothing.

It will not work for agents that stream unstructured prose as their only tool record. If you cannot add tool_call_id to the child process, stop. The promotion test will fail every run. That result is correct. It is also useless as a daily gate, the way a smoke alarm that cannot be silenced is useless as a ship checklist.

It will not reconstruct payloads you redacted. Promote ids and status codes. Leave secrets in a filter that runs before the log file exists. Strip the id and you have manufactured leftovers on purpose. Teams that sample traces at ingest should not use the method either. Sampling drops one side of a join by design. A partial sample of an agent that made a dozen tool calls is not a shorter story. It is a different, unnamed agent.

The same warning applies to tracers that buffer events until process exit and then die with the child. A killed tool produces leftovers. That is a reliability bug in the tracer. It is not a model-quality signal, and treating it as one will send you back into the prompt.

Hang the checker on CI if you hang anything. The chat transcript will still be there after the gate fails. Waiting does not make it more true.

Top comments (0)