Six silent bugs in a voice AI phone line

This is a submission for DEV's Summer Bug Smash: Clear the Lineup powered by Sentry.

The agent said goodbye and then stayed on the line for 566 seconds. That was the loudest of six bugs that all returned successfully, logged an OK, and kept running, six PRs, and the traces for each.

Project Overview

Ovela answers the phone for a motel in regional Victoria. A guest dials a landline, and five things have to happen before the agent can say a word:

• the phone network hands me the caller's audio (Twilio)
• something decides when the caller has actually stopped talking, as opposed to pausing (Deepgram)
• a model decides what to say, and which of 12 tools to call (OpenAI)
• something turns that text into speech (Cartesia)
• it goes back down the phone line

All of it inside 800 ms. Past about a second, people say "hello?" and start talking over the agent. There is no spinner on a phone call, and no way to say "still thinking".

Two words you will need. A turn is one round trip - caller speaks, agent answers and it is the unit everything here is measured in. Barge-in is the caller talking over the agent, which has to cut the agent off mid-word, the way a human would stop talking if you interrupted them.

That deadline is why these bugs were expensive, and the deadline is also why none of them looked like bugs.

Bug Fix or Performance Improvement

Start with the one that would not let a caller off the phone.

The agent has a tool for ending a call. It returned this:

{"action": "hangup", "message": "Thanks for calling, goodbye!"}

Nothing read action.

When a model calls a tool, you run the function and hand the return value back to the model as text, and it carries on from there. That is the tool loop, and mine passed this whole dict straight through. The model found message, said goodbye — warmly, in the right tone, at the right moment. Then the line stayed open.

Here is one call, laid out from Twilio's record and Sentry's turn timeline:

01:06:15   call answered
01:07:46   1:31  caller says goodbye, agent says goodbye back
              …  475 seconds of an open line. Three turns fire in that
                 stretch, all on room noise, none of them a conversation.
01:15:41   9:26  the caller gives up and hangs up the phone themselves

Sentry has the hole. Each row is one turn; the last column is the start time in seconds, so the spacing is the conversation:

b82b0208   1.48s    1,786,756,066.3304   ← the goodbye
aa847306   1.48s    1,786,756,379.7518   ← the next thing that fired
                    ─────────────────────
                              313 seconds

The rows above those two are spaced 12, 11, 8, 12, 12, 7, 13, 7 and 3 seconds apart. Then 313.

566 seconds, and the agent ended none of it. transfer_to_staff had the identical defect — it promised a transfer that never dialled.

Read the transcript and the call is perfect. Read the logs and everything succeeded. The only places it looks wrong are the carrier's billing record and a five-minute hole in a column of timestamps.

Reconstructing that call took a Twilio record and thirteen unrelated Sentry traces, because in August each turn was its own trace with nothing tying them together. That is exactly what PR #11 fixes: the same call today arrives as one conversation, in one view.

That is the shape of every serious bug in this system. They return, they log an OK, they keep running. Here are four more of the same family, all from the provider boundary:

What the provider told me	What I did with it	What the caller heard
UNPARSABLE_CLIENT_MESSAGE: unknown field 'processors', expected 'thresholds'	dropped	25 seconds of silence
400 unsupported encoding for raw: mulaw (correct: pcm_mulaw)	dropped	only the cached greeting was ever real speech
sonic-english sunsetted → a second 400 behind the first	dropped	same
TurnInfo carries its state in event; I read type	matched nothing	barge-in never fired, and neither did the early nudge to the model that starts it thinking before the caller finishes

Each of those arrived on a WebSocket as an ordinary message and hit an if/elif chain with no else. Parsed, matched nothing, discarded. The socket stayed open. Audio kept flowing in. Nothing came back, and every health check in the system stayed green, because every component genuinely was up.

Two more, once the telemetry was honest enough to find them:

The tenant lookup 404'd on every single call. It queried by document ID; the rows are keyed by slug. It failed, fell through to the correct query, succeeded, and logged success — while spending 4,316 ms on the critical path of the first turn. A slow path that is also a working one is the hardest kind to notice.

One booking was looked up eight times in a single call, because nothing remembered the answer to a question the caller had not changed. One database round trip is about 250 ms; a single lookup_booking makes up to three of them in sequence includes phone, then name, then a hundred-row scan to redo the name match case insensitively - so a miss costs 1.1 to 1.6 seconds.

Code

Six PRs, stacked, each one reviewable on its own:

PR
#7 Make the provider bridges speak the APIs the providers actually run	the four dropped errors, and a finally that ran on every break
#8 Stop the agent interrupting itself	barge-in armed before any audio existed; chunks from an abandoned turn
#9 Drive the turn from the orchestrator	a design change, not a fix
#10 Execute control-flow tool actions, kill the cold start	the 566-second call; 4,316 ms → 12 ms
#11 Repair the telemetry, group the call as one conversation	a span measuring 0.01 ms; a span hiding 84% of a turn
#12 Stop paying for work already done	prompt cache missed every turn; eight identical lookups

#9 is the odd one out, and its commit message says so in the first line: it is not a bug fix. It moves the live conversation off a multi-agent graph and into a direct streaming call. The graph routes work between a Manager and two workers — worth its latency for background jobs, not for someone waiting mid-sentence. Under the real payload it cost 2,810 ms to first token against 1,040 ms direct.

Everything else in that table is the same bug wearing different clothes: a message arrived, nothing was listening, and the system reported success. A dropped provider error, an action field with no reader, a span opened and closed on the same line, an environment tag never set. Same shape, six times.

My Improvements

Hanging up without cutting off the goodbye.

The obvious fix is to terminate the call the moment the tool fires — and then the caller never hears the farewell, because the line drops mid-word. So the intent is recorded, the audio finishes draining, and only then does the call end:

if result.get("action") == "hangup":
    self._pending_hangup = True

finally:
    interrupted = self.state != ConversationState.AGENT_SPEAKING
    if self._pending_hangup:
        self._pending_hangup = False
        if interrupted:
            logger.info("🛑 Hangup aborted — user spoke during farewell")
        else:
            await self._hangup_call()

If the caller starts speaking during the goodbye, they have changed their mind, and hanging up on them would be worse than the original bug. The termination is also idempotent — because a tool with no observable effect gets retried by the model, which is how the bug announced itself in the first place.

Caching the task, not the result.

The repeated booking lookup got a per-call memo. The detail that matters is one line:

task = self._cache.get(key)
if task is None:
    # Cache the task, not the result: the prefetch and the first tool call
    # race for the same row, and the loser must join the in-flight request
    # instead of issuing a second one.
    task = asyncio.ensure_future(self._db.lookup_motel_reservation(**kwargs))
    self._cache[key] = task

If you cache the finished value, both racers find an empty cache and both hit the database. Caching the unfinished task makes the second one wait on the first. Invalidation uses a read-only allowlist, so a tool added next month that writes a booking will be slow before it is wrong.

Two lines at the front of a prompt.

The other half of that PR is smaller and I nearly left it out. A volatile header — the current date and time — sat at the very start of a ~9,000-token system prompt. The prefix therefore changed on every single turn, so none of it could ever be reused. Moving it to the end was a two-line diff:

- return f"""{context_header}You're the AI receptionist for Coal Creek Motel...
+ return f"""You're the AI receptionist for Coal Creek Motel...
+ {context_header}"""

Cached prompt tokens are billed at a discount and, more to the point here, skip re-processing — so this is both cheaper and quicker to first token. Sentry reads the result straight off the model call: 178 new tokens, 8.9K served from cache, 32 out — 98% of the prompt reused on a turn budgeted at 800 ms end to end.

What the memo did, stated precisely. Two live calls, one either side of the fix, paired trace by trace:

	before (8 calls)	after (7 calls)
Queries that actually ran	8 of 8	4 of 7
Resolved from an in-flight task	0	3, at ~0.1 ms
Median of the queries that still ran	1,263 ms	1,136 ms
Total query wait per call	11,049 ms	4,496 ms

Look at the third row, because it says what this fix is not. A memo cannot make a database query faster, and it didn't. The 59% saving is entirely the three queries that stopped happening.

Elsewhere: cold start 4,316 ms → 12 ms — that pair came from Heroku startup logs at the time, which have since rotated, so it is the one number here with no artifact behind it. Conversational turns land at 400–890 ms, median 790 ms across 28 consecutive turns. There is no before-figure for that median, and I am not going to manufacture one — before these fixes the pipeline never reached a second turn, so there was nothing to time.

Best Use of Sentry

Sentry found the latency bugs, and one I shipped myself halfway through. It is not the place I reported them from afterwards.

The span that was lying to me. A span is a stopwatch around one stage of a request; nest them and a turn arrives as a waterfall instead of a single number. Mine covered "user speech ended → tool executed", which turned out to be far too much ground for one stopwatch. Across the 25 pre-fix turns still inside Sentry's retention window it held a median 84% of turn time. Here is one of them: 5.29 seconds of a 5.52 second turn in a single bar, with the only other span reading 0.01 ms, because it was opened and closed on the same line.

I read that 84% and concluded the model was slow, because the model was what I already suspected. Splitting it into llm.stream per model round and gen_ai.execute_tool per tool inverted the answer immediately:

A 2.02 s turn: 538 ms model round, 506 ms tool call, 407 ms second model round, 268 ms of speech synthesis. (Different turn, different length — compare the shape, not the totals.) I had spent a day blaming the language model. It was a database round trip.

One phone call, one conversation. The pipeline emits Sentry's gen_ai.* conventions with the Twilio CallSid as the conversation id:

from sentry_sdk.ai import set_conversation_id

if self.call_sid:
    set_conversation_id(self.call_sid)

One line, and the dashboard stopped being a latency chart. This is a real call - the caller's words, the tool the agent reached for, the arguments it passed, and the cost of each:

lookup_booking  guest_name: "Drew Patel"    1.72 s     ← the real query
lookup_booking  guest_name: "Drew Patel"    0.08 ms    ← memo
lookup_booking  guest_name: "Drew Patel"    0.09 ms    ← memo

That screenshot also contains a bug I have not fixed. Look at the turn where the caller spells their name — B h r u v p a t e l — and the very next lookup still goes out as "Drew Patel". The memo did its job: same question in, cached answer back. The model never updated the argument after being corrected. A cache is only ever as right as the question it is asked, and that one is next on my list as UX work.

Sentry also caught me. While adding those tool spans I shipped this:

transaction.start_child(op="gen_ai.execute_tool", attributes={...})
# TypeError: Span.__init__() got an unexpected keyword argument 'attributes'

start_child() takes no attributes. My unit test passed because it used a MagicMock, and a MagicMock accepts every keyword argument you invent. Someone called the number ten minutes later and every tool call on that call failed.

I found it in the issue before the call had ended, and rewrote the test against a real Transaction subclass — then proved the new test fails against the broken version. A mock at a provider boundary tests your assumption. The provider's contract is somewhere else, and it does not care what your mock agreed to.

Also in Sentry, also mine: sentry_sdk.init() never passed an environment, so every event arrived tagged production — including the ones my own test suite raised on every run. PR #7 sets it and blanks the DSN in conftest.py. That is why every screenshot here reads environment: demo: it is the live service, labelled correctly for the first time.

I could not run Seer Autofix. I asked Sentry support, including about the bugsmash26 credits but needs a paid plan and the credits do not unlock it on a free-tier org. So there is no RCA screenshot here. The conversation view above is what I used instead, and it is the artifact that showed me the tool firing three times.

Best Use of Google AI

Gemini 2.5 Flash reads the traces after every call, without being asked. When Twilio posts a completed callback, a watchdog waits two minutes for spans to land, pulls them from Sentry's API, aggregates them per span name, and hands the numbers to Gemini with the pipeline architecture as context. It replies in strict JSON.

Here is a real run: the whole file is in the repo, including the two root causes I trimmed for space:

{
  "bottleneck_span": "Span 1: User Speech Ended -> First Token Yielded",
  "bottleneck_share_pct": 88,
  "root_causes": [
    "Excessive latency in specific tool executions: The `perform_live_search`
     tool has an extremely high median latency of 2126.73 ms, and other tools
     like `check_availability` and `lookup_booking` also add ~500 ms when
     invoked."
  ],
  "verdict": "The pipeline currently does not meet the sub-800ms TTFA target,
              with a median `user_voice_turn_transaction` of 952.18 ms."
}

Here is the honest shape of this system, stated once: a turn with no tool call lands at ~790 ms median across 28 turns. A turn that hits the database lands around 950 ms. The 800 ms budget is met on conversation and missed on lookups — which is exactly what the analyser flags, unprompted, after every call, because that window mixes both kinds of turn together.

It also flagged perform_live_search at 2,126 ms — on two samples, so a median of two points is just the slower one. The analyser did not mention that, and I will.

What Gemini does not do here is fix files, and it has not yet found a root cause I did not already have. It reads production telemetry and says where to look, unprompted, after every call. That step used to cost me a day per bug. A span that regresses more than 40% against the previous run raises a Sentry message; nobody has to open a chart.

Google ADK still runs the cold path, and that is exactly why PR #9 exists. The graph was driving the live conversation, and it was never built for that: it routes work between a Manager, a BookingWorker and an InfoWorker, which is worth its latency in the background and not worth it to someone waiting mid-sentence. Measured under the payload actually shipped a ~9,500-token prompt with 12 tool definitions — the direct streaming call reached first token in 1,040 ms against 2,810 ms. On a bare "hello" the ranking reverses, which is precisely why the benchmark that counts is the real payload, and why a day of my optimisation went the wrong way before I understood that.

So Gemini does the analysis and the background reasoning, and does not drive the conversation, because the measurement said not to.

Every number above was read out of Sentry after a call placed over the phone network📞.

here's what the latency sounds like: click to hear