Shihao Qi
← Writing

LLM Request Observability: Logs Count Messages, and the Native Tools Schema Shows Up Nowhere

4 min read#LLM#Python#Observability#Autarkia

With native function calling, tool definitions go in the tools parameter, not in messages. A log that measures message length can’t see them, and streaming responses omit usage by default. Autarkia sent 82 tools and 47,898 characters of schema every turn while the prompt log showed about 2,200 characters; the API counted 21k–23k tokens.

Table of Contents

With native function calling through an OpenAI-compatible API, each tool’s JSON schema goes in the request’s tools parameter, alongside messages. It counts toward prompt tokens like message text, but it isn’t in messages: a log that measures message length can’t see it, and neither can a printed prompt. Streaming responses also omit usage by default; you only get real prompt_tokens if you pass stream_options={"include_usage": True}. Put the three together and the cost of tool definitions can stay out of every log.

That is what happened in Autarkia. In August it started recording the usage the API returns, and a week later the stats showed the main chat at 21k–23k prompt tokens per turn. But the prompt I could see was about 2,200 characters: the assembly log CompleteMessageList: StaticLen=… had always been around that, and so was the printed system prompt. The difference was the tool definitions: every turn at the time carried 82 tools, 47,898 characters once serialized.

01Two kinds of active_tools

The odd part is that picking tools per message was already implemented. Before the prompt was assembled, prepare_active_tools() started from a few resident tools and added more by keyword; ordinary chat ended up with four:

python
# context_persona.py：拼 prompt 用
async def prepare_active_tools(agent, message, model_hint) -> List[str]:
    active_tools = ["get_current_time", "calculator", "text_to_speech"]
    # ……加 web_search，再按关键词路由
    return active_tools

The code that actually sent the request lived in another file. It did not use the list computed above; it went to the registry itself:

python
# model_resolution.py：发请求用
native_tool_names = agent.tool_registry.get_active_tools()
native_tool_names = filter_tool_names(native_tool_names, ...)
openai_tools = agent.tool_registry.get_openai_tools(include_names=native_tool_names)

# registry.py
def get_active_tools(self) -> List[str]:
    """Return currently enabled tool names."""
    return [name for name in self._tools if self.is_enabled(name)]

Both functions say active tools, and they mean different things. In prepare_active_tools() active means needed this turn; in ToolRegistry.get_active_tools() it means not disabled in the registry. Reading the send path, get_active_tools() looks exactly like this turn’s tools, and nothing gives you a reason to stop.

02Why nobody noticed

  • Every visible number measured the other list. The prompt text really did describe only those four tools, and the length log counted only messages, so everything that could be printed matched expectations.
  • The send side did log [Native Tools] Registered 82 tools for function calling, but only the count, not the size. Tools were added one at a time: about 45 on June 18, 66 on August 3, 81 on August 26. The number never jumped.
  • On June 30 someone changed that exact line, because certain tools should not be visible in certain contexts, and wrapped get_active_tools() in filter_tool_names(). After that the line looked handled, and nobody asked why it started from the full set.
  • Before August 16 there was no real token count anywhere locally. When recording started it still missed streaming requests: OpenAI-compatible streaming responses omit usage unless you pass stream_options={"include_usage": True}, and the main chat is streamed. Only after adding that did the twenty-thousand-plus show up.

There was also a duplicate: cloud models received a condensed tool list in the prompt text on top of the native schemas, so the same tools were described twice.

03The fix

The August 24 fix computes this turn’s tools once: the streaming preparation step produces active_tools, prompt assembly and the request share it, and prepare_native_tools() now takes that list. Cloud models no longer get the text tool list, and the send log gained schema_chars. Later a resident search_tools was added: when the model needs another tool it searches first, and only the matches get their schemas appended next round. Ordinary chat went from 83 tools and 48,311 characters to 5 tools and 1,870.

Looking at the code again recently, a few things are still loose:

  • ToolRegistry.get_active_tools() still has that name and three call sites. I plan to rename it get_enabled_tools().
  • The second call to prepare_native_tools(), after tool discovery, omits mode. Its default is "chat", so in other modes the second round filters by chat-mode rules. The parameter should lose its default so a missing argument fails loudly.
  • Streaming and non-streaming each have their own copy of the tool selection logic, and both this fix and the June one had to be applied twice.
  • Message length and schema length are still logged on separate lines. The total size of a request should be one line, written where the client is called, next to the returned prompt_tokens.

Related

Generator Exceptions Surface on the First next(): try Around create_chat_completion(stream=True) Never Sees the Context Window Error2026-11-08Calling a generator function only builds a generator; the body, including any raise in it, runs on the first next(). llama-cpp-python checks the context window inside such a body, so the try around a streaming call, and the shrink-and-retry under it, never fire with the real library. The test double raised at call time, so the tests passed with 100% coverage.#Python#LLM#Error Handling#Testing#AutarkiaOne pop() in a subclass payload builder: max_tokens deleted before sending, invisible to callers, logs and tests2026-10-21The parent class builds the request body, the subclass pops a field before returning it, and whatever the caller passes stops mattering without any error. Autarkia’s MiniMax client has deleted every caller’s max_tokens since the first commit, leaving a reasoning model with no output ceiling, and it was mentioned three times in my notes without being changed.#Python#LLM#ObservabilityFiltering kwargs with inspect.signature: a function that takes **kwargs looks like it accepts nothing, and a retry lost its model_path2026-11-08inspect.signature(f).parameters lists only declared parameters; **kwargs shows up as a single entry named kwargs. Checking by name whether a callee accepts an argument lets nothing through to the most permissive function. Autarkia’s empty-reply retry lost its model_path this way and fell back to the default model; the resulting 400s landed among upstream 503s, and that day’s error triage filed them as gateway noise.#Python#LLM#Debugging
← Back to writing