AI エージェントの tool 呼び出しを request_id で追えるようにした

はじめに: agent のログで迷子になった

AI Agent を業務アプリに入れ始めると、1 回の実行が思ったより細かく分かれます。

最初に LLM で次の行動を決める。社内 API や検索 tool を呼ぶ。tool 結果を LLM に戻す。必要なら別の tool を呼ぶ。最後にユーザー向けの文をまとめる。

この流れ自体は自然なのですが、失敗したときに私は少し困りました。ログには request_id がある。usage もある。tool のエラーもある。なのに「この tool 呼び出しは、どの LLM request の判断で走ったんだっけ」と追うのに時間がかかりました。

前に request_id、model、usage は残しつつ prompt や body は残さないログにしたのですが、agent になるともう 1 つ足りませんでした。step_name です。

今回は、自分の agent runner に step_name と request_id を結びつける小さいログを足しました。派手な tracing 基盤ではなく、まず JSONL で見えるようにしたメモです。

3行まとめ

• agent 実行単位では run_id、各段階では step_name、外部呼び出しでは request_id を分けて持つ
• ログに残すのは model、usage、latency_ms、status までにして、prompt、messages、tool arguments は残さない
• 最初は 1 行の logger.info(... step_name=..., request_id=...) でも、失敗時の追跡がかなり楽になる

前提とゴール

この記事で扱うのは、agent の行動ログです。LLM の prompt engineering や tool calling の schema 設計ではありません。

私が見たいのは、次のような問いにすぐ答えられるログです。

見たいこと	ログで見る field
どの agent 実行だったか	run_id
どの段階だったか	step_name
どの外部 request だったか	request_id
自分の trace と突き合わせられるか	client_request_id
どのモデルを使ったか	model
token はどれくらい使ったか	usage
失敗したのか遅かったのか	status, latency_ms, error_type

逆に、この記事では本文を保存しない前提にしています。prompt、messages、request body、response body、tool arguments は、ユーザー入力や社内データが混ざりやすいので、ログの外に置きました。

OpenAI の API docs でも、x-request-id はトラブルシュート用の request identifier として扱われていて、本番環境では request ID をログに残すことが推奨されています。また、呼び出し側で X-Client-Request-Id を付けることもできます。なので、provider 側の request_id と自分側の client_request_id を分けて持つのが素直だと思います。

まず fixture を作った

いきなり本番ログを貼ると危ないので、最初に redacted な fixture を作りました。外部 API は呼ばず、agent の 4 step だけを固定データで出すものです。

{"client_request_id":"trace_230_step_003","event":"agent_step.finished","latency_ms":694,"model":"gpt-4o-mini","provider":"openai.chat_completions","request_id":"req_redacted_summary_01","run_id":"agent_run_20260710_redacted","status":"success","step_name":"summarize_tool_result","usage":{"completion_tokens":92,"prompt_tokens":431,"total_tokens":523}}

fixture では、次のキーが出ていないことをテストしています。

FORBIDDEN_KEYS = {
    "prompt",
    "messages",
    "input",
    "request_body",
    "response_body",
    "tool_arguments",
    "authorization",
    "api_key",
    "user_text",
    "email",
}

ここで見たいのは、provider の正確な挙動ではなくログの形です。実ログを晒さずに、記事やレビューで「この粒度なら見せられる」を確認できます。

1行だけ足すなら step_name と request_id

まず最小はこれでよいと思います。

logger.info(
    "agent_step.finished",
    extra={"step_name": step_name, "request_id": request_id},
)

もちろん、これだけだと集計には足りません。ですが、失敗調査ではこの 2 つだけでもかなり効きます。

たとえば、run_tool.search_docs が timeout したとします。その直前の plan_next_action の request_id が分かれば、LLM がなぜその tool を選んだのかを、provider 側の request と自分の agent 実行で突き合わせやすくなります。

私はここで tool_name ではなく step_name にしました。理由は、LLM 呼び出しも tool 呼び出しも同じ timeline に載せたかったからです。

step_name	provider	例
plan_next_action	openai.responses	次の action を決める
run_tool.search_docs	internal.tool	検索 tool を呼ぶ
summarize_tool_result	openai.chat_completions	tool 結果を要約する
call_crm_lookup	internal.tool	業務 API を呼ぶ

tool だけを見ると LLM の判断が消えます。LLM だけを見ると tool の失敗が消えます。step_name はこの間をつなぐためのラベルです。

小さい実装

実装は allowlist にしました。「危ないキーを消す」ではなく、「このキーだけ出す」です。agent は tool ごとに payload の形が変わるので、denylist だと私は抜け漏れを作りそうでした。

import logging
import time
from collections.abc import Callable
from typing import Any
from uuid import uuid4

logger = logging.getLogger("agent.trace")

ALLOWED_TRACE_KEYS = {
    "event",
    "run_id",
    "step_name",
    "provider",
    "request_id",
    "client_request_id",
    "model",
    "usage",
    "latency_ms",
    "status",
    "error_type",
}


def usage_to_dict(usage: Any) -> dict[str, int]:
    if usage is None:
        return {}

    if hasattr(usage, "model_dump"):
        data = usage.model_dump()
    elif isinstance(usage, dict):
        data = usage
    else:
        return {}

    keys = (
        "prompt_tokens",
        "completion_tokens",
        "input_tokens",
        "output_tokens",
        "total_tokens",
    )
    return {key: data[key] for key in keys if isinstance(data.get(key), int)}


def request_id_from(value: Any) -> str | None:
    return (
        getattr(value, "_request_id", None)
        or getattr(value, "request_id", None)
    )


def log_agent_step(event: dict[str, Any]) -> None:
    safe = {key: event[key] for key in ALLOWED_TRACE_KEYS if key in event}
    logger.info("agent_step.finished", extra={"agent_trace": safe})

usage_to_dict で Chat Completions と Responses を同じ dict に寄せていますが、完全に同じ意味として扱わないほうがよいと思います。Chat Completions では prompt_tokens と completion_tokens が出ます。Responses では input_tokens と output_tokens が出ます。集計側では endpoint ごとに列を分けるか、正規化したあとに元の provider を残しておくほうが事故りにくいです。

次に、step を囲む wrapper を作りました。

def run_step(
    *,
    run_id: str,
    step_name: str,
    provider: str,
    call: Callable[[str], Any],
) -> Any:
    started = time.perf_counter()
    client_request_id = str(uuid4())

    try:
        result = call(client_request_id)
        log_agent_step({
            "event": "agent_step.finished",
            "run_id": run_id,
            "step_name": step_name,
            "provider": provider,
            "request_id": request_id_from(result),
            "client_request_id": client_request_id,
            "model": getattr(result, "model", "n/a"),
            "usage": usage_to_dict(getattr(result, "usage", None)),
            "latency_ms": int((time.perf_counter() - started) * 1000),
            "status": "success",
        })
        return result

    except Exception as exc:
        log_agent_step({
            "event": "agent_step.finished",
            "run_id": run_id,
            "step_name": step_name,
            "provider": provider,
            "request_id": request_id_from(exc),
            "client_request_id": client_request_id,
            "model": "n/a",
            "usage": {},
            "latency_ms": int((time.perf_counter() - started) * 1000),
            "status": "error",
            "error_type": exc.__class__.__name__,
        })
        raise

OpenAI SDK を使う場合は、実際の request に X-Client-Request-Id を渡します。SDK や endpoint で渡し方は少し違いますが、考え方は同じです。

def call_llm(client, client_request_id: str):
    return client.responses.create(
        model="gpt-4.1-mini",
        input="redacted example task",
        extra_headers={"X-Client-Request-Id": client_request_id},
    )

ここで input は例示のために書いていますが、私はこの値をログには渡しません。logger に渡すのは wrapper が組み立てた allowlist だけです。

出力ログの見方

JSONL にすると、agent run の timeline として読めます。

{"step_name":"plan_next_action","provider":"openai.responses","request_id":"req_redacted_plan_01","model":"gpt-4.1-mini","usage":{"input_tokens":612,"output_tokens":148,"total_tokens":760},"status":"success"}
{"step_name":"run_tool.search_docs","provider":"internal.tool","request_id":"tool_redacted_search_01","model":"n/a","usage":{},"status":"success"}
{"step_name":"summarize_tool_result","provider":"openai.chat_completions","request_id":"req_redacted_summary_01","model":"gpt-4o-mini","usage":{"prompt_tokens":431,"completion_tokens":92,"total_tokens":523},"status":"success"}
{"step_name":"call_crm_lookup","provider":"internal.tool","request_id":"tool_redacted_crm_01","model":"n/a","usage":{},"status":"error","error_type":"TimeoutError"}

これで、少なくとも次の切り分けはできます。

症状	最初に見るところ
agent 全体が遅い	run_id で step ごとの latency_ms を並べる
token が急に増えた	model と usage.total_tokens を step ごとに見る
tool が失敗した	失敗 step の直前にある LLM step の request_id を見る
provider サポートに聞きたい	request_id と client_request_id を控える
dashboard の usage と差がある	agent 側の usage と gateway 側の usage を同じ時間帯で見る

この程度でも、障害時に「ログはあるのにどこを見ればいいか分からない」が減りました。自分で書いた agent なのに迷子になるのは少し情けないですが、複数 step になると普通に起きると思います。

request_id だけでは足りなかったところ

最初は request_id だけ残せば十分だと思っていました。provider 側に問い合わせるときも、あとから usage を突き合わせるときも、request ID があれば強いからです。

ただ、agent の実行では request が横に並びます。1 つの run_id の中に、計画用の LLM request、tool 結果を読む LLM request、最終回答の LLM request が入ります。さらに tool 側にも、それぞれ社内 API や検索 API の request ID があります。

この状態で request_id だけを見ると、どの順番で何が起きたかが分かりません。特に失敗時は、失敗した tool request だけ見えても、その tool を呼ぶ判断をした LLM request まで戻れないことがあります。

そこで、私は request_id を「外部呼び出しの識別子」、step_name を「agent 内の意味」、run_id を「一連の実行」として分けました。

field	役割	人間が読むときの意味
run_id	agent 実行全体	この問い合わせ全体
step_name	agent 内の段階	次の action 決定、検索、要約、最終回答
request_id	provider や tool の request	外部サービスに問い合わせるときの ID
client_request_id	自分で付けた request	timeout 時にも自分側で控えられる ID

この分け方にすると、ログの会話がしやすくなりました。「req_xxx が失敗した」ではなく、「run_tool.search_docs の req_xxx が失敗して、その直前の plan_next_action は req_yyy だった」と言えます。小さい違いですが、調査時の認知負荷がだいぶ下がります。

retry と streaming で気をつけたこと

もう 1 つ悩んだのは retry です。

SDK や自前 wrapper が retry する場合、1 つの step_name に複数の provider request がぶら下がることがあります。ここを最後の request だけで上書きすると、最初の 429 や timeout が見えなくなります。

私はまだ大きな tracing にはしていませんが、retry を入れるなら次のどちらかにします。

方針	向いている場面
attempt を field に足す	1 step の中で複数回 request することを見たい
retry 後の最終結果だけ残す	まず成功率と usage だけ見たい

本番運用なら前者のほうが安全だと思います。ただ、記事の fixture では複雑にしすぎないため attempt は入れていません。最初から全部入れると、実装前に疲れるからです。

streaming も少し注意が必要でした。Responses の streaming では、途中 event の usage が空で、完了 event で token usage が出る形があります。Chat Completions の stream でも、途中 chunk だけ見ていると usage が取れないことがあります。

なので、streaming を使う step では、途中の delta ではなく完了時点の event で usage を記録する方針にしました。もし完了前に切断されたら、usage は空にして status="error" と error_type を残します。ここで無理に token を推定すると、あとから dashboard の数字とずれて混乱すると思いました。

このあたりは地味ですが、agent の observability ではけっこう効きます。特に tool をまたぐ処理では、失敗した request と token が増えた request が別 step になることがあります。step_name があると、その差分を見つけやすいです。

残さないもの

今回のログで一番大事なのは、残すことより残さないことだと思っています。

残さない field	理由
prompt / messages	ユーザー入力や社内文書が混ざる
request_body	tool args、file ID、業務 ID が混ざる
response_body	生成結果に秘密情報が再出力されることがある
tool_arguments	CRM ID、検索語、社内 API の条件が入りやすい
Authorization / api_key	言うまでもなく危ない
生の email / user text	ログ基盤に個人情報を寄せすぎない

「障害時だけ body を出せるようにする」は便利そうですが、私はまだ避けています。後から例外運用が常態化しそうだからです。必要なら、一時的な再現環境や短い保存期間の別ストアに分けるほうがよいかもしれません。

agent の tool arguments は特に危ないです。tool calling の arguments は JSON なので、ついそのままログに出したくなります。でもそこには検索語、顧客 ID、社内システムの条件が入ります。step_name と request_id で追えるなら、まずはそれで足りるかを見るほうが安全だと思います。

Flatkey AI 側の visibility とどう分けるか

Flatkey AI のような API gateway を使うと、usage、billing、routing の見え方は gateway 側でも確認できます。これはモデルごとの費用感や routing の確認には便利です。

ただ、アプリの agent が「どの業務 step で何をしたか」は、gateway だけでは分かりません。そこはアプリ側の run_id と step_name が必要です。

私はざっくりこう分けています。

レイヤー	見るもの
アプリ側ログ	run_id, step_name, client_request_id, feature, status
LLM provider / gateway	request_id, model, usage, billing, routing, upstream error
集計 dashboard	日次の usage、失敗率、遅延、モデル別コスト

この分け方にすると、prompt や body を保存しなくても、かなりの調査はできます。もちろん、完全な observability ではありません。それでも、まず運用できる最小単位としてはちょうどよかったです。

まとめ

agent の observability は、最初から大きい tracing 基盤を入れなくても始められます。

私の場合は、次の 4 つを足しただけで調査がかなり楽になりました。

• agent 実行に run_id を付ける
• 各段階に step_name を付ける
• 外部呼び出しに request_id と client_request_id を残す
• model と usage を allowlist で残す

逆に、prompt、messages、tool arguments、body はログに入れませんでした。AI Agent は便利なぶん、ログにも業務データが混ざりやすいです。追えることと保存しすぎないことを、最初に分けておくのが大事だと思います。

自分の agent runner に 1 行だけ足すなら、まずは step_name と request_id だと思います。

参考

• OpenAI API Reference: Debugging requests, x-request-id と X-Client-Request-Id
• OpenAI API Reference: Chat Completions usage fields
• OpenAI API Reference: Responses usage fields and streaming events
• Flatkey AI: usage、billing、routing visibility の文脈

おわりに

この記事の fixture は redacted な合成ログです。実ログではありません。実装に入れるときは、自分の組織のログポリシーや保存期間に合わせて確認してください。

間違いあったらコメントください。よろしくお願いします。