From bbb35c21cd2eb95e228f562f0566221e1d3bf61a Mon Sep 17 00:00:00 2001 From: retoor Date: Sun, 18 Oct 2026 22:13:56 +0200 Subject: [PATCH] v1.44.1: log per-completion tool census (sent, mcp, core, lazy, names) --- logging.md | 21 +++++++++++------- tai.py | 61 +++++++++++++++++++++++++++++++++++------------------ test_tai.py | 9 +++++++- 3 files changed, 62 insertions(+), 29 deletions(-) diff --git a/logging.md b/logging.md index 089e3e0..2301913 100644 --- a/logging.md +++ b/logging.md @@ -87,7 +87,7 @@ configure. Logging never raises: a failed write is counted in | `LOG_MSG_MAX` | 2000 | message truncation, chars | | `LOG_TEXT_MAX` | 4000 | each trapped text (system/user/assistant) in DB meta, chars | | `LOG_PREVIEW` | 300 | each trapped text in the file sink, chars | -| `LOG_META_MAX` | 16384 | `meta_json` truncation, bytes | +| `LOG_META_MAX` | 16384 | `meta_json` cap, bytes; oversized metas shrink longest strings first, so the stored JSON stays valid | ## The rules @@ -109,11 +109,13 @@ defaults under explicit arguments. R4. LLM completions trap the full accounting tuple: backend, model, `exec_ms`, `tokens_in`, `tokens_out`, `tokens_total`, -`cost_usd`, message char counts, and the system, user, and -assistant texts (full to `LOG_TEXT_MAX` in the DB, previewed to -`LOG_PREVIEW` in the file). Tokens are estimated at 4 chars each -unless a backend reports real usage (none do today); -`cost_usd` is null until a backend reports cost. +`cost_usd`, message char counts, the system, user, and assistant +texts (full to `LOG_TEXT_MAX` in the DB, previewed to +`LOG_PREVIEW` in the file), and the tool census: how many schemas +were actually sent, split into MCP, core, and lazy-native, plus +the sorted name list. Tokens are estimated at 4 chars each unless +a backend reports real usage (none do today); `cost_usd` is null +until a backend reports cost. R5. Timed operations always log `exec_ms` as an integer. The measurement wraps the operation, never the logging. @@ -151,7 +153,10 @@ line-delimited and greppable without a parser. R12. New events extend the registry below with a fixed level, a single site, and a fixed meta vocabulary (`exec_ms`, `tokens_in`, `tokens_out`, `tokens_total`, `cost_usd`, `outcome`, `error`, -`steps`, `*_chars`, `*_text`). Synonyms are rejected in review. +`steps`, `tools_sent`, `tools_mcp`, `tools_core`, `tools_lazy`, +`tool_names`, `*_chars`, `*_text`). A schema counts as MCP when +its name is not a native `TOOL_SCHEMAS` name. Synonyms are +rejected in review. ## Event registry @@ -163,7 +168,7 @@ single site, and a fixed meta vocabulary (`exec_ms`, `tokens_in`, | `agent.turn_end` | INFO | `run_turn` wrapper | `exec_ms`, `steps`, `tools_used`, `outcome`, `reply_chars` | | `agent.verified` | INFO | `ensure_verified` end | `success`, `failures` | | `agent.compact` | INFO | `compact_messages` end | `before_tokens`, `after_tokens`, `kept_turns` | -| `llm.completion` | INFO | `try_candidate` success | `backend`, `model`, `exec_ms`, `tokens_in`, `tokens_out`, `tokens_total`, `cost_usd`, `history_msgs`, `system_chars`, `user_chars`, `assistant_chars`, `system_text`, `user_text`, `assistant_text`, `tool_calls`, `retried_without_tools` | +| `llm.completion` | INFO | `try_candidate` success | `backend`, `model`, `exec_ms`, `tokens_in`, `tokens_out`, `tokens_total`, `cost_usd`, `history_msgs`, `system_chars`, `user_chars`, `assistant_chars`, `system_text`, `user_text`, `assistant_text`, `tool_calls`, `retried_without_tools`, `tools_sent`, `tools_mcp`, `tools_core`, `tools_lazy`, `tool_names` | | `llm.failed` | WARNING | `try_candidate` failure | `backend`, `model`, `error`, `transient` | | `llm.round_retry` | WARNING | `complete()` before sleep | `round`, `pause_s`, `candidates`, `errors` | | `llm.fatal` | ERROR | `complete()` wrapper on `BackendError` | `error` | diff --git a/tai.py b/tai.py index aa88124..53464b6 100755 --- a/tai.py +++ b/tai.py @@ -105,7 +105,7 @@ def _fromisoformat(text): return parsed.replace(tzinfo=tzinfo) raise ValueError("invalid datetime, use ISO like 2026-10-08T09:00") -VERSION = "1.44.0" +VERSION = "1.44.1" WORKER_STEPS = 12 CREATE_SKILL_STEPS = 40 FORK_MAX_DEPTH = 2 @@ -5468,24 +5468,38 @@ class DebugLog(object): except Exception: return text + def scrub_deep(self, value, profile, limit, depth=0): + if isinstance(value, str): + clean = self.scrub(value, profile) + if len(clean) > limit: + clean = clean[:limit] + "..." + return self.flat(clean) + if depth >= 4: + return short_error(value) + if isinstance(value, list): + return [self.scrub_deep(item, profile, limit, depth + 1) for item in value[:100]] + if isinstance(value, dict): + return dict((str(key), self.scrub_deep(value[key], profile, limit, depth + 1)) for key in sorted(value)) + return value + def cut_meta(self, meta, profile, limit): - out = {} - for key in sorted((meta or {})): - value = (meta or {})[key] - if isinstance(value, str): - clean = self.scrub(value, profile) - if len(clean) > limit: - clean = clean[:limit] + "..." - out[str(key)] = self.flat(clean) - elif isinstance(value, (dict, list)): - try: - blob = json.dumps(value, sort_keys=True)[:limit] - except (TypeError, ValueError): - blob = short_error(value) - out[str(key)] = self.flat(self.scrub(blob, profile)) - else: - out[str(key)] = value - return out + return dict((str(key), self.scrub_deep((meta or {})[key], profile, limit)) for key in sorted((meta or {}))) + + def pack_meta(self, meta): + blob = json.dumps(meta, sort_keys=True) + if len(blob) <= LOG_META_MAX: + return blob + slim = dict(meta) + for _pass in range(4): + big = [key for key in slim if isinstance(slim[key], str) and len(slim[key]) > 100] + if not big: + break + for key in big: + slim[key] = slim[key][:len(slim[key]) // 2] + "..." + blob = json.dumps(slim, sort_keys=True) + if len(blob) <= LOG_META_MAX: + return blob + return json.dumps({"truncated": True, "keys": sorted(meta)}, sort_keys=True) @staticmethod def quote(value): @@ -5530,7 +5544,7 @@ class DebugLog(object): self.handle.write(line + "\n") self.handle.flush() if self.db is not None: - blob = json.dumps(db_meta, sort_keys=True)[:LOG_META_MAX] + blob = self.pack_meta(db_meta) if self.store is not None and self.store.seal.enabled: self.db.execute("INSERT INTO logs (profile, bot, chat, ts, run, level, component, event, message, meta_json) VALUES (?, ?, ?, ?, ?, ?, ?, ?, tai_enc(?), tai_enc(?))", (profile, bot, chat, ts, self.run, level, component, event, clean, blob)) @@ -8409,6 +8423,11 @@ class ChatClient: tokens_in = conversation_tokens(messages, use_tools or []) tokens_out = estimate_tokens(assistant_text) + estimate_tokens(json.dumps(reply.get("tool_calls") or [])) calls = reply.get("tool_calls") or [] + names = [(schema.get("function") or {}).get("name", "") for schema in (use_tools or []) if isinstance(schema, dict)] + native = set(schema["function"]["name"] for schema in TOOL_SCHEMAS) + mcp_count = sum(1 for name in names if name not in native) + core_count = sum(1 for name in names if name in CORE_TOOLS) + lazy_count = len(names) - mcp_count - core_count LOG.event("INFO", "llm", "completion", "%s/%s answered in %dms (%d tokens in, %d out)" % (cand["provider"], cand["model"], int(elapsed_ms), tokens_in, tokens_out), profile=profile, bot=bot, @@ -8417,7 +8436,9 @@ class ChatClient: "cost_usd": None, "history_msgs": len(messages), "system_chars": len(system_text), "user_chars": len(user_text), "assistant_chars": len(assistant_text), "system_text": system_text, "user_text": user_text, "assistant_text": assistant_text, - "tool_calls": len(calls), "retried_without_tools": retried}) + "tool_calls": len(calls), "retried_without_tools": retried, "tools_sent": len(names), + "tools_mcp": mcp_count, "tools_core": core_count, "tools_lazy": lazy_count, + "tool_names": sorted(names)}) def single_shot(self, url, key, payload, label, extra=None): body = json.dumps(payload).encode("utf-8") diff --git a/test_tai.py b/test_tai.py index b37f57a..63af6d9 100644 --- a/test_tai.py +++ b/test_tai.py @@ -17068,8 +17068,10 @@ class LoggerTests(unittest.TestCase): cand = {"provider": "p", "model": "m"} messages = [{"role": "system", "content": "sys"}, {"role": "user", "content": "hi"}] reply = {"role": "assistant", "content": "yo", "reasoning": "", "tool_calls": [], "backend": "p"} + schemas = [tai.tool_schema("shell", "d", {}, []), tai.tool_schema("record_search", "d", {}, []), + {"type": "function", "function": {"name": "mcp_srv_echo"}}] with mock.patch.object(tai.ChatClient, "call_candidate", return_value=reply): - self.assertEqual(chat.try_candidate(cand, messages, None, {"model": "x"}, None, False, []), reply) + self.assertEqual(chat.try_candidate(cand, messages, schemas, {"model": "x"}, None, False, []), reply) tai.LOG.db.commit() rows = self.store.log_query(component="llm", event="completion") self.assertEqual(len(rows), 1) @@ -17078,6 +17080,11 @@ class LoggerTests(unittest.TestCase): self.assertEqual(meta["assistant_text"], "yo") self.assertEqual(meta["tokens_total"], meta["tokens_in"] + meta["tokens_out"]) self.assertIsNone(meta["cost_usd"]) + self.assertEqual(meta["tools_sent"], 3) + self.assertEqual(meta["tools_core"], 1) + self.assertEqual(meta["tools_lazy"], 1) + self.assertEqual(meta["tools_mcp"], 1) + self.assertEqual(meta["tool_names"], ["mcp_srv_echo", "record_search", "shell"]) with mock.patch.object(tai.ChatClient, "call_candidate", side_effect=tai.BackendError("boom")): self.assertIsNone(chat.try_candidate(cand, messages, None, {"model": "x"}, None, False, [])) tai.LOG.db.commit()