agharsallah Codex commited on
Commit
a196e34
·
1 Parent(s): 3f7b296

feat(observability): instrument models, conductor, memory, ledger (Units 2-6)

Browse files

Wire the observability facade through the load-bearing layers:
- models: llm.call/llm.structured spans with GenAI attrs, token/cost metrics,
full prompt+response captured at DEBUG (litellm, stub, openai-compat, router).
- conductor+governor: run/turn/agent.turn spans, run/turn/agent context binding,
event-append logs, agent-turn latency, governor budget-trip metrics+logs.
- memory: memory.recall + memory.index.search spans; DEBUG-logs the EXACT
salience-ranked memory text (with scores) each agent receives; index hit/latency
metrics and keyword-fallback logging; context.build structure logging.
- ledger/events/projections: per-append log+counter, projection.apply, invalid-kind.

Note: litellm_provider.py carries some pre-existing in-progress changes that ride
along with the instrumentation on this feature branch.

Co-Authored-By: Codex <codex@openai.com>

src/core/conductor.py CHANGED
@@ -32,11 +32,13 @@ the observer never participates in cognition.
32
  from __future__ import annotations
33
 
34
  import logging
 
35
  from collections import deque
36
  from pathlib import Path
37
  from typing import TYPE_CHECKING
38
  from uuid import uuid4
39
 
 
40
  from src.core.events import Event
41
  from src.core.governor import BudgetExceeded, Governor
42
  from src.core.ledger import Ledger
@@ -96,6 +98,8 @@ class Conductor:
96
  self.run_id = str(uuid4())
97
  self.turn = 0
98
  self.governor.reset()
 
 
99
  genesis_start = Event(
100
  run_id=self.run_id,
101
  turn=self.turn,
@@ -158,6 +162,7 @@ class Conductor:
158
  self.turn += 1
159
  self.governor.begin_turn(self.turn)
160
  self.governor.check(self.turn)
 
161
  self._pending.extend(agent for agent, _ in self._trigger_queue)
162
  self._trigger_queue.clear()
163
  self._pending.extend(self._tick_scheduled_agents())
@@ -195,38 +200,45 @@ class Conductor:
195
  self.turn += 1
196
  self.governor.begin_turn(self.turn)
197
  self.governor.check(self.turn)
 
198
 
199
  projection = self.projection
200
 
201
- # ── phase 1: event-triggered (subscription) agents ────────────────────
202
- while self._trigger_queue:
203
- agent, _trigger = self._trigger_queue.popleft()
204
- self._run_agent(agent, projection)
 
205
 
206
- # ── phase 2: tick-based scheduled agents ──────────────────────────────
207
- for agent in self._tick_scheduled_agents():
208
- self._run_agent(agent, projection)
209
 
210
  def _run_agent(self, agent: "Agent", projection: StageProjection) -> None:
211
- self.governor.check(self.turn)
212
- try:
213
- event = agent.act(
214
- run_id=self.run_id,
215
- turn=self.turn,
216
- projection=projection,
217
- recent_events=self.ledger.events,
218
- )
219
- except BudgetExceeded:
220
- raise # an intentional stop from the governor — never swallow it
221
- except Exception as exc: # noqa: BLE001 — one agent's crash must not silence the cast
222
- self._note_agent_error(agent, exc)
223
- return
224
- usage = getattr(agent, "last_usage", {})
225
- tokens = int(usage.get("total_tokens", 0) or 0)
226
- cost_usd = float(usage.get("cost_usd", 0.0) or 0.0)
227
- self.governor.record_call(tokens=tokens, cost_usd=cost_usd)
228
- self._append(event)
229
- projection.apply(event)
 
 
 
 
 
230
 
231
  def _note_agent_error(self, agent: "Agent", exc: Exception) -> None:
232
  """Record (and log) an agent's failed turn without aborting the tick.
@@ -237,6 +249,7 @@ class Conductor:
237
  name = getattr(agent, "name", agent.__class__.__name__)
238
  self.agent_errors.append({"turn": str(self.turn), "agent": name, "error": str(exc)})
239
  logger.warning("agent %s failed on turn %d: %s", name, self.turn, exc, exc_info=exc)
 
240
 
241
  def _maybe_snapshot(self) -> None:
242
  if not self.snapshot_every or not self.snapshot_path:
@@ -249,6 +262,9 @@ class Conductor:
249
 
250
  def _append(self, event: Event) -> Event:
251
  appended = self.ledger.append(event)
 
 
 
252
  if self.observer:
253
  self.observer.consume(appended)
254
  self._notify_subscribers(appended)
 
32
  from __future__ import annotations
33
 
34
  import logging
35
+ import time
36
  from collections import deque
37
  from pathlib import Path
38
  from typing import TYPE_CHECKING
39
  from uuid import uuid4
40
 
41
+ from src import observability as obs
42
  from src.core.events import Event
43
  from src.core.governor import BudgetExceeded, Governor
44
  from src.core.ledger import Ledger
 
98
  self.run_id = str(uuid4())
99
  self.turn = 0
100
  self.governor.reset()
101
+ obs.set_context(run_id=self.run_id, turn=self.turn)
102
+ obs.log("run.started", run_id=self.run_id, seed=seed, goal=getattr(self.scenario, "goal", ""))
103
  genesis_start = Event(
104
  run_id=self.run_id,
105
  turn=self.turn,
 
162
  self.turn += 1
163
  self.governor.begin_turn(self.turn)
164
  self.governor.check(self.turn)
165
+ obs.set_context(turn=self.turn)
166
  self._pending.extend(agent for agent, _ in self._trigger_queue)
167
  self._trigger_queue.clear()
168
  self._pending.extend(self._tick_scheduled_agents())
 
200
  self.turn += 1
201
  self.governor.begin_turn(self.turn)
202
  self.governor.check(self.turn)
203
+ obs.set_context(turn=self.turn)
204
 
205
  projection = self.projection
206
 
207
+ with obs.span("turn", **{"mal.turn": self.turn}):
208
+ # ── phase 1: event-triggered (subscription) agents ────────────────
209
+ while self._trigger_queue:
210
+ agent, _trigger = self._trigger_queue.popleft()
211
+ self._run_agent(agent, projection)
212
 
213
+ # ── phase 2: tick-based scheduled agents ──────────────────────────
214
+ for agent in self._tick_scheduled_agents():
215
+ self._run_agent(agent, projection)
216
 
217
  def _run_agent(self, agent: "Agent", projection: StageProjection) -> None:
218
+ self.governor.check(self.turn) # before the span: a budget stop is not an agent turn
219
+ name = getattr(agent, "name", agent.__class__.__name__)
220
+ start = time.perf_counter()
221
+ with obs.bind(agent=name), obs.span("agent.turn", **{"mal.agent": name, "mal.turn": self.turn}):
222
+ try:
223
+ event = agent.act(
224
+ run_id=self.run_id,
225
+ turn=self.turn,
226
+ projection=projection,
227
+ recent_events=self.ledger.events,
228
+ )
229
+ except BudgetExceeded:
230
+ raise # an intentional stop from the governor — never swallow it
231
+ except Exception as exc: # noqa: BLE001 — one agent's crash must not silence the cast
232
+ self._note_agent_error(agent, exc)
233
+ return
234
+ usage = getattr(agent, "last_usage", {})
235
+ tokens = int(usage.get("total_tokens", 0) or 0)
236
+ cost_usd = float(usage.get("cost_usd", 0.0) or 0.0)
237
+ obs.add_span_attrs(**{"event.kind": event.kind, "mal.tokens": tokens, "mal.cost_usd": cost_usd})
238
+ self.governor.record_call(tokens=tokens, cost_usd=cost_usd)
239
+ self._append(event)
240
+ projection.apply(event)
241
+ obs.record_agent_turn(name, time.perf_counter() - start)
242
 
243
  def _note_agent_error(self, agent: "Agent", exc: Exception) -> None:
244
  """Record (and log) an agent's failed turn without aborting the tick.
 
249
  name = getattr(agent, "name", agent.__class__.__name__)
250
  self.agent_errors.append({"turn": str(self.turn), "agent": name, "error": str(exc)})
251
  logger.warning("agent %s failed on turn %d: %s", name, self.turn, exc, exc_info=exc)
252
+ obs.log("agent.error", level="warning", agent=name, turn=self.turn, error=str(exc))
253
 
254
  def _maybe_snapshot(self) -> None:
255
  if not self.snapshot_every or not self.snapshot_path:
 
262
 
263
  def _append(self, event: Event) -> Event:
264
  appended = self.ledger.append(event)
265
+ obs.log(
266
+ "event.append", level="debug", id=appended.id, kind=appended.kind, actor=appended.actor, turn=appended.turn
267
+ )
268
  if self.observer:
269
  self.observer.consume(appended)
270
  self._notify_subscribers(appended)
src/core/context.py CHANGED
@@ -17,6 +17,7 @@ Changing the prompt strategy for all agents is a one-file edit here.
17
 
18
  from __future__ import annotations
19
 
 
20
  from src.core.events import Event
21
  from src.core.memory import EpisodicMemory
22
  from src.core.projections import StageProjection
@@ -53,7 +54,7 @@ class ContextBuilder:
53
 
54
  goal_block = f"SHARED GOAL\n{projection.goal}\n\n" if projection.goal else ""
55
 
56
- return (
57
  f"IDENTITY\n{persona}\n\n"
58
  f"{goal_block}"
59
  f"CURRENT SCENE\n{projection.current_scene}\n\n"
@@ -61,6 +62,20 @@ class ContextBuilder:
61
  f"YOUR MEMORY (recent events you witnessed)\n{memory_text}\n\n"
62
  f"VISITOR DISTURBANCES\n{visitor_lines}"
63
  )
 
 
 
 
 
 
 
 
 
 
 
 
 
 
64
 
65
  @staticmethod
66
  def _blackboard_block(agent_notes: list[str], window: int = 6) -> str:
 
17
 
18
  from __future__ import annotations
19
 
20
+ from src import observability as obs
21
  from src.core.events import Event
22
  from src.core.memory import EpisodicMemory
23
  from src.core.projections import StageProjection
 
54
 
55
  goal_block = f"SHARED GOAL\n{projection.goal}\n\n" if projection.goal else ""
56
 
57
+ prompt = (
58
  f"IDENTITY\n{persona}\n\n"
59
  f"{goal_block}"
60
  f"CURRENT SCENE\n{projection.current_scene}\n\n"
 
62
  f"YOUR MEMORY (recent events you witnessed)\n{memory_text}\n\n"
63
  f"VISITOR DISTURBANCES\n{visitor_lines}"
64
  )
65
+ # Structure + size of the assembled context (the full prompt is logged by the
66
+ # agent layer as ``agent.prompt``; here we record which sections were present).
67
+ sections = ["IDENTITY", "CURRENT SCENE", "BLACKBOARD", "MEMORY", "VISITOR"]
68
+ if goal_block:
69
+ sections.insert(1, "SHARED GOAL")
70
+ obs.log(
71
+ "context.build",
72
+ level="debug",
73
+ agent=agent_name,
74
+ sections=sections,
75
+ prompt_chars=len(prompt),
76
+ memory_chars=len(memory_text),
77
+ )
78
+ return prompt
79
 
80
  @staticmethod
81
  def _blackboard_block(agent_notes: list[str], window: int = 6) -> str:
src/core/events.py CHANGED
@@ -7,6 +7,8 @@ from uuid import uuid4
7
 
8
  from pydantic import BaseModel, ConfigDict, Field, field_validator
9
 
 
 
10
  # ── event kinds ───────────────────────────────────────────────────────────────
11
  #
12
  # `kind` is an OPEN, format-validated string — NOT a closed enum. This is the
@@ -58,6 +60,7 @@ class Event(BaseModel):
58
  @classmethod
59
  def _validate_kind(cls, value: str) -> str:
60
  if not is_valid_kind(value):
 
61
  raise ValueError(
62
  f"invalid event kind {value!r}: must be a lowercase, dot-namespaced "
63
  "identifier such as 'agent.spoke' or 'clue.found'"
 
7
 
8
  from pydantic import BaseModel, ConfigDict, Field, field_validator
9
 
10
+ from src import observability as obs
11
+
12
  # ── event kinds ───────────────────────────────────────────────────────────────
13
  #
14
  # `kind` is an OPEN, format-validated string — NOT a closed enum. This is the
 
60
  @classmethod
61
  def _validate_kind(cls, value: str) -> str:
62
  if not is_valid_kind(value):
63
+ obs.log("event.invalid", level="warning", kind=value)
64
  raise ValueError(
65
  f"invalid event kind {value!r}: must be a lowercase, dot-namespaced "
66
  "identifier such as 'agent.spoke' or 'clue.found'"
src/core/governor.py CHANGED
@@ -2,6 +2,8 @@ from __future__ import annotations
2
 
3
  from dataclasses import dataclass, field
4
 
 
 
5
 
6
  @dataclass
7
  class Governor:
@@ -35,18 +37,29 @@ class Governor:
35
 
36
  def check(self, turn: int) -> None:
37
  if turn > self.max_turns:
38
- raise BudgetExceeded(f"Turn cap {self.max_turns} reached", reason="max_turns")
39
  if self._total_calls >= self.max_total_calls:
40
- raise BudgetExceeded(f"Total call cap {self.max_total_calls} reached", reason="max_total_calls")
41
  if self._calls_this_turn >= self.max_calls_per_turn:
42
- raise BudgetExceeded(
43
- f"Per-turn call cap {self.max_calls_per_turn} reached on turn {turn}",
44
- reason="max_calls_per_turn",
45
- )
46
  if self.max_total_tokens is not None and self._total_tokens >= self.max_total_tokens:
47
- raise BudgetExceeded(f"Total token cap {self.max_total_tokens} reached", reason="max_total_tokens")
48
  if self.hourly_budget_usd is not None and self._spend_usd >= self.hourly_budget_usd:
49
- raise BudgetExceeded(f"Spend cap ${self.hourly_budget_usd:.2f} reached", reason="hourly_budget_usd")
 
 
 
 
 
 
 
 
 
 
 
 
 
 
50
 
51
  def record_call(self, tokens: int = 0, cost_usd: float = 0.0) -> None:
52
  self._calls_this_turn += 1
 
2
 
3
  from dataclasses import dataclass, field
4
 
5
+ from src import observability as obs
6
+
7
 
8
  @dataclass
9
  class Governor:
 
37
 
38
  def check(self, turn: int) -> None:
39
  if turn > self.max_turns:
40
+ self._trip("max_turns", f"Turn cap {self.max_turns} reached")
41
  if self._total_calls >= self.max_total_calls:
42
+ self._trip("max_total_calls", f"Total call cap {self.max_total_calls} reached")
43
  if self._calls_this_turn >= self.max_calls_per_turn:
44
+ self._trip("max_calls_per_turn", f"Per-turn call cap {self.max_calls_per_turn} reached on turn {turn}")
 
 
 
45
  if self.max_total_tokens is not None and self._total_tokens >= self.max_total_tokens:
46
+ self._trip("max_total_tokens", f"Total token cap {self.max_total_tokens} reached")
47
  if self.hourly_budget_usd is not None and self._spend_usd >= self.hourly_budget_usd:
48
+ self._trip("hourly_budget_usd", f"Spend cap ${self.hourly_budget_usd:.2f} reached")
49
+
50
+ def _trip(self, reason: str, message: str) -> None:
51
+ """Record the budget trip as a metric + log, then raise the stop."""
52
+ obs.record_governor_trip(reason)
53
+ obs.log(
54
+ "governor.trip",
55
+ level="warning",
56
+ reason=reason,
57
+ message=message,
58
+ total_calls=self._total_calls,
59
+ total_tokens=self._total_tokens,
60
+ spend_usd=round(self._spend_usd, 4),
61
+ )
62
+ raise BudgetExceeded(message, reason=reason)
63
 
64
  def record_call(self, tokens: int = 0, cost_usd: float = 0.0) -> None:
65
  self._calls_this_turn += 1
src/core/ledger.py CHANGED
@@ -2,6 +2,7 @@ from __future__ import annotations
2
 
3
  from collections.abc import Iterable
4
 
 
5
  from src.core.events import Event
6
 
7
 
@@ -21,6 +22,8 @@ class Ledger:
21
  return event
22
  self._events.append(event)
23
  self._seen_ids.add(event.id)
 
 
24
  return event
25
 
26
  def extend(self, events: Iterable[Event]) -> None:
@@ -28,6 +31,6 @@ class Ledger:
28
  self.append(event)
29
 
30
  def reset(self) -> None:
 
31
  self._events.clear()
32
  self._seen_ids.clear()
33
-
 
2
 
3
  from collections.abc import Iterable
4
 
5
+ from src import observability as obs
6
  from src.core.events import Event
7
 
8
 
 
22
  return event
23
  self._events.append(event)
24
  self._seen_ids.add(event.id)
25
+ obs.log("ledger.append", level="debug", id=event.id, kind=event.kind, actor=event.actor, turn=event.turn)
26
+ obs.incr("ledger.events", 1, kind=event.kind)
27
  return event
28
 
29
  def extend(self, events: Iterable[Event]) -> None:
 
31
  self.append(event)
32
 
33
  def reset(self) -> None:
34
+ obs.log("ledger.reset", level="debug", events=len(self._events))
35
  self._events.clear()
36
  self._seen_ids.clear()
 
src/core/memory.py CHANGED
@@ -35,6 +35,7 @@ import math
35
  from dataclasses import dataclass, field
36
  from typing import TYPE_CHECKING
37
 
 
38
  from src.core.events import Event
39
 
40
  if TYPE_CHECKING: # pragma: no cover - typing only
@@ -92,9 +93,22 @@ class EpisodicMemory:
92
  return result[-self.max_recent :]
93
 
94
  def format_for_prompt(self, events: tuple[Event, ...]) -> str:
95
- recalled = self.visible(events)
96
- lines = [f"[turn {e.turn:03d}][{e.kind}] {text}" for e in recalled if (text := _displayable(e))]
97
- return "\n".join(lines) if lines else "(no prior memory)"
 
 
 
 
 
 
 
 
 
 
 
 
 
98
 
99
 
100
  # ── layer 2: salience-scored memory ──────────────────────────────────────────
@@ -175,6 +189,7 @@ class SalienceMemory:
175
  hits = self.index.search(query, k=len(candidates))
176
  except Exception as exc: # noqa: BLE001 — relevance is best-effort, never fatal
177
  logger.warning("memory index unavailable, using keyword relevance: %s", exc)
 
178
  return None
179
  eligible = {e.id for e in candidates}
180
  ranked = [h.id for h in hits if h.id in eligible]
@@ -201,19 +216,47 @@ class SalienceMemory:
201
  return sorted(top, key=lambda e: e.turn)
202
 
203
  def format_for_prompt(self, events: tuple[Event, ...], current_turn: int, query: str) -> str:
204
- candidates = self._candidates(events)
205
- relevance = self._relevance_map(candidates, query)
206
-
207
- def _score(e: Event) -> float:
208
- rel = None if relevance is None else relevance.get(e.id, 0.0)
209
- return self.score(e, current_turn, query, relevance=rel)
210
-
211
- top = sorted(candidates, key=_score, reverse=True)[: self.top_k]
212
- recalled = sorted(top, key=lambda e: e.turn)
213
- lines = [
214
- f"[turn {e.turn:03d}][{e.kind}][sal={_score(e):.2f}] {text}" for e in recalled if (text := _displayable(e))
215
- ]
216
- return "\n".join(lines) if lines else "(no salient memories)"
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
217
 
218
 
219
  # ── layer 3: reflection trigger ───────────────────────────────────────────────
 
35
  from dataclasses import dataclass, field
36
  from typing import TYPE_CHECKING
37
 
38
+ from src import observability as obs
39
  from src.core.events import Event
40
 
41
  if TYPE_CHECKING: # pragma: no cover - typing only
 
93
  return result[-self.max_recent :]
94
 
95
  def format_for_prompt(self, events: tuple[Event, ...]) -> str:
96
+ with obs.span("memory.recall", **{"mal.agent": self.agent_name, "memory.mode": "episodic"}):
97
+ recalled = self.visible(events)
98
+ lines = [f"[turn {e.turn:03d}][{e.kind}] {text}" for e in recalled if (text := _displayable(e))]
99
+ memory = "\n".join(lines) if lines else "(no prior memory)"
100
+ obs.add_span_attrs(**{"memory.visible_count": len(recalled)})
101
+ obs.observe("memory.visible_count", len(recalled), agent=self.agent_name)
102
+ # DEBUG: the EXACT memory string this agent will receive (what it "sees").
103
+ obs.log(
104
+ "memory.recall",
105
+ level="debug",
106
+ agent=self.agent_name,
107
+ mode="episodic",
108
+ visible_count=len(recalled),
109
+ memory=memory,
110
+ )
111
+ return memory
112
 
113
 
114
  # ── layer 2: salience-scored memory ──────────────────────────────────────────
 
189
  hits = self.index.search(query, k=len(candidates))
190
  except Exception as exc: # noqa: BLE001 — relevance is best-effort, never fatal
191
  logger.warning("memory index unavailable, using keyword relevance: %s", exc)
192
+ obs.log("memory.index.fallback", level="warning", agent=self.agent_name, error=str(exc))
193
  return None
194
  eligible = {e.id for e in candidates}
195
  ranked = [h.id for h in hits if h.id in eligible]
 
216
  return sorted(top, key=lambda e: e.turn)
217
 
218
  def format_for_prompt(self, events: tuple[Event, ...], current_turn: int, query: str) -> str:
219
+ with obs.span(
220
+ "memory.recall",
221
+ **{"mal.agent": self.agent_name, "memory.mode": "salience", "memory.top_k": self.top_k},
222
+ ):
223
+ candidates = self._candidates(events)
224
+ relevance = self._relevance_map(candidates, query)
225
+
226
+ def _score(e: Event) -> float:
227
+ rel = None if relevance is None else relevance.get(e.id, 0.0)
228
+ return self.score(e, current_turn, query, relevance=rel)
229
+
230
+ top = sorted(candidates, key=_score, reverse=True)[: self.top_k]
231
+ recalled = sorted(top, key=lambda e: e.turn)
232
+ lines = [
233
+ f"[turn {e.turn:03d}][{e.kind}][sal={_score(e):.2f}] {text}"
234
+ for e in recalled
235
+ if (text := _displayable(e))
236
+ ]
237
+ memory = "\n".join(lines) if lines else "(no salient memories)"
238
+ scores = {e.id: round(_score(e), 3) for e in recalled}
239
+ obs.add_span_attrs(
240
+ **{
241
+ "memory.visible_count": len(recalled),
242
+ "memory.query": query,
243
+ "memory.semantic": relevance is not None,
244
+ }
245
+ )
246
+ obs.observe("memory.visible_count", len(recalled), agent=self.agent_name)
247
+ # DEBUG: the EXACT salience-ranked memory this agent will receive, with scores.
248
+ obs.log(
249
+ "memory.recall",
250
+ level="debug",
251
+ agent=self.agent_name,
252
+ mode="salience",
253
+ query=query,
254
+ visible_count=len(recalled),
255
+ semantic=relevance is not None,
256
+ scores=scores,
257
+ memory=memory,
258
+ )
259
+ return memory
260
 
261
 
262
  # ── layer 3: reflection trigger ───────────────────────────────────────────────
src/core/memory_index.py CHANGED
@@ -35,8 +35,10 @@ duplicates) — this is what makes the index rebuildable rather than authoritati
35
  from __future__ import annotations
36
 
37
  import os
 
38
  from typing import TYPE_CHECKING, Protocol, runtime_checkable
39
 
 
40
  from src.core.events import Event
41
 
42
  if TYPE_CHECKING: # pragma: no cover - typing only
@@ -162,13 +164,31 @@ class _Mem0BackendBase:
162
  """Semantic search; map hits back to :class:`Event` via stored metadata."""
163
  if not query or k <= 0:
164
  return []
165
- mem = self._memory()
166
- events: list[Event] = []
167
- for hit in self._query(mem, query, k):
168
- event = _event_from_metadata(hit.get("metadata"))
169
- if event is not None:
170
- events.append(event)
171
- return events
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
172
 
173
 
174
  # ── local (off-the-grid) backend ──────────────────────────────────────────────
 
35
  from __future__ import annotations
36
 
37
  import os
38
+ import time
39
  from typing import TYPE_CHECKING, Protocol, runtime_checkable
40
 
41
+ from src import observability as obs
42
  from src.core.events import Event
43
 
44
  if TYPE_CHECKING: # pragma: no cover - typing only
 
164
  """Semantic search; map hits back to :class:`Event` via stored metadata."""
165
  if not query or k <= 0:
166
  return []
167
+ with obs.span(
168
+ "memory.index.search",
169
+ **{"memory.query": query, "memory.k": k, "memory.backend": type(self).__name__},
170
+ ):
171
+ started = time.perf_counter()
172
+ mem = self._memory()
173
+ events: list[Event] = []
174
+ for hit in self._query(mem, query, k):
175
+ event = _event_from_metadata(hit.get("metadata"))
176
+ if event is not None:
177
+ events.append(event)
178
+ elapsed_ms = (time.perf_counter() - started) * 1000
179
+ obs.add_span_attrs(**{"memory.hits": len(events), "memory.latency_ms": round(elapsed_ms, 2)})
180
+ obs.observe("memory.index.hits", len(events))
181
+ obs.observe("memory.index.latency_ms", elapsed_ms)
182
+ obs.log(
183
+ "memory.index.search",
184
+ level="debug",
185
+ backend=type(self).__name__,
186
+ query=query,
187
+ k=k,
188
+ hits=len(events),
189
+ latency_ms=round(elapsed_ms, 2),
190
+ )
191
+ return events
192
 
193
 
194
  # ── local (off-the-grid) backend ──────────────────────────────────────────────
src/core/projections.py CHANGED
@@ -2,6 +2,7 @@ from __future__ import annotations
2
 
3
  from dataclasses import dataclass, field
4
 
 
5
  from src.core.events import Event
6
 
7
 
@@ -15,6 +16,7 @@ class StageProjection:
15
  user_artifacts: list[str] = field(default_factory=list)
16
 
17
  def apply(self, event: Event) -> None:
 
18
  if event.kind == "run.started":
19
  self.seed = str(event.payload["seed"])
20
  self.goal = str(event.payload.get("goal", "")) or self.goal
 
2
 
3
  from dataclasses import dataclass, field
4
 
5
+ from src import observability as obs
6
  from src.core.events import Event
7
 
8
 
 
16
  user_artifacts: list[str] = field(default_factory=list)
17
 
18
  def apply(self, event: Event) -> None:
19
+ obs.log("projection.apply", level="debug", kind=event.kind, actor=event.actor, turn=event.turn)
20
  if event.kind == "run.started":
21
  self.seed = str(event.payload["seed"])
22
  self.goal = str(event.payload.get("goal", "")) or self.goal
src/models/litellm_provider.py CHANGED
@@ -36,6 +36,7 @@ from __future__ import annotations
36
  from dataclasses import dataclass, field
37
  from typing import TYPE_CHECKING
38
 
 
39
  from src.models.openai_compat import OpenAICompatProvider
40
  from src.models.provider import ModelProvider, model_error
41
 
@@ -64,28 +65,40 @@ class LiteLLMProvider(ModelProvider):
64
  """Transport retries LiteLLM makes on a transient call failure — a dropped
65
  connection, a timeout, a 5xx. Lets a flaky endpoint self-heal mid-demo before the
66
  call gives up and returns the failure sentinel."""
 
 
 
 
 
 
 
 
 
67
  _last_usage: dict = field(default_factory=dict, init=False, repr=False)
68
  _last_cost: float = field(default=0.0, init=False, repr=False)
69
  _last_reasoning: str = field(default="", init=False, repr=False)
70
 
71
  def complete(self, role: str, prompt: str) -> str:
72
  litellm = self._litellm()
73
- try:
74
- response = litellm.completion(
75
- model=self.model,
76
- api_base=self.api_base,
77
- api_key=self._resolved_api_key(),
78
- messages=self._messages(role, prompt),
79
- temperature=self.temperature,
80
- max_tokens=self.max_tokens,
81
- num_retries=self.num_retries,
82
- )
83
- text = (response.choices[0].message.content or "").strip()
84
- self._capture_usage(litellm, response, prompt, text)
85
- return text
86
- except Exception as exc:
87
- self._zero_usage()
88
- return model_error(exc)
 
 
 
89
 
90
  def complete_structured(
91
  self,
@@ -115,25 +128,32 @@ class LiteLLMProvider(ModelProvider):
115
  "instructor package is required for complete_structured(). Install it with: uv pip install instructor"
116
  ) from exc
117
 
118
- client = instructor.from_litellm(litellm.completion)
119
- try:
120
- result, response = client.create_with_completion(
121
- model=self.model,
122
- api_base=self.api_base,
123
- api_key=self._resolved_api_key(),
124
- messages=self._messages(role, prompt),
125
- response_model=response_model,
126
- max_retries=self.max_retries,
127
- num_retries=self.num_retries,
128
- temperature=self.temperature,
129
- max_tokens=self.max_tokens,
130
- )
131
- text = getattr(result, "text", "") or ""
132
- self._capture_usage(litellm, response, prompt, text)
133
- return result
134
- except Exception:
135
- self._zero_usage()
136
- raise
 
 
 
 
 
 
 
137
 
138
  @property
139
  def last_reasoning(self) -> str:
@@ -150,6 +170,65 @@ class LiteLLMProvider(ModelProvider):
150
  """Metered USD cost of the most recent call (0.0 offline)."""
151
  return self._last_cost
152
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
153
  # ── call helpers (shared by complete / complete_structured) ─────────────────
154
 
155
  @staticmethod
 
36
  from dataclasses import dataclass, field
37
  from typing import TYPE_CHECKING
38
 
39
+ from src import observability as obs
40
  from src.models.openai_compat import OpenAICompatProvider
41
  from src.models.provider import ModelProvider, model_error
42
 
 
65
  """Transport retries LiteLLM makes on a transient call failure — a dropped
66
  connection, a timeout, a 5xx. Lets a flaky endpoint self-heal mid-demo before the
67
  call gives up and returns the failure sentinel."""
68
+ structured_mode: str = "json_schema"
69
+ """Instructor mode for :meth:`complete_structured` (an ``instructor.Mode`` member name,
70
+ case-insensitive). Defaults to ``json_schema`` — vLLM **guided decoding** via
71
+ ``response_format``, which is parser-independent: it constrains the output to the schema
72
+ (``kind`` can't be an unauthorised value) without needing a tool-call parser. This is
73
+ deliberate: not every served model ships a tool parser (e.g. MiniCPM4.1 emits a custom
74
+ ``<|tool_call_start|>`` format vLLM 0.21.0 has no parser for), so Instructor's default
75
+ ``tools`` mode 400s there. ``json`` (plain ``json_object`` + schema-in-prompt) is the
76
+ fallback if a backend rejects ``json_schema``; ``tools`` restores the old behaviour."""
77
  _last_usage: dict = field(default_factory=dict, init=False, repr=False)
78
  _last_cost: float = field(default=0.0, init=False, repr=False)
79
  _last_reasoning: str = field(default="", init=False, repr=False)
80
 
81
  def complete(self, role: str, prompt: str) -> str:
82
  litellm = self._litellm()
83
+ with obs.span("llm.call", **self._span_request_attrs(role)):
84
+ try:
85
+ response = litellm.completion(
86
+ model=self.model,
87
+ api_base=self.api_base,
88
+ api_key=self._resolved_api_key(),
89
+ messages=self._messages(role, prompt),
90
+ temperature=self.temperature,
91
+ max_tokens=self.max_tokens,
92
+ num_retries=self.num_retries,
93
+ )
94
+ text = (response.choices[0].message.content or "").strip()
95
+ self._capture_usage(litellm, response, prompt, text)
96
+ self._emit_telemetry(role, prompt, text, structured=False)
97
+ return text
98
+ except Exception as exc:
99
+ self._zero_usage()
100
+ obs.log("llm.error", level="warning", model=self.model, role=role, error=str(exc))
101
+ return model_error(exc)
102
 
103
  def complete_structured(
104
  self,
 
128
  "instructor package is required for complete_structured(). Install it with: uv pip install instructor"
129
  ) from exc
130
 
131
+ # Guided-JSON by default (see ``structured_mode``): constrain the output to the
132
+ # schema via vLLM's ``response_format`` rather than tool calling, so a model with no
133
+ # tool-call parser still returns a validated payload instead of a 400.
134
+ mode = getattr(instructor.Mode, self.structured_mode.upper(), instructor.Mode.JSON_SCHEMA)
135
+ client = instructor.from_litellm(litellm.completion, mode=mode)
136
+ with obs.span("llm.structured", **{**self._span_request_attrs(role), "llm.mode": self.structured_mode}):
137
+ try:
138
+ result, response = client.create_with_completion(
139
+ model=self.model,
140
+ api_base=self.api_base,
141
+ api_key=self._resolved_api_key(),
142
+ messages=self._messages(role, prompt),
143
+ response_model=response_model,
144
+ max_retries=self.max_retries,
145
+ num_retries=self.num_retries,
146
+ temperature=self.temperature,
147
+ max_tokens=self.max_tokens,
148
+ )
149
+ text = getattr(result, "text", "") or ""
150
+ self._capture_usage(litellm, response, prompt, text)
151
+ self._emit_telemetry(role, prompt, text, structured=True)
152
+ return result
153
+ except Exception as exc:
154
+ self._zero_usage()
155
+ obs.log("llm.error", level="warning", model=self.model, role=role, structured=True, error=str(exc))
156
+ raise
157
 
158
  @property
159
  def last_reasoning(self) -> str:
 
170
  """Metered USD cost of the most recent call (0.0 offline)."""
171
  return self._last_cost
172
 
173
+ # ── telemetry (shared by complete / complete_structured) ────────────────────
174
+
175
+ def _span_request_attrs(self, role: str) -> dict:
176
+ """GenAI request attributes for an LLM span — never includes the api key."""
177
+ return {
178
+ "gen_ai.system": "litellm",
179
+ "gen_ai.request.model": self.model,
180
+ "gen_ai.request.temperature": self.temperature,
181
+ "gen_ai.request.max_tokens": self.max_tokens,
182
+ "llm.api_base": self.api_base or "",
183
+ "mal.role": role,
184
+ }
185
+
186
+ def _emit_telemetry(self, role: str, prompt: str, text: str, *, structured: bool) -> None:
187
+ """Attach usage/cost/prompt to the active span, count the call, and log it.
188
+
189
+ The full prompt + completion + reasoning ride on the span (truncated in the
190
+ UI store) and on a DEBUG ``llm.exchange`` log, so a reviewer can read exactly
191
+ what was sent to each model. INFO ``llm.call`` carries the metered summary.
192
+ """
193
+ usage = self._last_usage or {}
194
+ prompt_tokens = int(usage.get("prompt_tokens", 0) or 0)
195
+ completion_tokens = int(usage.get("completion_tokens", 0) or 0)
196
+ obs.add_span_attrs(
197
+ **{
198
+ "gen_ai.usage.input_tokens": prompt_tokens,
199
+ "gen_ai.usage.output_tokens": completion_tokens,
200
+ "llm.cost_usd": self._last_cost,
201
+ "llm.structured": structured,
202
+ "llm.prompt": prompt,
203
+ "llm.completion": text,
204
+ "llm.reasoning": self._last_reasoning or "",
205
+ }
206
+ )
207
+ obs.record_llm_call(
208
+ self.model,
209
+ prompt_tokens=prompt_tokens,
210
+ completion_tokens=completion_tokens,
211
+ cost_usd=self._last_cost,
212
+ )
213
+ obs.log(
214
+ "llm.call",
215
+ role=role,
216
+ model=self.model,
217
+ structured=structured,
218
+ prompt_tokens=prompt_tokens,
219
+ completion_tokens=completion_tokens,
220
+ cost_usd=round(self._last_cost, 6),
221
+ )
222
+ obs.log(
223
+ "llm.exchange",
224
+ level="debug",
225
+ role=role,
226
+ model=self.model,
227
+ prompt=prompt,
228
+ completion=text,
229
+ reasoning=self._last_reasoning or "",
230
+ )
231
+
232
  # ── call helpers (shared by complete / complete_structured) ─────────────────
233
 
234
  @staticmethod
src/models/openai_compat.py CHANGED
@@ -3,6 +3,7 @@ from __future__ import annotations
3
  import os
4
  from dataclasses import dataclass, field
5
 
 
6
  from src.models.provider import ModelProvider, model_error
7
 
8
 
@@ -72,31 +73,61 @@ class OpenAICompatProvider(ModelProvider):
72
 
73
  client = self._get_client()
74
  system = self._system_for_role(role)
75
- try:
76
- resp = client.chat.completions.create(
77
- model=self.model,
78
- messages=[
79
- {"role": "system", "content": system},
80
- {"role": "user", "content": prompt},
81
- ],
82
- max_tokens=self.max_tokens,
83
- temperature=self.temperature,
84
- )
85
- text = resp.choices[0].message.content.strip()
86
- usage = getattr(resp, "usage", None)
87
- if usage is not None:
88
- self._last_usage = {
89
- "prompt_tokens": getattr(usage, "prompt_tokens", 0) or 0,
90
- "completion_tokens": getattr(usage, "completion_tokens", 0) or 0,
91
- "total_tokens": getattr(usage, "total_tokens", 0) or 0,
92
- }
93
- else:
94
- p, c = estimate_tokens(prompt), estimate_tokens(text)
95
- self._last_usage = {"prompt_tokens": p, "completion_tokens": c, "total_tokens": p + c}
96
- return text
97
- except Exception as exc:
98
- self._last_usage = {"prompt_tokens": 0, "completion_tokens": 0, "total_tokens": 0}
99
- return model_error(exc)
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
100
 
101
  @staticmethod
102
  def _system_for_role(role: str) -> str:
 
3
  import os
4
  from dataclasses import dataclass, field
5
 
6
+ from src import observability as obs
7
  from src.models.provider import ModelProvider, model_error
8
 
9
 
 
73
 
74
  client = self._get_client()
75
  system = self._system_for_role(role)
76
+ span_attrs = {
77
+ "gen_ai.system": "openai-compatible",
78
+ "gen_ai.request.model": self.model,
79
+ "llm.api_base": self.base_url or "",
80
+ "mal.role": role,
81
+ }
82
+ with obs.span("llm.call", **span_attrs):
83
+ try:
84
+ resp = client.chat.completions.create(
85
+ model=self.model,
86
+ messages=[
87
+ {"role": "system", "content": system},
88
+ {"role": "user", "content": prompt},
89
+ ],
90
+ max_tokens=self.max_tokens,
91
+ temperature=self.temperature,
92
+ )
93
+ text = resp.choices[0].message.content.strip()
94
+ usage = getattr(resp, "usage", None)
95
+ if usage is not None:
96
+ self._last_usage = {
97
+ "prompt_tokens": getattr(usage, "prompt_tokens", 0) or 0,
98
+ "completion_tokens": getattr(usage, "completion_tokens", 0) or 0,
99
+ "total_tokens": getattr(usage, "total_tokens", 0) or 0,
100
+ }
101
+ else:
102
+ p, c = estimate_tokens(prompt), estimate_tokens(text)
103
+ self._last_usage = {"prompt_tokens": p, "completion_tokens": c, "total_tokens": p + c}
104
+ obs.add_span_attrs(
105
+ **{
106
+ "gen_ai.usage.input_tokens": int(self._last_usage["prompt_tokens"]),
107
+ "gen_ai.usage.output_tokens": int(self._last_usage["completion_tokens"]),
108
+ "llm.prompt": prompt,
109
+ "llm.completion": text,
110
+ }
111
+ )
112
+ obs.record_llm_call(
113
+ self.model,
114
+ prompt_tokens=int(self._last_usage["prompt_tokens"]),
115
+ completion_tokens=int(self._last_usage["completion_tokens"]),
116
+ )
117
+ obs.log(
118
+ "llm.call",
119
+ role=role,
120
+ model=self.model,
121
+ structured=False,
122
+ prompt_tokens=int(self._last_usage["prompt_tokens"]),
123
+ completion_tokens=int(self._last_usage["completion_tokens"]),
124
+ )
125
+ obs.log("llm.exchange", level="debug", role=role, model=self.model, prompt=prompt, completion=text)
126
+ return text
127
+ except Exception as exc:
128
+ self._last_usage = {"prompt_tokens": 0, "completion_tokens": 0, "total_tokens": 0}
129
+ obs.log("llm.error", level="warning", model=self.model, role=role, error=str(exc))
130
+ return model_error(exc)
131
 
132
  @staticmethod
133
  def _system_for_role(role: str) -> str:
src/models/provider.py CHANGED
@@ -5,6 +5,8 @@ import json
5
  import re
6
  from dataclasses import dataclass, field
7
 
 
 
8
 
9
  def estimate_tokens(text: str) -> int:
10
  """Rough token estimate (~4 chars/token) for providers without usage data.
@@ -167,6 +169,10 @@ class DeterministicTinyModel(ModelProvider):
167
  _last_usage: dict[str, int] = field(default_factory=dict, init=False, repr=False)
168
 
169
  def complete(self, role: str, prompt: str) -> str:
 
 
 
 
170
  digest = hashlib.sha256(f"{self.variant}:{role}:{prompt}".encode("utf-8")).hexdigest()
171
  choices = {
172
  "scene-whisperer": [
@@ -243,11 +249,33 @@ class DeterministicTinyModel(ModelProvider):
243
  obj[name] = self._synth_field(name, role, digest)
244
  out = json.dumps(obj, ensure_ascii=False)
245
 
 
246
  self._last_usage = {
247
- "prompt_tokens": estimate_tokens(prompt),
248
- "completion_tokens": estimate_tokens(out),
249
- "total_tokens": estimate_tokens(prompt) + estimate_tokens(out),
250
  }
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
251
  return out
252
 
253
  def _synth_field(self, name: str, role: str, digest: str) -> str:
 
5
  import re
6
  from dataclasses import dataclass, field
7
 
8
+ from src import observability as obs
9
+
10
 
11
  def estimate_tokens(text: str) -> int:
12
  """Rough token estimate (~4 chars/token) for providers without usage data.
 
169
  _last_usage: dict[str, int] = field(default_factory=dict, init=False, repr=False)
170
 
171
  def complete(self, role: str, prompt: str) -> str:
172
+ with obs.span("llm.call", **{"gen_ai.system": "stub", "gen_ai.request.model": self.variant, "mal.role": role}):
173
+ return self._complete(role, prompt)
174
+
175
+ def _complete(self, role: str, prompt: str) -> str:
176
  digest = hashlib.sha256(f"{self.variant}:{role}:{prompt}".encode("utf-8")).hexdigest()
177
  choices = {
178
  "scene-whisperer": [
 
249
  obj[name] = self._synth_field(name, role, digest)
250
  out = json.dumps(obj, ensure_ascii=False)
251
 
252
+ prompt_tokens, completion_tokens = estimate_tokens(prompt), estimate_tokens(out)
253
  self._last_usage = {
254
+ "prompt_tokens": prompt_tokens,
255
+ "completion_tokens": completion_tokens,
256
+ "total_tokens": prompt_tokens + completion_tokens,
257
  }
258
+ obs.add_span_attrs(
259
+ **{
260
+ "gen_ai.usage.input_tokens": prompt_tokens,
261
+ "gen_ai.usage.output_tokens": completion_tokens,
262
+ "llm.prompt": prompt,
263
+ "llm.completion": out,
264
+ }
265
+ )
266
+ obs.record_llm_call(
267
+ self.variant, prompt_tokens=prompt_tokens, completion_tokens=completion_tokens, cost_usd=0.0
268
+ )
269
+ obs.log(
270
+ "llm.call",
271
+ role=role,
272
+ model=self.variant,
273
+ structured=False,
274
+ prompt_tokens=prompt_tokens,
275
+ completion_tokens=completion_tokens,
276
+ cost_usd=0.0,
277
+ )
278
+ obs.log("llm.exchange", level="debug", role=role, model=self.variant, prompt=prompt, completion=out)
279
  return out
280
 
281
  def _synth_field(self, name: str, role: str, digest: str) -> str:
src/models/router.py CHANGED
@@ -23,6 +23,7 @@ from __future__ import annotations
23
 
24
  from dataclasses import dataclass, field
25
 
 
26
  from src.core.manifest import ModelProfile, resolve_model
27
  from src.models.openai_compat import has_live_credentials
28
  from src.models.provider import DeterministicTinyModel, ModelProvider
@@ -86,12 +87,15 @@ class ModelRouter:
86
 
87
  def _build(self, profile: str) -> ModelProvider:
88
  if self.offline:
 
89
  return DeterministicTinyModel(variant=f"stub:{profile}")
90
  # Live transport is the LiteLLM gateway (ADR-0015). Lazy-import keeps the
91
  # offline path free of the dependency.
92
  from src.models.litellm_provider import LiteLLMProvider
93
 
94
  spec = self._spec_for(profile)
 
 
95
  return LiteLLMProvider(
96
  model=spec.model,
97
  api_base=spec.base_url,
 
23
 
24
  from dataclasses import dataclass, field
25
 
26
+ from src import observability as obs
27
  from src.core.manifest import ModelProfile, resolve_model
28
  from src.models.openai_compat import has_live_credentials
29
  from src.models.provider import DeterministicTinyModel, ModelProvider
 
87
 
88
  def _build(self, profile: str) -> ModelProvider:
89
  if self.offline:
90
+ obs.log("router.resolve", profile=profile, mode="offline", model=f"stub:{profile}")
91
  return DeterministicTinyModel(variant=f"stub:{profile}")
92
  # Live transport is the LiteLLM gateway (ADR-0015). Lazy-import keeps the
93
  # offline path free of the dependency.
94
  from src.models.litellm_provider import LiteLLMProvider
95
 
96
  spec = self._spec_for(profile)
97
+ # Resolution is logged WITHOUT the api key — only the model + endpoint.
98
+ obs.log("router.resolve", profile=profile, mode="live", model=spec.model, api_base=spec.base_url or "")
99
  return LiteLLMProvider(
100
  model=spec.model,
101
  api_base=spec.base_url,
tests/test_observability.py CHANGED
@@ -45,14 +45,18 @@ def test_log_sanitises_reserved_field_names():
45
 
46
  def test_context_binding_stamps_logs():
47
  _fresh()
 
 
 
48
  with obs.bind(run_id="run-7", turn=2, agent="clue-gatherer"):
 
49
  obs.log("memory.recall", k=5)
50
  record = [r for r in obs.telemetry_store().recent_logs() if r.get("event") == "memory.recall"][-1]
51
  assert record["run_id"] == "run-7"
52
  assert record["turn"] == 2
53
  assert record["agent"] == "clue-gatherer"
54
- # Binding is scoped — it clears on exit.
55
- assert "run_id" not in obs.current_context()
56
 
57
 
58
  def test_span_recorded_with_attributes_and_nesting():
 
45
 
46
  def test_context_binding_stamps_logs():
47
  _fresh()
48
+ # `set_context` (used by the conductor for run/turn) persists by design, so the
49
+ # process context may be non-empty here; capture it and assert bind RESTORES it.
50
+ before = obs.current_context().get("run_id")
51
  with obs.bind(run_id="run-7", turn=2, agent="clue-gatherer"):
52
+ assert obs.current_context()["run_id"] == "run-7"
53
  obs.log("memory.recall", k=5)
54
  record = [r for r in obs.telemetry_store().recent_logs() if r.get("event") == "memory.recall"][-1]
55
  assert record["run_id"] == "run-7"
56
  assert record["turn"] == 2
57
  assert record["agent"] == "clue-gatherer"
58
+ # Binding is scoped — run_id returns to whatever it was before the block.
59
+ assert obs.current_context().get("run_id") == before
60
 
61
 
62
  def test_span_recorded_with_attributes_and_nesting():