*By Nikša Perović, 6 Oct 2026. Source: https://niksa.me/logs-told-me-a-lie.*

Agents · 5 min read

# My Logs Told Me a Lie. I Believed It.

I read a run of log lines from a live production capture and concluded my agent was running the expensive setup.

It wasn't.

The logs weren't wrong exactly. They were missing the one piece of information I needed to interpret them correctly.

I wrote down the conclusion. I was ready to act on it.

Plain terms: on off Short explanations for non-engineers, in the dashed yellow boxes. Engineers can switch them off.

## 01 The setup

Tools on this server sat behind domains, and a domain had to be "unlocked" before anything in it became callable. A server setting decided how that worked. All-tools (`all` in the config) opened every domain from the start. On-demand (`primary`, the default) opened them one at a time, as needed.

On top of that sat a separate layer, not a third mode: deferred tool loading, done client-side. Instead of carrying every tool description in context, the agent looks one up by name when it needs it. It needs the full tool list to work from, so the intended pairing is deferred loading on top of all-tools. Once it's doing its job, the server's own unlocking has nothing left to do. Worse, every on-demand unlock that opens something new changes the tool list, and each change costs the client a cache extension. So on-demand under deferred loading is the expensive combination.

When the unlock logic ran, the system logged one line:

```
[unlock] declared (domain) -> reports
```

That line fired whether or not the unlock did anything. Under all-tools, every domain was already open, so "unlocking" one changed nothing. Under on-demand, re-unlocking a domain that had opened earlier in the session was also a no-op. Both cases, same line.

```
[unlock] declared (domain) -> reports   # a domain just became visible[unlock] declared (domain) -> reports   # a domain that was already visible, again
```

Read it the way the log does Show what actually happened

Byte-identical. No way to read the log and know which one had happened.

It also skipped the shared structured logger entirely: no timestamp, no request ID, no session ID on any of it. With one session running you'd never notice. In production, with sessions running concurrently, there was no way to tell which session any given line belonged to, let alone which of the two situations it represented.

Plain terms A shared tool that stamps every log line with context automatically: time, session, request. Skip it once, in one function, and that one line goes out with the message but none of the context.

## 02 Where it broke

The story from the top came from a run of these lines: I concluded the agent was on on-demand, when it should have been on all-tools under deferred loading. I ran it past an AI, and it agreed. The story had a hole neither of us checked. Production was running all-tools, which is what it should have been running. The information to know that wasn't missing from the system: a health endpoint had reported the active mode the day before I read the capture. It just wasn't on the line I was looking at.

The line wasn't false. It said the unlock logic ran, and it had. I was asking a different question: did anything become visible?

Nothing about the line itself would have stopped me from reaching the wrong conclusion. No field naming which mode was active. No flag telling a real unlock apart from a no-op. Just a message that read the same whether something had happened or nothing had, and I filled in the difference myself, wrong.

## 03 The fix

```
before:  [unlock] declared (domain) -> reports
after:   unlock  source: declared  granularity: domain  unlocked: [reports]
         mode: all  changedVisibility: false  requestId: …  session: …
```

The fix turned it into a structured entry with the missing context on it: whether the unlock changed anything, which mode was active, and the request and session IDs the original never had.

None of it was hard to build. It wasn't built because the original line looked fine.

Silence would have sent me to look closer. A line that looks informative but isn't tells you you already know, and you don't.

## 04 Three fixes in 27 hours

1. First, in the client, a cache-miss counter that fired on every lookup, whether anything new had to load or not.
2. Then a server that logged 358 requests over 26 hours without a single error, while one of its tools was failing roughly three calls in four, because a failure inside an MCP tool still comes back as a normal, successful response one layer up.

   Plain terms MCP (Model Context Protocol) is the open standard letting an AI agent discover and call tools in outside systems.

   Plain terms Tools run over the same protocol as a webpage load. A failure inside the tool's own logic can still register as a successful delivery one layer up, the way a truck can log a completed drop-off for a package that arrived broken.
3. Then this one, the unlock line that couldn't tell a real change from a no-op.

Three different mechanisms. Same failure as the unlock line: the signal was emitted at a lower level than the question I was trying to answer.

- A lookup happened, but I wanted to know whether something loaded.
- A request succeeded, but I wanted to know whether the tool operation succeeded.
- An unlock was declared, but I wanted to know whether visibility changed.

I'd fixed this exact shape in the client the day before, and I still didn't recognize it one layer over. The unlock fix landed about six hours after the tool-failure one, in the same server.

Fixing the line in front of you doesn't touch the pattern behind it.