Tool Calling That “Works” But Never Executes (Silent Failure After HTTP 200)

#ai #api #llm #python

Tool calling failures are the silent killers of LLM apps. Your API call returns HTTP 200, the model outputs a tool call, and everything looks “fine”… until users get an answer that’s missing the actual data—empty, guessed, stale, or half-formed.

The annoying part: most teams only log the top-level completion. They don’t log the tool lifecycle. So you end up debugging uncertainty instead of root cause.

In this post, I’ll show you a logging schema that answers one question with confidence:

Did the tool call get parsed, executed, and fed back into the model—before we rendered the final answer?

Why tool calling can fail while the request “succeeds”

A logical “chat completion” can succeed while the tool chain doesn’t. Common failure modes:

The model outputs a tool call, but your server skips execution
Tool arguments parse fails, so you fall back to a non-tool path (but still return an answer)
The tool executes, but you never send the tool result back to the model
You send it back, but the callback fails, times out, or throws, so the second model call doesn’t happen
Streaming vs non-streaming changes the event ordering, so your state machine marks the flow as “done” too early
Retries/fallback happen and hide the original tool failure

If your logs don’t cover the tool lifecycle, you can’t tell the difference between:

“The model decided not to use tools”
vs “It tried to use tools, but your system dropped the execution”

The logging schema: make tool calling debuggable

For every logical tool call (not just every LLM request), log enough to answer:

Was a tool call produced?
Were the tool arguments parsed successfully?
Did we execute the tool?
Did we send tool results back to the model?
Did we end with an answer that depended on the tool?

1) Tool call successfully executed and returned to the model

{
  "event": "llm_tool_call",
  "request_id": "req_201",
  "tool_call_id": "call_abc",
  "provider": "YOUR_PROVIDER",
  "model": "gpt-4.1-mini",
  "operation": "tool_call",

  "tool_name": "search_knowledge_base",
  "tool_arguments_parse_status": "parsed",
  "tool_execution_status": "success",
  "tool_result_hash": "sha256:…",
  "tool_result_size_bytes": 18231,

  "callback_to_model_status": "sent",
  "callback_attempt": 1,

  "final_assistant_status": "tool_ran_then_answered",

  "retry_count": 0,
  "fallback_from": null,
  "fallback_to": null
}

2) Tool call exists, but arguments fail to parse (execution skipped)

{
  "event": "llm_tool_call",
  "request_id": "req_202",
  "tool_call_id": "call_def",
  "provider": "YOUR_PROVIDER",
  "model": "gpt-4.1-mini",
  "operation": "tool_call",

  "tool_name": "get_customer_profile",
  "tool_arguments_parse_status": "failed",
  "tool_execution_status": "skipped",

  "tool_result_hash": null,
  "tool_result_size_bytes": 0,

  "callback_to_model_status": "not_sent",

  "final_assistant_status": "answer_without_tool",
  "error_type": "tool_arguments_parse_failed",
  "error_message": "Invalid JSON in tool arguments",

  "retry_count": 0,
  "fallback_from": null,
  "fallback_to": "backup-model"
}

3) Tool executed, but tool result callback to model failed

{
  "event": "llm_tool_call",
  "request_id": "req_203",
  "tool_call_id": "call_xyz",
  "provider": "YOUR_PROVIDER",
  "model": "gpt-4.1-mini",
  "operation": "tool_call",

  "tool_name": "fetch_order_status",
  "tool_arguments_parse_status": "parsed",
  "tool_execution_status": "success",

  "tool_result_hash": "sha256:…",
  "tool_result_size_bytes": 4021,

  "callback_to_model_status": "failed",
  "callback_attempt": 2,

  "final_assistant_status": "tool_ran_but_no_followup_answer",
  "error_type": "callback_to_model_failed",
  "error_message": "Timeout while calling model follow-up",

  "retry_count": 1,
  "fallback_from": "gpt-4.1-mini",
  "fallback_to": "backup-model"
}

Key point: you’re not logging “the model output.” You’re logging the tool chain state. That’s what turns “mystery UX” into a deterministic diagnosis.

The two most common “it looks fine” illusions

Illusion A: tool call exists, but execution got skipped

Symptom: answers are generic, missing facts, or reference “I don’t have enough data.”
Log tell: tool_execution_status="skipped" while tool_arguments_parse_status is failed/unknown or your state machine decided to bypass tools.

Illusion B: tool executed, but result never got fed back

Symptom: model hallucinates the result or repeats the same question (“I need the tool output…”).
Log tell: tool_execution_status="success" but callback_to_model_status!="sent".

Minimal wrapper logic (Node.js): enforce lifecycle ordering

You don’t need a complex observability platform. You need a state machine that logs transitions.

Below is a compact pattern you can adapt. It assumes you already have:

a function to parse tool arguments
a tool executor
a function to call the model again with tool results

function logEvent(evt) {
  console.log(JSON.stringify(evt));
}

async function handleToolCall({
  requestId,
  provider,
  model,
  toolCall,
  executeTool,
  callbackToModel,
  retryCount = 0,
  fallbackFrom = null,
  fallbackTo = null
}) {
  const tool_call_id = toolCall.id;
  const tool_name = toolCall.name;

  // 1) Parse arguments
  let parsed = null;
  let parseStatus = "unknown";
  let parseError = null;

  try {
    parsed = JSON.parse(toolCall.arguments);
    parseStatus = "parsed";
  } catch (e) {
    parseStatus = "failed";
    parseError = String(e?.message || e);
  }

  if (parseStatus !== "parsed") {
    logEvent({
      event: "llm_tool_call",
      request_id: requestId,
      tool_call_id,
      provider,
      model,
      operation: "tool_call",
      tool_name,
      tool_arguments_parse_status: parseStatus,
      tool_execution_status: "skipped",
      tool_result_hash: null,
      tool_result_size_bytes: 0,
      callback_to_model_status: "not_sent",
      final_assistant_status: "answer_without_tool",
      error_type: "tool_arguments_parse_failed",
      error_message: parseError,
      retry_count: retryCount,
      fallback_from: fallbackFrom,
      fallback_to: fallbackTo
    });

    return { ok: false, reason: "parse_failed" };
  }

  // 2) Execute tool
  let result;
  let execStatus = "unknown";
  let execError = null;

  try {
    result = await executeTool(tool_name, parsed);
    execStatus = "success";
  } catch (e) {
    execStatus = "error";
    execError = String(e?.message || e);
  }

  if (execStatus !== "success") {
    logEvent({
      event: "llm_tool_call",
      request_id: requestId,
      tool_call_id,
      provider,
      model,
      operation: "tool_call",
      tool_name,
      tool_arguments_parse_status: "parsed",
      tool_execution_status: execStatus,
      tool_result_hash: null,
      tool_result_size_bytes: 0,
      callback_to_model_status: "not_sent",
      final_assistant_status: "tool_failed_no_result",
      error_type: "tool_execution_failed",
      error_message: execError,
      retry_count: retryCount,
      fallback_from: fallbackFrom,
      fallback_to: fallbackTo
    });

    return { ok: false, reason: "tool_execution_failed" };
  }

  // Optional: compute hash/size for privacy-safe summaries
  const resultSizeBytes = Buffer.byteLength(
    JSON.stringify(result || {})
  );

  // 3) Callback tool result to the model
  let callbackStatus = "unknown";
  let callbackError = null;

  try {
    await callbackToModel({ requestId, model, tool_call_id, result });
    callbackStatus = "sent";
  } catch (e) {
    callbackStatus = "failed";
    callbackError = String(e?.message || e);
  }

  logEvent({
    event: "llm_tool_call",
    request_id: requestId,
    tool_call_id,
    provider,
    model,
    operation: "tool_call",
    tool_name,
    tool_arguments_parse_status: "parsed",
    tool_execution_status: "success",
    tool_result_hash: "sha256:…",
    tool_result_size_bytes: resultSizeBytes,
    callback_to_model_status: callbackStatus,
    callback_attempt: 1,
    final_assistant_status:
      callbackStatus === "sent"
        ? "tool_ran_then_answered"
        : "tool_ran_but_no_followup_answer",
    error_type: callbackStatus === "sent" ? null : "callback_to_model_failed",
    error_message: callbackStatus === "sent" ? null : callbackError,
    retry_count: retryCount,
    fallback_from: fallbackFrom,
    fallback_to: fallbackTo
  });

  return { ok: callbackStatus === "sent", reason: callbackStatus };
}

If you implement only one thing from this post: log tool lifecycle transitions and make final assistant status depend on tool callback success.

Monitoring: alerts you actually care about

Pick a few metrics that correlate directly with broken UX:

tool_call_present_rate (baseline per route/feature)
tool_call_executed_rate (if this drops, you skip execution)
tool_arguments_parse_failed_rate (if this spikes, tool args schema drift)
tool_callback_failed_rate (if this spikes, follow-up model call is broken)
answer_without_tool_rate (often the fastest UX damage indicator)

You’re hunting for regressions that look like: HTTP 200 is fine, but the tool chain isn’t.

Closing thought

Tool calling isn’t reliable just because you got a tool call out of the model.

It’s reliable only when you: parse → execute → callback → then render an answer that actually used the result.

If your logs don’t tell that story, you’ll keep hearing “it worked but the answer was wrong.”

tokenbay: https://www.tokenbay.com/?utm_source=devto&utm_medium=community_content&utm_campaign=week1_free_content