Or press ESC to close.

Trace, Don't Trust: Testing What Your AI Agent Actually Called

Sep 19th 2026 17 min read
medium
javascriptES6
nodejs24.13.0
ai/ml
mocking
ci/cd
strategy

When an AI agent finishes a task, the test looks at the answer. If the file has the right content or the right record came back, the run is green. How the agent got there is rarely inspected, and that is where a whole class of problems lives: an agent can read the same file four times, run the same search twice, and re-fetch data it already has, and still produce a perfect result. Nothing in an outcome test would notice.

The tool-call trace makes this visible, and it is a very testable thing. Every call passes through the harness, so the harness can record it, and a list of calls is just data to assert on. This post builds a small Node.js demo with a scripted stand-in for the model, a tracer that records every tool invocation, and detectors that flag exact duplicates, semantically identical calls, and re-fetches of data that has not changed, without ever making a request to a real LLM.

The Call You Didn't See

Most agent testing is outcome testing. You give the agent a task, let it run its loop of model calls and tool calls, and check the final state: the answer it returned, the file it wrote, the record it updated. This is a reasonable place to start, because the outcome is what the user sees. It is also the only thing that is easy to assert on when the steps in between are non-deterministic.

The problem is that the outcome hides the path. Suppose the task is to enable debug mode in a config file. A well-behaved agent searches for the file, reads it, writes the change, and reads it once more to confirm. Four calls. A sloppy agent might search twice because the first result was already scrolled out of its attention, read the config, fetch a user record it did not need, fetch the same record again with the id as a string instead of a number, read the config again before writing, and then read it a third time afterward. Nine calls. Both agents produce the same file, and both pass the same outcome test.

Those extra calls are not free. Each one is a round trip to a tool, and each tool result is appended to the context the model sees on its next step, which means every redundant call makes every subsequent model request larger and more expensive. On a single run the difference is small. Across thousands of runs, or across an agent that operates in a loop for minutes at a time, it is the difference between a feature that is economical to ship and one that is not.

There is also a quality signal buried in the redundancy. An agent that re-reads a file it already has in context is telling you something about how the harness assembles that context, or about how the prompt describes the tools, or about a model change that shifted how it plans. These are regressions in their own right, and they are exactly the kind that arrive silently when a provider updates a model or a teammate rewords a system prompt. If the only check is the final answer, the first sign of trouble is the invoice.

What Counts as Redundant

Before writing any detection code it is worth being precise about what "redundant" means, because the vague version leads to tests that either flag nothing or flag everything. A call is redundant when the agent already had the information it would return, or could have had it, and nothing has happened since to make it stale. That definition splits into a few distinct cases, and each one needs a different check.

The first two are within-turn checks. The model emitted a batch of tool calls and some of them overlap. The third is a cross-turn check that follows a resource through the whole run. Keeping these separate matters for the tests: a single sloppy call should show up under one detector, not three, so that when a test fails the name of the failing test tells you what kind of mistake the agent made.

Just as important is what does not count. A re-read after a write is verification, not waste. A tool call that the harness itself repeated after a transient error is infrastructure, not model behavior, and blaming the model for it would make the tests flaky for the wrong reasons. And two searches with different phrasing that happen to return the same results are a judgment call that no argument normalization will resolve. The detectors in this post draw the line at what can be decided from the trace alone, and say so.

Recording Every Call

Everything that follows depends on having a complete, structured record of what the agent called. The cleanest place to capture that is the tool registry itself. The harness already holds a map of tool names to implementations and looks up each call by name, so if that map is replaced with a wrapped version that records the call before delegating to the real implementation, nothing else in the harness has to change. The agent loop does not know it is being traced.

For the wrapper to produce useful records, the tools need to describe themselves a little. Two pieces of metadata are enough. mutates says whether the tool changes state, and resource is a function that maps the arguments to a stable identifier for the thing being touched. Both read_file and write_file resolve to the same file:config.json key when given the same path, which is what lets the stale re-fetch detector later see that a write happened between two reads. The demo's tools operate on a small in-memory world of files and users, so they are a few lines each:

                
read_file: {
  mutates: false,
  resource: ({ path }) => `file:${path}`,
  run: ({ path }) => world.files[path] ?? null,
},
write_file: {
  mutates: true,
  resource: ({ path }) => `file:${path}`,
  run: ({ path, content }) => {
    world.files[path] = content;
    return 'ok';
  },
},
                

The tracer wraps each tool's run function in a closure that builds a record, delegates to the original, and pushes the record onto a list. The record captures the current turn, the raw arguments, two comparison keys, the resource, whether the tool mutates, and where the call came from. The delegation happens inside a try/catch/finally so that a tool that throws still leaves a record, marked as failed, rather than disappearing from the trace. The optional second parameter is how the harness tags calls it initiated itself, which becomes important when dealing with retries.

                
export class ToolTracer {
  constructor() {
    this.calls = [];
    this.turn = 0;
  }

  nextTurn() {
    this.turn++;
  }

  wrap(tools) {
    const wrapped = {};
    for (const [name, tool] of Object.entries(tools)) {
      wrapped[name] = {
        ...tool,
        run: (args, meta = {}) => {
          const record = {
            seq: this.calls.length,
            turn: this.turn,
            name,
            args,
            rawKey: `${name}(${JSON.stringify(args)})`,
            normalizedKey: `${name}(${JSON.stringify(normalizeArgs(args))})`,
            resource: tool.resource(args),
            mutates: tool.mutates,
            origin: meta.origin ?? 'model', // 'model' | 'harness-retry'
          };
          try {
            const result = tool.run(args);
            record.ok = true;
            record.resultHash = hash(result);
            return result;
          } catch (err) {
            record.ok = false;
            record.error = err.message;
            throw err;
          } finally {
            this.calls.push(record);
          }
        },
      };
    }
    return wrapped;
  }
}
                

The two comparison keys are the heart of the duplicate detection. The raw key is the tool name plus the arguments serialized exactly as the model sent them. The normalized key runs the arguments through a canonicalization step first: object keys are sorted so that order does not matter, numbers are coerced to strings so that 5 and "5" collide, and strings are trimmed. It is deliberately conservative. Lowercasing, for instance, would be wrong for a file path on a case-sensitive filesystem, so it is left out. The point is to catch arguments that are equivalent by construction, not to guess at intent.

                
export function normalizeArgs(value) {
  if (Array.isArray(value)) return value.map(normalizeArgs);
  if (value && typeof value === 'object') {
    return Object.fromEntries(
      Object.keys(value)
        .sort()
        .map((k) => [k, normalizeArgs(value[k])]),
    );
  }
  if (typeof value === 'number') return String(value);
  if (typeof value === 'string') return value.trim();
  return value;
}
                

Two small details round this out. The turn counter is advanced by the harness once per model step, so every record knows which batch of tool calls it belonged to. And the result is hashed rather than stored, which keeps the trace small and gives the detectors a cheap way to check whether two calls returned the same thing without holding the full payload. With this in place the trace is just an array of plain objects, which is exactly what you want to hand to a test.

Scripting the Model Out of the Test

The thing under test here is the harness: the loop that asks the model what to do, executes the tool calls it comes back with, feeds the results into the context, and repeats. The model is an input to that loop, not part of it. So for the redundancy tests to be deterministic, fast, and runnable without an API key, the model gets replaced with something that produces a fixed sequence of decisions. This is the same move as stubbing an HTTP client in a unit test. The harness does not care where the decisions come from.

The agent loop is small enough to show in full. Each iteration is one turn. It advances the tracer, asks the model for a step, and either returns the final answer or executes every tool call in the batch and appends the results to the context. The model function receives that context on its next call, which is how a real model would see what it has already fetched. The invokeWithRetry helper is where the harness handles transient tool failures, and it is covered in its own section later.

                
export function runAgent({ model, tools, tracer, maxTurns = 20 }) {
  const context = [];
  for (let i = 0; i < maxTurns; i++) {
    tracer.nextTurn();
    const step = model(context);
    if (step.final !== undefined) return { answer: step.final, context };

    for (const call of step.toolCalls) {
      const tool = tools[call.tool];
      if (!tool) throw new Error(`Unknown tool: ${call.tool}`);
      const result = invokeWithRetry(tool, call.args);
      context.push({ tool: call.tool, args: call.args, result });
    }
  }
  throw new Error(`Agent exceeded ${maxTurns} turns`);
}
                

The scripted model is a closure over a list of steps that hands them out one at a time. It ignores the context it is given, because the whole point is that its decisions are fixed in advance. If a fixture runs out of steps before returning a final answer, that is a bug in the fixture, so it throws rather than looping forever.

                
export function scriptedModel(steps) {
  let i = 0;
  return () => {
    if (i >= steps.length) throw new Error('Scripted model ran out of steps');
    return steps[i++];
  };
}
                

The steps live in JSON fixtures, one per scenario. Each fixture describes a task and the exact sequence of tool calls a model made while completing it. The well-behaved fixture is the baseline: search, read, write, read to confirm, done. The sloppy fixture below completes the same task with every kind of redundancy from the taxonomy folded in. The duplicated search in turn one, the two get_user calls in turn two that differ only in the type of the id, the re-read of the config in turn three before anything has written to it, and a final read after the write that is legitimate and should not be flagged.

                
{
  "name": "sloppy",
  "task": "Enable debug mode in the project config",
  "steps": [
    {
      "toolCalls": [
        { "tool": "search", "args": { "query": "config" } },
        { "tool": "search", "args": { "query": "config" } }
      ]
    },
    {
      "toolCalls": [
        { "tool": "read_file", "args": { "path": "config.json" } },
        { "tool": "get_user", "args": { "id": 5 } },
        { "tool": "get_user", "args": { "id": "5" } }
      ]
    },
    { "toolCalls": [{ "tool": "read_file", "args": { "path": "config.json" } }] },
    { "toolCalls": [{ "tool": "read_file", "args": { "path": "README.md" } }] },
    { "toolCalls": [{ "tool": "write_file", "args": { "path": "config.json", "content": "{\"debug\":true}" } }] },
    { "toolCalls": [{ "tool": "read_file", "args": { "path": "config.json" } }] },
    { "final": "Enabled debug mode in config.json." }
  ]
}
                

A small glue function, runFixture, ties this together for the tests. It loads a fixture by name, builds a fresh world and tracer, wraps the tools, runs the agent with a scripted model over the fixture's steps, and returns the tracer's call list. Every test starts from that list. Where the fixtures come from in practice is worth a note: the ones in the demo are hand-written to isolate each failure mode, but the same tracer can serialize a real model's trace to disk, and a captured trace from a run that went badly makes a very good regression fixture.

The Detectors

With a trace in hand, each category from the taxonomy becomes a short function that walks the list of calls and returns findings. A finding is a pair: the first call and the one that repeats it. Returning both rather than a count makes failures readable, since a test can print exactly which call was wasteful and which earlier call already covered it.

All of the detectors start by filtering the trace down to the calls that matter. Two filters do this. modelCalls keeps only calls the model initiated, dropping anything the harness repeated on its own. successfulModelCalls narrows that further to calls that returned a result. The duplicate detectors use the stricter filter, because a call that failed did not put anything in the model's context, so repeating it is not redundant in any meaningful sense.

Exact and semantic duplicates share one implementation. It walks the successful calls, builds a key from the turn number and whatever comparison key the caller asks for, and reports any call whose key has already been seen. Exact duplicates use the raw key. Semantic duplicates use the normalized key and then drop any pair whose raw keys also match, so that the same wasteful call is not reported twice under two names. Scoping the key to the turn is what makes these within-turn checks: the same search in two different turns is not this detector's business.

                
const modelCalls = (trace) => trace.filter((c) => c.origin === 'model');
const successfulModelCalls = (trace) => modelCalls(trace).filter((c) => c.ok);

export function findExactDuplicates(trace) {
  return findDuplicatesWithinTurn(trace, (c) => c.rawKey);
}

export function findSemanticDuplicates(trace) {
  return findDuplicatesWithinTurn(trace, (c) => c.normalizedKey).filter(
    (f) => f.first.rawKey !== f.repeat.rawKey,
  );
}

function findDuplicatesWithinTurn(trace, keyOf) {
  const seen = new Map(); // `${turn}|${key}` -> first call
  const findings = [];
  for (const call of successfulModelCalls(trace)) {
    const key = `${call.turn}|${keyOf(call)}`;
    if (seen.has(key)) findings.push({ first: seen.get(key), repeat: call });
    else seen.set(key, call);
  }
  return findings;
}
                

The stale re-fetch detector is the one that needs the tool metadata. It follows each resource through the trace, remembering the last call that touched it. When a new call arrives for a resource it has seen before, it asks three questions. Is this call a read? Was the previous call on this resource also a read? And did they happen in different turns? If all three are true, the model fetched something it already had and nothing had changed in between. The moment a write touches the resource, it becomes the last event, and the next read is treated as legitimate verification. The different-turn condition keeps this detector disjoint from the previous two, so each wasteful call lands in exactly one bucket.

                
export function findStaleRefetches(trace) {
  const lastEvent = new Map(); // resource -> last call touching it
  const findings = [];
  for (const call of successfulModelCalls(trace)) {
    const prev = lastEvent.get(call.resource);
    if (prev && !call.mutates && !prev.mutates && prev.turn !== call.turn) {
      findings.push({ first: prev, repeat: call });
    }
    lastEvent.set(call.resource, call);
  }
  return findings;
}
                

The budget check is not really a detector. It is a tally of model-initiated calls, per tool and in total, that a test can compare against a ceiling. It uses the looser filter on purpose. A call that failed still cost the model a request and still consumed a turn, so it counts. This is the check to reach for when you do not know what shape the waste will take, and it is the one most likely to fire first when a model update quietly changes how the agent plans.

                
export function callCounts(trace) {
  const counts = { total: 0 };
  for (const call of modelCalls(trace)) {
    counts[call.name] = (counts[call.name] ?? 0) + 1;
    counts.total++;
  }
  return counts;
}
                

Together these four functions are around sixty lines, and none of them know anything about the specific tools in the demo. They operate entirely on the shape of the trace record, which means they transfer unchanged to any harness whose tools can declare what they mutate and what they touch.

Turning Findings into Assertions

The tests are where the detectors earn their keep, and they are deliberately boring. Each one runs a fixture, gets the trace, calls a detector, and asserts on the result. The demo uses the built-in node:test runner and node:assert so there is nothing to install, but the shape is the same in Jest, Vitest, or anything else.

The first test is the baseline, and it is the one you want in CI. It runs the well-behaved fixture and asserts that every detector returns nothing and the call count stays under a budget. If someone changes the harness in a way that introduces redundancy into a run that used to be clean, this is the test that turns red. The budget number is a judgment call. Five is generous for a four-call task, tight enough that the sloppy version cannot sneak under it.

                
const CALL_BUDGET = 5;

test('well-behaved agent makes no redundant tool calls', () => {
  const { trace } = runFixture('well-behaved');

  assert.equal(findExactDuplicates(trace).length, 0);
  assert.equal(findSemanticDuplicates(trace).length, 0);
  assert.equal(findStaleRefetches(trace).length, 0);
  assert.ok(callCounts(trace).total <= CALL_BUDGET);
});
                

The sloppy tests go the other way and assert that each kind of waste is caught, one test per detector. These are tests of the detectors themselves, and their value is in being specific. Rather than checking that a finding exists, they check which call was flagged and which earlier call it repeats, down to the turn numbers. That precision is what makes the tests trustworthy: if a detector starts flagging the wrong call, or flags the legitimate read after the write, the assertion on the turn number will say so. Two of them are shown here.

                
test('sloppy agent: semantically identical args are caught', () => {
  const { trace } = runFixture('sloppy');
  const findings = findSemanticDuplicates(trace);

  assert.equal(findings.length, 1);
  assert.equal(findings[0].first.rawKey, 'get_user({"id":5})');
  assert.equal(findings[0].repeat.rawKey, 'get_user({"id":"5"})');
});

test('sloppy agent: re-read with no intervening write is a stale re-fetch', () => {
  const { trace } = runFixture('sloppy');
  const findings = findStaleRefetches(trace);

  assert.equal(findings.length, 1);
  assert.equal(findings[0].repeat.resource, 'file:config.json');
  assert.equal(findings[0].first.turn, 2);
  assert.equal(findings[0].repeat.turn, 3);
});
                

Assertions are what CI needs, but a person debugging a failing run needs to see the trace. The demo ships a small script that runs a fixture and prints the full call list followed by the findings from each detector. Running it against the sloppy fixture gives this:

Fixture: sloppy - "Enable debug mode in the project config"

Trace:
 turn 1 search({"query":"config"})
 turn 1 search({"query":"config"})
 turn 2 read_file({"path":"config.json"})
 turn 2 get_user({"id":5})
 turn 2 get_user({"id":"5"})
 turn 3 read_file({"path":"config.json"})
 turn 4 read_file({"path":"README.md"})
 turn 5 write_file({"path":"config.json","content":"{\"debug\":true}"})
 turn 6 read_file({"path":"config.json"})

Exact duplicates: 1
 search({"query":"config"}) (turn 1) repeats search({"query":"config"}) (turn 1)

Semantic duplicates: 1
 get_user({"id":"5"}) (turn 2) repeats get_user({"id":5}) (turn 2)

Stale re-fetches: 1
 read_file({"path":"config.json"}) (turn 3) repeats read_file({"path":"config.json"}) (turn 2)

Call counts: { total: 9, search: 2, read_file: 4, get_user: 2, write_file: 1 }

Reading it top to bottom is the whole argument for tracing in one screen. The two searches in turn one are flagged as an exact duplicate. The two user fetches in turn two are flagged as semantic, and the output shows the raw keys so it is obvious that the only difference is a string versus a number. The read in turn three is flagged as stale against the read in turn two. The read in turn six, after the write in turn five, is not flagged anywhere. And the call count at the bottom says nine where the well-behaved run says four. Running the same script against the well-behaved fixture produces four lines of trace, three zeros, and a total of four.

What Not to Flag

A redundancy test that fires on legitimate behavior gets loosened or deleted within a week, so the cases the detectors deliberately ignore deserve as much attention as the ones they catch. Two of them are built into the demo and tested. The first has already come up: a read that follows a write to the same resource. The stale re-fetch detector handles this by treating any mutating call as the new last event for that resource, so the read after it compares against a write, not a read, and passes. The second test in the suite exists purely to pin this down. It runs the well-behaved fixture, confirms that config.json was read twice, and asserts that the stale re-fetch detector still returns nothing.

The second case is retries. Real tools fail for reasons that have nothing to do with the model: a search backend times out, a rate limit trips, a connection resets. A sensible harness retries those, and from the tool's point of view the retry looks exactly like a duplicate call. If the tracer recorded it as one, the tests would fail whenever the infrastructure had a bad moment, which is precisely the flakiness that gets a test suite ignored. The fix is to make the harness say who asked. When the loop catches a transient error and calls the tool again, it passes an origin tag through the wrapped tool's optional second parameter, and the tracer stores it on the record.

                
function invokeWithRetry(tool, args) {
  try {
    return tool.run(args);
  } catch (err) {
    if (err instanceof TransientError) return tool.run(args, { origin: 'harness-retry' });
    throw err;
  }
}
                

The detectors then filter on that tag before doing anything else, which is what the modelCalls helper from earlier does. A harness retry is never a duplicate, never a stale re-fetch, and never counts toward the budget, because the model made one request and the harness made the second. The failed attempt is still in the trace, marked as failed, so nothing is hidden. It is just attributed correctly. The demo's third fixture sets up a world where the first search will throw a transient error, and the test checks that the trace contains both attempts, that only the second one is tagged as a retry, and that the model's call count is one.

                
test('harness retries after a transient error are not counted as duplicates', () => {
  const { trace } = runFixture('transient-retry');

  assert.equal(trace.length, 2, 'one failed attempt plus one retry');
  assert.equal(trace[0].ok, false);
  assert.equal(trace[1].origin, 'harness-retry');
  assert.equal(findExactDuplicates(trace).length, 0);
  assert.equal(callCounts(trace).total, 1);
});
                

There is a third case that the demo does not try to handle, and it is worth naming so nobody expects the detectors to do more than they can. Two searches with different wording that return the same results are arguably redundant, and a model that phrases the same question three ways is wasting calls. But deciding that from the trace requires either comparing result hashes, which flags any two calls that happen to return the same thing, or judging whether the queries mean the same thing, which is not something a deterministic test should attempt. Argument normalization catches equivalence by construction. It does not catch equivalence by intent, and the line between the two is where these tests stop.

Running It Against a Real Model

Everything so far has run with the model scripted out, and that is where most of the value is: fast, deterministic tests that guard the harness against regressions. But the question that started this post was about real agents, and the tracer was built so that swapping the scripted model for a real one changes nothing else. The model function receives the context and returns a step. Whether that step came from a JSON fixture or from parsing tool-use blocks out of an API response is invisible to the loop, the tracer, and the detectors. One model response with several tool calls in it is one turn, exactly as in the fixtures.

What does change is how the results should be read. A scripted run either has a duplicate or it does not. A real model is sampled, and the same task run ten times will produce ten slightly different traces. Some of the checks survive that well. An exact duplicate within a single turn is a hard failure at any temperature, because there is no reading of it that is intentional, and it is reasonable to fail a run on it outright. The stale re-fetch and budget checks are different. A model might re-read a file on two runs out of ten because its plan happened to go a different way, and failing the build on that would make the suite as flaky as the model.

The way to handle this is to stop treating those checks as pass/fail and start treating them as a metric. Run the task some fixed number of times, collect the call count and the number of stale re-fetches from each run, and compare the distribution against a baseline recorded when the harness was known to be healthy. A median that moves from four calls to six, or a stale re-fetch rate that goes from one in ten to five in ten, is a regression even if no single run would have failed a hard assertion. This is the same shift from binary to statistical that golden datasets and LLM-as-judge setups go through, and for the same reason.

Two practical notes. First, these runs cost real money and real time, so they belong in a nightly or pre-release job rather than on every commit, while the scripted tests stay in the fast suite that runs everywhere. Second, when a real run does trip a threshold, save its trace. The tracer's records are plain objects that serialize to JSON without any work, and a captured trace from a bad run is exactly the shape the fixtures already use. Dropping it into the fixture directory turns a one-off observation into a permanent regression test that runs in milliseconds, and the next time someone rewords the system prompt or the provider ships a new model version, that test is the one that catches it.

Conclusion

Redundant tool calls are the kind of problem that stays invisible for as long as you only check the answer. The agent completes the task, the outcome test passes, and the fact that it took nine calls instead of four shows up nowhere except the bill. The fix is not a smarter assertion on the outcome. It is recording the path and asserting on that, which turns out to need very little: a wrapper around the tool registry, two pieces of metadata per tool, and a few dozen lines of detectors that know the difference between a repeat, an equivalent, a stale read, and a verify-after-write.

The most important design decision is the one that keeps the model out of the fast suite. The harness is deterministic and the model is not, so testing them together means every test inherits the model's variance. Scripting the decisions and tracing the execution gives you tests that run in milliseconds, need no API key, and fail for exactly one reason. The real model then gets its own slower, statistical job, and any run it flags becomes a fixture for the fast one.

The complete example is available on our GitHub page. It has no dependencies, so cloning it and running npm test is the whole setup. The useful next step is to point the tracer at your own harness, capture a trace from a task you run often, and print it. Most teams that do this find at least one call they did not know was there.