diff --git a/.claude-plugin/plugin.json b/.claude-plugin/plugin.json index 50018ef..6b52808 100644 --- a/.claude-plugin/plugin.json +++ b/.claude-plugin/plugin.json @@ -1,7 +1,7 @@ { "name": "langfuse-observability", "description": "The Langfuse x Claude Code Observability Plugin", - "version": "1.2.1", + "version": "1.2.2", "author": { "name": "Langfuse" }, @@ -67,6 +67,12 @@ "description": "Send the conversation so far as each LLM call's input. On long sessions this grows quadratically and span batches can exceed the exporter's 64 MiB limit, which drops them. Set to false to send each call's own new input only.", "default": true }, + "CC_LANGFUSE_DETERMINISTIC_IDS": { + "type": "boolean", + "title": "Deterministic observation ids", + "description": "Derive each observation id from its trace id and a stable key (message id, tool_use id, agent id). Needed to continue a background agent that resumed after an interim result: its later work attaches to its span id across firings. Set to false for random ids; agents then ship once, as they are on disk at their first result.", + "default": true + }, "CC_LANGFUSE_STATE_DIR": { "type": "string", "title": "State directory", diff --git a/README.md b/README.md index 04e0b6a..6c37580 100644 --- a/README.md +++ b/README.md @@ -71,6 +71,43 @@ claude plugin update langfuse-observability@langfuse-observability Restart Claude Code afterwards. `claude plugin list` shows the installed version. +## Backfilling a past session + +The hook can re-upload a finished session from its transcript, for example +to repair traces a version with a known gap exported incompletely. Run it +only after the session has ended. + +```bash +uv run --script hooks/langfuse_hook.py \ + --backfill ~/.claude/projects//.jsonl --dry-run +``` + +`--dry-run` builds every observation, sends nothing, and prints the counts +and token totals that would be exported. Without it, the same Langfuse keys as +the hook are read from the environment. + +- The re-uploaded turns go to traces of their own (`--namespace`, default + `backfill-v1`). Langfuse v4 does not merge two uploads of one observation + id, so a namespace that already holds traces of the session is refused; + supersede an earlier backfill with a new namespace. +- After the upload, the backfill reads the session back from Langfuse until + every observation it sent is visible (up to 10 minutes). If any is + missing it exits with code 4 and deletes nothing: a rejected upload is + only logged by the exporter, never raised. `--verify-minutes` changes the + window. +- After exit 4: if Langfuse is only slow to ingest, run again with + `--verify-only` and the same `--namespace`. It uploads nothing (the ids + are deterministic), re-reads, and with `--replace-session-traces` + deletes the old traces once everything is visible. If the upload really + failed, start over with a new `--namespace` and + `--replace-session-traces`; that also removes the partial upload. +- `--replace-session-traces` then deletes the session's traces this hook + named `Claude Code Turn` that are not the backfill's own. Traces under + another name are never touched. With `--dry-run` it lists them instead. +- The session id must be the transcript's own (file name and rows), and a + session with any file under its directory (agents, workflows) modified in + the last 30 minutes is refused unless `--force` is passed. + ## Troubleshooting The hook explains nearly every failure in diff --git a/hooks/langfuse_hook.py b/hooks/langfuse_hook.py index b5da67c..11f3013 100644 --- a/hooks/langfuse_hook.py +++ b/hooks/langfuse_hook.py @@ -12,6 +12,7 @@ import base64 import contextlib +import contextvars import json import logging import os @@ -47,6 +48,13 @@ def _opt(name: str) -> str: # whole batch (measured: 51 batches of 67-425 MB dropped re-sending one 165-turn # session). "false" sends each generation's own new input only, as before history. CAPTURE_HISTORY = (_opt("CC_LANGFUSE_CAPTURE_HISTORY") or "true").lower() == "true" +# Observation ids derived from the trace id plus a stable key (message id, +# tool_use id, agent id) instead of random ones. They let a later firing +# attach children to an agent span that has not shipped yet, and make a +# backfill's ids reproducible. They do NOT make a re-send free: Langfuse v4 +# reads do not merge two exports of one id, so every observation is still +# exported exactly once. +DETERMINISTIC_IDS = (_opt("CC_LANGFUSE_DETERMINISTIC_IDS") or "true").lower() == "true" OPERATOR_TAGS_VAR = "CC_LANGFUSE_TRACE_TAGS" try: MAX_CHARS = int(_opt("CC_LANGFUSE_MAX_CHARS") or "20000") @@ -624,6 +632,25 @@ def sweep_stale_session_locks(state: Dict[str, Any], cutoff: datetime) -> None: lock.unlink() except OSError: pass + try: + registries = [ + f for pattern in ("langfuse_agents.*.json", "langfuse_agents.*.bak", "langfuse_agents.*.tmp") + for f in STATE_DIR.glob(pattern) + ] + except OSError: + return + stray_cutoff = time.time() - 24 * 3600 + for registry in registries: + stem = registry.name[len("langfuse_agents."):].rsplit(".", 1)[0] + try: + mtime = registry.stat().st_mtime + if registry.suffix == ".tmp" and mtime < stray_cutoff: + # A save interrupted between write and rename. + registry.unlink() + elif len(stem) == 16 and stem not in live and mtime < cutoff.timestamp(): + registry.unlink() + except OSError: + pass def save_hook_state(state: Dict[str, Any]) -> None: @@ -665,12 +692,32 @@ def get_content_from_row(row: Dict[str, Any]) -> Any: return message.get("content") return row.get("content") +# Row types that echo the API request Claude Code sent (since 2.1.301): a +# request record, its system/shape, and one "blob" per request message. A blob +# carries message.role "user"/"assistant" with neither id, usage nor timestamp, +# so read as a chat row it starts phantom turns and zero-usage generations. +REQUEST_ECHO_ROW_TYPE_PREFIX = "api-request" + +def is_request_echo_row(row: Any) -> bool: + if not isinstance(row, dict): + return False + row_type = row.get("type") + return isinstance(row_type, str) and row_type.startswith(REQUEST_ECHO_ROW_TYPE_PREFIX) + +def drop_request_echo_rows(rows: List[Dict[str, Any]]) -> List[Dict[str, Any]]: + return [row for row in rows if not is_request_echo_row(row)] + def get_user_or_assistant_role_from_row(row: Dict[str, Any]) -> Optional[str]: # Claude Code transcript row format is internal. Prefer top-level row.type # when it marks a chat row, then fall back to nested message.role. row_type = row.get("type") if row_type in ("user", "assistant"): return row_type + if isinstance(row_type, str) and row_type: + # A typed row of any other kind (attachment, queue-operation, + # api-request-blob, ...) is never a chat message, even when it embeds + # one; only untyped rows from older formats fall back to message.role. + return None message = row.get("message") if isinstance(message, dict): @@ -942,7 +989,7 @@ def read_new_jsonl(transcript_path: Path, session_state: SessionState) -> Tuple[ except Exception: continue - return msgs, session_state + return drop_request_echo_rows(msgs), session_state # ----------------- Turn assembly ----------------- @@ -979,21 +1026,37 @@ def _extract_xml_tag_value(text: str, tag: str) -> Optional[str]: return None return text[i + len(start):j] +def get_task_notification_text(row: Dict[str, Any]) -> str: + """The text a notification row carries. A notification delivered while + the receiver is working arrives as an attachment row + ({"type": "queued_command", "prompt": "..."}); that is + how a subagent receives the results of the agents it launched.""" + attachment = row.get("attachment") + if row.get("type") == "attachment" and isinstance(attachment, dict): + if attachment.get("type") == "queued_command": + prompt = attachment.get("prompt") + return prompt if isinstance(prompt, str) else extract_text_from_content(prompt) + return "" + return extract_text_from_content(get_content_from_row(row)) + def is_task_notification_row(row: Dict[str, Any]) -> bool: + if is_request_echo_row(row): + # A request blob repeats a delivered notification without its timestamp. + return False origin = row.get("origin") if isinstance(origin, dict) and origin.get("kind") == "task-notification": return True - notification_text = extract_text_from_content(get_content_from_row(row)).lstrip() + notification_text = get_task_notification_text(row).lstrip() return notification_text.startswith("") def get_tool_use_id_from_task_notification(row: Dict[str, Any]) -> Optional[str]: - notification_text = extract_text_from_content(get_content_from_row(row)) + notification_text = get_task_notification_text(row) tool_use_id = _extract_xml_tag_value(notification_text, "tool-use-id") return tool_use_id.strip() if isinstance(tool_use_id, str) and tool_use_id.strip() else None def get_task_id_from_task_notification(row: Dict[str, Any]) -> Optional[str]: - notification_text = extract_text_from_content(get_content_from_row(row)) + notification_text = get_task_notification_text(row) task_id = _extract_xml_tag_value(notification_text, "task-id") return task_id.strip() if isinstance(task_id, str) and task_id.strip() else None @@ -1014,7 +1077,7 @@ def get_tool_use_id_for_task_notification( return None def get_result_from_task_notification(row: Dict[str, Any]) -> str: - notification_text = extract_text_from_content(get_content_from_row(row)) + notification_text = get_task_notification_text(row) result = _extract_xml_tag_value(notification_text, "result") return result if result is not None else notification_text @@ -1090,13 +1153,15 @@ def route_to_pending_turn(pending_turn: Dict[str, Any], row: Dict[str, Any], too session_state.pending_task_notifications = stashed_notifications[-MAX_PENDING_TASK_NOTIFICATIONS:] - # Pop fully resolved turns in deferral (i.e. chronological) order. + # Pop fully resolved turns in deferral (i.e. chronological) order; a + # turn past the defer bound is popped too and ships as it is. + newest = get_latest_row_timestamp(rows) resolved_turn_row_lists: List[List[Dict[str, Any]]] = [] still_pending: List[Dict[str, Any]] = [] for pending_turn in session_state.pending_agent_turns: if not isinstance(pending_turn, dict) or not isinstance(pending_turn.get("rows"), list): continue - if pending_turn.get("pending_tool_use_ids"): + if pending_turn.get("pending_tool_use_ids") and not is_older_than_defer_bound(pending_turn["rows"], newest): still_pending.append(pending_turn) continue resolved_turn_row_lists.append(pending_turn["rows"]) @@ -1210,6 +1275,13 @@ def get_undelivered_queued_notification_ids(rows: List[Dict[str, Any]]) -> List[ Queue remove rows carry no notification content and cannot be matched, so a removed notification keeps the gate closed until the turn ends — the safe direction (close-time emission is always correct). + + Newer Claude Code versions do write the notification content on the + remove row. A notification for an agent launched BY a subagent is + enqueued on the main queue and removed at once (it is routed to that + subagent and never delivered here), so a remove row carrying the id + takes its entry off the queue; otherwise such a notification would + hold the main turn closed until it ends. """ queued: List[str] = [] delivered = set() @@ -1220,6 +1292,10 @@ def get_undelivered_queued_notification_ids(rows: List[Dict[str, Any]]) -> List[ if not tool_use_id: continue if row.get("type") == "queue-operation": + if row.get("operation") == "remove": + if tool_use_id in queued: + queued.remove(tool_use_id) + continue queued.append(tool_use_id) else: delivered.add(tool_use_id) @@ -1237,17 +1313,117 @@ def turn_has_unresolved_async_activity(turn: Turn) -> bool: ) +def get_stopped_task_id(row: Dict[str, Any]) -> Optional[str]: + """Task id a successful TaskStop result row stopped, or None. A stopped + task never notifies, so its launch would otherwise wait forever. A + failed stop comes back as an error string, not a dict.""" + if not is_tool_result(row): + return None + tool_use_result = row.get("toolUseResult") + if not isinstance(tool_use_result, dict): + return None + task_id = tool_use_result.get("task_id") + if not isinstance(task_id, str) or not task_id: + return None + if any(block.get("is_error") is True for block in get_tool_result_blocks(get_content_from_row(row))): + return None + return task_id + + +def get_launch_tool_use_ids_by_task_id(rows: List[Dict[str, Any]]) -> Dict[str, str]: + """task id -> launching tool_use id, from async launch results + (toolUseResult.taskId for workflows, agentId for agents, + backgroundTaskId for background shells).""" + out: Dict[str, str] = {} + for row in rows: + tool_use_result = row.get("toolUseResult") if isinstance(row, dict) else None + if not isinstance(tool_use_result, dict): + continue + task_id = ( + tool_use_result.get("taskId") + or tool_use_result.get("agentId") + or tool_use_result.get("backgroundTaskId") + ) + if not isinstance(task_id, str) or not task_id: + continue + for block in get_tool_result_blocks(get_content_from_row(row)): + tool_use_id = block.get("tool_use_id") + if tool_use_id: + out[task_id] = str(tool_use_id) + return out + + +def expand_task_stop_rows( + rows: List[Dict[str, Any]], + lookup_rows: List[Dict[str, Any]], + task_id_to_tool_use_id: Optional[Dict[str, str]] = None, +) -> List[Dict[str, Any]]: + """After each successful TaskStop result, add a synthetic notification + resolving the stopped launch, so its turn stops waiting. Idempotent: + a TaskStop row already followed by its synthetic row is not expanded + again (held rows pass through here on every firing).""" + launches: Optional[Dict[str, str]] = None + done = {row.get("syntheticForUuid") for row in rows if isinstance(row, dict) and row.get("syntheticForUuid")} + out: List[Dict[str, Any]] = [] + for row in rows: + out.append(row) + if not isinstance(row, dict) or row.get("syntheticForUuid"): + continue + task_id = get_stopped_task_id(row) + if task_id is None: + continue + marker = str(row.get("uuid") or f"taskstop:{task_id}") + if marker in done: + continue + if launches is None: + launches = get_launch_tool_use_ids_by_task_id(lookup_rows) + tool_use_id = launches.get(task_id) or (task_id_to_tool_use_id or {}).get(task_id) + if not tool_use_id: + continue + done.add(marker) + out.append({ + "type": "user", + "timestamp": row.get("timestamp"), + "sessionId": row.get("sessionId"), + "syntheticForUuid": marker, + "origin": {"kind": "task-notification"}, + "message": {"role": "user", "content": ( + f"\n{task_id}\n{tool_use_id}\n" + "stopped\nStopped with TaskStop.\n" + )}, + }) + return out + + +try: + MAX_DEFER_SECONDS = float(_opt("CC_LANGFUSE_MAX_DEFER_HOURS") or "12") * 3600 +except ValueError: + MAX_DEFER_SECONDS = 12 * 3600 + + +def get_latest_row_timestamp(rows: List[Dict[str, Any]]) -> Optional[datetime]: + return _get_latest_timestamp(*[parse_timestamp(row) for row in rows if isinstance(row, dict)]) + + +def is_older_than_defer_bound(rows: List[Dict[str, Any]], newest: Optional[datetime]) -> bool: + """A turn whose launch never notifies (killed, stopped from outside) + would wait for SessionEnd; past this age it ships as it is.""" + latest = get_latest_row_timestamp(rows) + return newest is not None and latest is not None and (newest - latest).total_seconds() > MAX_DEFER_SECONDS + + def get_turns_to_emit( turns: List[Turn], session_state: SessionState, *, flush_deferred_agent_turns: bool = False, + newest_timestamp: Optional[datetime] = None, ) -> List[Turn]: turns_to_emit: List[Turn] = [] for turn in turns: pending_agent_tool_use_ids = get_pending_agent_tool_use_ids(turn) if pending_agent_tool_use_ids: - if flush_deferred_agent_turns: + if flush_deferred_agent_turns or is_older_than_defer_bound(turn.rows, newest_timestamp): debug(f"Emitting async agent turn without task notification: {pending_agent_tool_use_ids}") turns_to_emit.append(turn) continue @@ -1305,6 +1481,11 @@ def add_tool_result_row(row: Dict[str, Any], state: TurnAssemblyState) -> bool: tool_result_entry["is_error"] = tool_result_block["is_error"] if is_async_launch is not None: tool_result_entry["is_async_launch"] = is_async_launch + background_task_id = (row.get("toolUseResult") or {}).get("backgroundTaskId") if isinstance(row.get("toolUseResult"), dict) else None + if isinstance(background_task_id, str) and background_task_id: + # A shell moved to the background (run_in_background, or a + # command that outlived its timeout); it notifies when done. + tool_result_entry["background_task_id"] = background_task_id if workflow_launch_marker is not None: # Links the launching tool_use to its workflow run so emission # can attach the run's agent transcripts (which have no @@ -1456,14 +1637,18 @@ def assemble_turns( turns: List[Turn] = [] state = TurnAssemblyState() + rows = expand_task_stop_rows(rows, rows, task_id_to_tool_use_id) for row in rows: - if add_injected_context_row(row, state): + # Before the isMeta check: a subagent receives a notification as an + # isMeta user row ("[SYSTEM NOTIFICATION ...]" with origin kind + # task-notification), which the injected-context branch would eat. + if add_task_notification_row(row, state, task_id_to_tool_use_id, closed_turns=turns): continue - if add_tool_result_row(row, state): + if add_injected_context_row(row, state): continue - if add_task_notification_row(row, state, task_id_to_tool_use_id, closed_turns=turns): + if add_tool_result_row(row, state): continue if add_interrupted_turn_row(row, state): @@ -1615,6 +1800,12 @@ def get_new_turns_from_transcript( rows = held_rows + rows session_state.open_turn = {} + pending_rows = [ + row for pending_turn in session_state.pending_agent_turns + if isinstance(pending_turn, dict) and isinstance(pending_turn.get("rows"), list) + for row in pending_turn["rows"] + ] + rows = expand_task_stop_rows(rows, pending_rows + rows, task_id_to_tool_use_id) deferred_turn_row_lists, rows = resolve_deferred_agent_turns(rows, session_state, task_id_to_tool_use_id) if flush_deferred_agent_turns and session_state.pending_agent_turns: @@ -1681,7 +1872,7 @@ def get_agent_launch_tool_use_ids_by_name(transcript_path: Path) -> Dict[str, st row = json.loads(line) except Exception: continue - if not isinstance(row, dict): + if not isinstance(row, dict) or is_request_echo_row(row): continue for tool_use in get_tool_use_blocks(get_content_from_row(row)): tool_use_id = str(tool_use.get("id") or "") @@ -1753,7 +1944,7 @@ def get_workflow_journal_results(run_dir: Path) -> Dict[str, Any]: one per completed agent; unparseable lines are skipped.""" journal_path = run_dir / "journal.jsonl" try: - lines = journal_path.read_text(encoding="utf-8").splitlines() + lines = split_jsonl_lines(journal_path.read_text(encoding="utf-8")) except Exception: return {} results_by_agent_id: Dict[str, Any] = {} @@ -1942,6 +2133,109 @@ def _build_forced_trace_context(trace_id_hex: str, debug(f"forced trace context for {trace_id_hex!r} failed: {e}") return None +class DeterministicSpanIdGenerator: + """Wraps the tracer's OTel id generator: the next span id can be preset + (one shot); everything else is delegated to the wrapped generator.""" + + def __init__(self, inner: Any) -> None: + self._inner = inner + self.next_span_id: Optional[int] = None + + def generate_span_id(self) -> int: + span_id, self.next_span_id = self.next_span_id, None + return span_id if span_id else self._inner.generate_span_id() + + def generate_trace_id(self) -> int: + return self._inner.generate_trace_id() + + def is_trace_id_random(self) -> bool: + is_random = getattr(self._inner, "is_trace_id_random", None) + return bool(is_random()) if callable(is_random) else True + + +def install_deterministic_span_ids(langfuse: Any) -> Optional[DeterministicSpanIdGenerator]: + """Wrap the tracer's id generator once. Returns None (random ids stay) + when deterministic ids are off or the tracer exposes no id_generator + (a no-op tracer, an SDK that changed its internals).""" + if not DETERMINISTIC_IDS: + return None + tracer = getattr(langfuse, "_otel_tracer", None) + inner = getattr(tracer, "id_generator", None) + if inner is None: + return None + if isinstance(inner, DeterministicSpanIdGenerator): + return inner + try: + wrapper = DeterministicSpanIdGenerator(inner) + tracer.id_generator = wrapper + return wrapper + except Exception as e: + debug(f"deterministic span ids unavailable: {e}") + return None + + +# Scope for observations without a natural id (an assistant message with no +# message.id): their keys are positional, so the scope (agent id + turn +# index) keeps two turns of one agent trace from deriving the same id. +_ID_SCOPE: "contextvars.ContextVar[str]" = contextvars.ContextVar("cc_langfuse_id_scope", default="") + + +@contextlib.contextmanager +def id_scope(scope: str) -> Any: + token = _ID_SCOPE.set(scope) + try: + yield + finally: + _ID_SCOPE.reset(token) + + +def derive_span_id(trace_id_hex: str, id_key: str) -> int: + """sha256(trace id + key)[:8 bytes] as a non-zero 64-bit span id.""" + scope = _ID_SCOPE.get() if "noid:" in id_key else "" + seed = f"{trace_id_hex}:{scope}:{id_key}" if scope else f"{trace_id_hex}:{id_key}" + return int(hashlib.sha256(seed.encode("utf-8")).hexdigest()[:16], 16) or 1 + + +def get_trace_id_hex_for_new_span(parent_otel_span: Any, forced_trace_id: Optional[str]) -> Optional[str]: + try: + if parent_otel_span is not None: + trace_id = parent_otel_span.get_span_context().trace_id + return f"{trace_id:032x}" if trace_id else None + except Exception: + return None + if forced_trace_id and _is_valid_trace_id_hex(forced_trace_id): + return forced_trace_id.lower() + return None + + +def get_span_context_hex(otel_span: Any) -> Optional[Tuple[str, str]]: + """(trace id, span id) of an OTel span as hex, or None.""" + try: + context = otel_span.get_span_context() + if not context.trace_id or not context.span_id: + return None + return f"{context.trace_id:032x}", f"{context.span_id:016x}" + except Exception: + return None + + +def carrier_span(trace_id_hex: str, span_id_hex: str) -> Optional[Any]: + """A non-exporting stand-in for an already exported span, so children + emitted by a later firing nest under it.""" + if not _is_valid_trace_id_hex(trace_id_hex) or not is_valid_span_id_hex(span_id_hex): + return None + try: + return otel_trace_api.NonRecordingSpan(otel_trace_api.SpanContext( + trace_id=int(trace_id_hex, 16), + span_id=int(span_id_hex, 16), + is_remote=False, + trace_flags=otel_trace_api.TraceFlags(0x01), + )) + except Exception as e: + debug(f"carrier span failed: {e}") + return None + + def _start_root_otel_span(langfuse: Langfuse, name: str, start_ns: Optional[int], forced_trace_id: Optional[str], forced_parent_span_id: Optional[str] = None) -> Any: @@ -1960,9 +2254,13 @@ def _start_backdated(langfuse: Langfuse, *, name: str, as_type: str, as_root: bool = False, forced_trace_id: Optional[str] = None, forced_parent_span_id: Optional[str] = None, + id_key: Optional[str] = None, **obs_kwargs: Any) -> Any: """Create a Langfuse observation with an explicit OTel start_time. + With id_key set (and deterministic ids on), the observation id is + derive_span_id(trace id, id_key) rather than random. + Bypasses langfuse.start_observation() (which has no start_time kwarg in SDK 4.x) by talking to the underlying OTel tracer directly and then wrapping the resulting span with the Langfuse observation type. @@ -1983,11 +2281,20 @@ def _start_backdated(langfuse: Langfuse, *, name: str, as_type: str, f"pin with `pip install \"langfuse>=4.7,<5\"` or update the hook script." ) start_ns = to_otel_nanoseconds(start_time) - if parent_otel_span is not None: - with otel_trace_api.use_span(parent_otel_span, end_on_exit=False): - otel_span = langfuse._otel_tracer.start_span(name=name, start_time=start_ns) - else: - otel_span = _start_root_otel_span(langfuse, name, start_ns, forced_trace_id, forced_parent_span_id) + id_generator = install_deterministic_span_ids(langfuse) if id_key else None + if id_generator is not None: + trace_id_hex = get_trace_id_hex_for_new_span(parent_otel_span, forced_trace_id) + if trace_id_hex is not None: + id_generator.next_span_id = derive_span_id(trace_id_hex, id_key) + try: + if parent_otel_span is not None: + with otel_trace_api.use_span(parent_otel_span, end_on_exit=False): + otel_span = langfuse._otel_tracer.start_span(name=name, start_time=start_ns) + else: + otel_span = _start_root_otel_span(langfuse, name, start_ns, forced_trace_id, forced_parent_span_id) + finally: + if id_generator is not None: + id_generator.next_span_id = None if as_root: # SDK/server contract: spans under a synthetic trace-id carrier have a # parentSpanId that never exports, so the server only treats them as @@ -2383,10 +2690,15 @@ class EmissionCursor: emitted: set completed_only: bool = False newly_emitted: List[str] = field(default_factory=list) + # Keys that are not complete whatever the caller computes (an agent's + # last message while it is still being written). + held: set = field(default_factory=set) def should_emit(self, key: str, complete: bool = True) -> bool: if key in self.emitted: return False + if key in self.held: + complete = False if self.completed_only and not complete: return False self.emitted.add(key) @@ -2468,6 +2780,7 @@ def emit_single_tool_observation( as_type="tool", start_time=tool_use_timestamp, parent_otel_span=parent_otel_span, + id_key=tool_key, input=tool_input, metadata=tool_metadata, **get_status_kwargs(tool_result.status), @@ -2502,6 +2815,12 @@ def emit_single_tool_observation( subagent, tool_use_timestamp, subagent_transcripts_by_tool_use_id=subagent_transcripts_by_tool_use_id, + workflow_agent_transcripts_by_run_id=workflow_agent_transcripts_by_run_id, + # A sync launch's tool_result is written when the agent is done. + known_finished=( + tool_result_entry is not None + and not is_async_agent_launch_result(tool_result_entry) + ), ) workflow_end_timestamp = None @@ -2523,6 +2842,8 @@ def emit_single_tool_observation( workflow_resolved=workflow_resolved, cursor=cursor, emission_scope=tool_use_id or tool_key, + subagent_transcripts_by_tool_use_id=subagent_transcripts_by_tool_use_id, + workflow_agent_transcripts_by_run_id=workflow_agent_transcripts_by_run_id, ) # Exported spans are immutable, so the end time set here must already @@ -2718,6 +3039,7 @@ def emit_generation_observation( generation_name: str, start_timestamp: Optional[datetime], generation_kwargs: Dict[str, Any], + id_key: Optional[str] = None, ) -> Any: return _start_backdated( langfuse, @@ -2725,6 +3047,7 @@ def emit_generation_observation( as_type="generation", start_time=start_timestamp, parent_otel_span=parent_otel_span, + id_key=id_key, **generation_kwargs, ) @@ -2777,6 +3100,7 @@ def emit_pending_subagent(pending_subagent: Dict[str, Any]) -> None: pending_subagent["subagent"], pending_subagent.get("display_start_timestamp") or pending_subagent.get("start_timestamp"), subagent_transcripts_by_tool_use_id=subagent_transcripts_by_tool_use_id, + workflow_agent_transcripts_by_run_id=workflow_agent_transcripts_by_run_id, ) latest_end_timestamp = _get_latest_timestamp(latest_end_timestamp, subagent_end_timestamp) @@ -2839,6 +3163,7 @@ def emit_pending_subagent(pending_subagent: Dict[str, Any]) -> None: generation_name=generation_name, start_timestamp=generation_start_timestamp, generation_kwargs=generation_kwargs, + id_key=generation_emission_key(assistant_index, assistant_message), ) update_pending_subagent_display_start_after_launch_response( pending_subagents, @@ -2912,6 +3237,8 @@ def emit_workflow_agent_observations( workflow_resolved: bool, cursor: EmissionCursor, emission_scope: str, + subagent_transcripts_by_tool_use_id: Optional[Dict[str, Dict[str, Any]]] = None, + workflow_agent_transcripts_by_run_id: Optional["WorkflowAgentTranscriptsByRunId"] = None, ) -> Optional[datetime]: """Emit each workflow-spawned agent transcript under the launching "Tool: Workflow" span. @@ -2955,10 +3282,221 @@ def emit_workflow_agent_observations( # (no text in the final message); the journal result is the agent's # actual return value, so it becomes the span output instead of "". empty_output_fallback=agent_result_json, + # A workflow agent can launch agents and workflows of its own. + subagent_transcripts_by_tool_use_id=subagent_transcripts_by_tool_use_id, + workflow_agent_transcripts_by_run_id=workflow_agent_transcripts_by_run_id, + known_finished=workflow_resolved or agent_result is not None, ) latest_end_timestamp = _get_latest_timestamp(latest_end_timestamp, agent_end_timestamp) return latest_end_timestamp +class AgentRegistry: + """Every agent span a session has emitted, with where it hangs and what + of its transcript is already exported. + + An agent is not done when its launch first resolves: a background agent + that ends a turn while its own background work runs notifies "completed" + (an interim result), then resumes on that work's notifications and keeps + writing its transcript, launching more agents. Each firing re-emits every + registered agent whose transcript grew, under the parent it was first + emitted under, so late generations and late-launched agents (at any + depth) still arrive. Stored per session, beside the state file. + """ + + def __init__(self, path: Optional[Path] = None) -> None: + self.path = path + self.entries: Dict[str, Dict[str, Any]] = {} + + @staticmethod + def _read(path: Path) -> Dict[str, Dict[str, Any]]: + data = json.loads(path.read_text(encoding="utf-8")) + if not isinstance(data, dict) or not isinstance(data.get("agents"), dict): + raise ValueError("no agents map") + return {k: v for k, v in data["agents"].items() if isinstance(k, str) and isinstance(v, dict)} + + @classmethod + def load(cls, path: Optional[Path]) -> "AgentRegistry": + """Load the registry, falling back to the previous version (.bak). + + Losing it cannot be repaired from the transcripts: what was already + exported is only known here, and re-sending would count twice. So a + lost registry means agents that grow later are not continued (their + late work is missing), never duplicated; that is logged loudly.""" + registry = cls(path) + if path is None or not path.exists(): + return registry + try: + registry.entries = cls._read(path) + return registry + except Exception as e: + first_error = f"{type(e).__name__}: {e}" + backup = path.with_suffix(".bak") + try: + registry.entries = cls._read(backup) + info(f"WARNING agent registry unreadable ({path}: {first_error}); using the previous " + f"version. Agents that grew in the last firing may miss that firing's work.") + except Exception: + info(f"WARNING agent registry unreadable ({path}: {first_error}) and no usable backup; " + f"agents emitted earlier in this session will not be continued.") + return registry + + def save(self) -> None: + if self.path is None: + return + try: + self.path.parent.mkdir(parents=True, exist_ok=True) + tmp = self.path.with_suffix(".tmp") + tmp.write_text(json.dumps({"agents": self.entries}, sort_keys=True), encoding="utf-8") + if self.path.exists(): + os.replace(self.path, self.path.with_suffix(".bak")) + os.replace(tmp, self.path) + except Exception as e: + info(f"WARNING agent registry save failed ({self.path}): {type(e).__name__}: {e}") + + +def get_agent_registry_path(session_state_key: str) -> Path: + return STATE_DIR / f"langfuse_agents.{session_state_key[:16]}.json" + + +# The registry of the firing in progress; None outside one (one-shot emission +# then keeps the old behavior: an agent is emitted once, as it is on disk). +_ACTIVE_AGENT_REGISTRY: "contextvars.ContextVar[Optional[AgentRegistry]]" = contextvars.ContextVar( + "cc_langfuse_agent_registry", default=None +) + + +@contextlib.contextmanager +def active_agent_registry(registry: Optional[AgentRegistry]) -> Any: + token = _ACTIVE_AGENT_REGISTRY.set(registry) + try: + yield + finally: + _ACTIVE_AGENT_REGISTRY.reset(token) + + +def _get_file_mtime(path: Path) -> float: + try: + return path.stat().st_mtime + except OSError: + return time.time() + + +def _get_file_size(path: Path) -> Optional[int]: + try: + return path.stat().st_size + except OSError: + return None + + +# Set while a firing must ship everything (SessionEnd, backfill): agents that +# have not settled are finalized as they are on disk. +_FORCE_FINALIZE: "contextvars.ContextVar[bool]" = contextvars.ContextVar( + "cc_langfuse_force_finalize", default=False +) + + +@contextlib.contextmanager +def force_finalize(enabled: bool) -> Any: + token = _FORCE_FINALIZE.set(enabled) + try: + yield + finally: + _FORCE_FINALIZE.reset(token) + + +# An agent transcript unchanged this long is treated as at rest even when its +# last message never got a stop_reason (an agent killed mid-message). +AGENT_IDLE_SETTLE_SECONDS = 30 * 60 + + +def get_streaming_message_key(turns: List[Turn]) -> Optional[str]: + """Emission key of the agent's last message if it may still be written. + + A message is written as several rows sharing message.id; the earlier + rows carry partial usage and stop_reason null. Only the main + transcript is guaranteed complete at a Stop, so in an agent transcript + the LAST message is final only once its last row has a stop_reason. An + earlier message with a null stop_reason is final: a later message + exists.""" + if not turns or not turns[-1].assistant_msgs: + return None + last_turn = turns[-1] + index = len(last_turn.assistant_msgs) - 1 + last_message = last_turn.assistant_msgs[index] + message = last_message.get("message") + if isinstance(message, dict) and "stop_reason" in message and message.get("stop_reason") is None: + return generation_emission_key(index, last_message) + return None + + +def agent_is_settled(turns: List[Turn]) -> bool: + """True when the agent transcript, as it is now, ends at rest: no async + launch without its notification, no queued notification undelivered, no + tool_use without its result, and a last message that is not a tool call. + Nothing it already wrote can then change, so every observation can ship + in final form. An agent can still be resumed later (a new message to + it); what it writes then is new observations, never old ones changed.""" + if not turns: + return False + for turn in turns: + if turn_has_unresolved_async_activity(turn) or get_running_background_shell_ids(turn): + return False + last_turn = turns[-1] + for assistant_message in last_turn.assistant_msgs: + for tool_use in get_tool_use_blocks(get_content_from_row(assistant_message)): + if str(tool_use.get("id") or "") not in last_turn.tool_results_by_id: + return False + last_message = last_turn.assistant_msgs[-1].get("message") + if isinstance(last_message, dict) and last_message.get("stop_reason") == "tool_use": + return False + if get_streaming_message_key(turns) is not None: + return False + return True + + +def agent_is_settled_but_for_streaming(turns: List[Turn]) -> bool: + """agent_is_settled, ignoring only a last message that never got its + stop_reason (used once the transcript has been idle for a long time).""" + if not turns: + return False + if any(turn_has_unresolved_async_activity(turn) or get_running_background_shell_ids(turn) for turn in turns): + return False + return True + + +def get_running_background_shell_ids(turn: Turn) -> List[str]: + """Background shells of the turn with no notification yet. Counted only + when deciding whether an AGENT is at rest (its span ships once, so it + must not ship before the shell's notification wakes the agent); main + turns keep their own gate.""" + return [ + tool_use_id for tool_use_id, entry in turn.tool_results_by_id.items() + if isinstance(entry, dict) and entry.get("background_task_id") and entry.get("final_content") is None + ] + + +def agent_entry_needs_visit(entry: Dict[str, Any], size: Optional[int], force: bool, + path: Optional[Path] = None) -> bool: + """A registered agent is re-read when its transcript grew, when it is + not at rest yet (an idle bound may settle it although nothing changed), + when it holds a message back, or, at SessionEnd, when its span has not + shipped.""" + if size is None: + return False + if size != entry.get("size"): + return True + if force: + return bool(entry.get("unsettled") or entry.get("held") or not entry.get("span_exported")) + if entry.get("unsettled") or entry.get("held"): + # Unchanged on disk: only an idle bound can settle it, so wait until + # that bound is due instead of re-reading it every firing. + bound = entry.get("idle_bound_s") + if not isinstance(bound, (int, float)) or path is None: + return True + return time.time() - _get_file_mtime(path) > bound + return False + + def emit_subagent_observations(langfuse: Langfuse, parent_otel_span: Any, subagent: Dict[str, Any], start_timestamp: Optional[datetime], @@ -2967,20 +3505,59 @@ def emit_subagent_observations(langfuse: Langfuse, parent_otel_span: Any, generation_name: str = "Subagent LLM Call", empty_output_fallback: Optional[str] = None, subagent_transcripts_by_tool_use_id: Optional[Dict[str, Dict[str, Any]]] = None, + workflow_agent_transcripts_by_run_id: Optional["WorkflowAgentTranscriptsByRunId"] = None, + known_finished: bool = False, ) -> Optional[datetime]: + """Emit one agent transcript under parent_otel_span. + + known_finished: the caller holds proof the agent is done (a sync launch's + tool_result, a workflow journal result), which agent_is_settled cannot + see from the transcript alone (a workflow agent ends on a bare + StructuredOutput call). + + Inside a firing with an agent registry, every observation is exported + exactly once, in final form: Langfuse v4 does not merge two exports of + one id at read time, so a re-send would count twice. While the agent + still runs, only observations that can no longer change ship; the agent + span itself ships once, when the agent settles (or at SessionEnd). Its + id is deterministic, so children exported earlier already point at it. + Without a registry, or without deterministic ids, the agent ships in one + pass as it is on disk (the previous behavior). + """ path = subagent.get("path") if not isinstance(path, Path): return start_timestamp + agent_id = subagent.get("agent_id") + if not isinstance(agent_id, str) or not agent_id: + agent_id = path.stem + + registry = _ACTIVE_AGENT_REGISTRY.get() + entry = registry.entries.get(agent_id) if registry is not None else None + force = _FORCE_FINALIZE.get() + size = _get_file_size(path) + if entry is not None and size is not None and not agent_entry_needs_visit(entry, size, force, path): + # Nothing new on disk, and nothing left to finalize. + return parse_timestamp(entry.get("end")) or start_timestamp + rows = read_subagent_jsonl(path) if rows is None: return start_timestamp - turns = build_turns(rows) + # Notifications inside the agent's transcript may carry only a task id: + # agents' ids come from the metas, shells' and workflows' from the + # agent's own launch results. + task_id_map = get_launch_tool_use_ids_by_task_id(rows) + task_id_map.update(get_task_id_to_tool_use_id(subagent_transcripts_by_tool_use_id)) + turns = build_turns(rows, task_id_map) if not turns: return start_timestamp first_turn = turns[0] - subagent_start_timestamp = start_timestamp or parse_timestamp(first_turn.user_msg) + # The agent span keeps the start it was first seen with. + stored_start_timestamp = parse_timestamp(entry.get("start")) if entry else None + subagent_start_timestamp = ( + stored_start_timestamp or start_timestamp or parse_timestamp(first_turn.user_msg) + ) subagent_input_text, subagent_input_meta = truncate_text(extract_text_from_content(get_content_from_row(first_turn.user_msg))) last_turn = turns[-1] @@ -3003,50 +3580,201 @@ def emit_subagent_observations(langfuse: Langfuse, parent_otel_span: Any, } if extra_metadata: subagent_metadata.update(extra_metadata) - subagent_span = _start_backdated( - langfuse, + span_kwargs: Dict[str, Any] = dict( name=span_name, as_type="span", start_time=subagent_start_timestamp, - parent_otel_span=parent_otel_span, + id_key=f"agent:{agent_id}", input={"role": "user", "content": subagent_input_text}, metadata=subagent_metadata, **get_status_kwargs(get_worst_turn_status(turns)), ) + # Where the agent hangs: the parent it was first emitted under. + if entry is not None and entry.get("trace_id") and entry.get("parent_span_id"): + parent_ids: Optional[Tuple[str, str]] = (str(entry["trace_id"]), str(entry["parent_span_id"])) + else: + parent_ids = get_span_context_hex(parent_otel_span) if parent_otel_span is not None else None + incremental = ( + registry is not None + and parent_ids is not None + and size is not None + and install_deterministic_span_ids(langfuse) is not None + ) + + subagent_span = None + if incremental: + trace_id_hex, parent_span_id_hex = parent_ids + agent_span_id_hex = f"{derive_span_id(trace_id_hex, f'agent:{agent_id}'):016x}" + children_parent = carrier_span(trace_id_hex, agent_span_id_hex) + idle_seconds = 0.0 + try: + idle_seconds = time.time() - path.stat().st_mtime + except OSError: + pass + streaming_key = get_streaming_message_key(turns) + settled = ( + force + or known_finished + or agent_is_settled(turns) + # Killed mid-message: the last message never gets its stop_reason. + or (idle_seconds > AGENT_IDLE_SETTLE_SECONDS and streaming_key is not None + and agent_is_settled_but_for_streaming(turns)) + # Killed while waiting on a launch that will never notify; the + # same bound as a waiting main turn. + or idle_seconds > MAX_DEFER_SECONDS + ) + cursor = EmissionCursor( + emitted=set(k for k in (entry or {}).get("emitted", []) if isinstance(k, str)), + completed_only=not settled, + held={streaming_key} if streaming_key is not None and not settled else set(), + ) + else: + settled = True + subagent_span = _start_backdated(langfuse, parent_otel_span=parent_otel_span, **span_kwargs) + children_parent = subagent_span._otel_span + cursor = fresh_cursor() + latest_end_timestamp = subagent_start_timestamp previous_start_timestamp = subagent_start_timestamp - # The agent transcript is complete on disk, so history accumulates - # across its turns the same way as in the main conversation. + # History accumulates across the agent's turns the same way as in the + # main conversation. subagent_history: List[Dict[str, Any]] = [] - for turn in turns: - latest_turn_timestamp = emit_turn_observations( - langfuse, - subagent_span._otel_span, - turn, - previous_start_timestamp, - generation_name=generation_name, - # Agents launched by this agent are listed in the same map. - subagent_transcripts_by_tool_use_id=subagent_transcripts_by_tool_use_id, - history_prefix=list(subagent_history), - ) + for turn_index, turn in enumerate(turns): + with id_scope(f"{agent_id}:{turn_index}"): + latest_turn_timestamp = emit_turn_observations( + langfuse, + children_parent, + turn, + previous_start_timestamp, + generation_name=generation_name, + # Agents launched by this agent are listed in the same map. + subagent_transcripts_by_tool_use_id=subagent_transcripts_by_tool_use_id, + cursor=cursor, + workflow_agent_transcripts_by_run_id=workflow_agent_transcripts_by_run_id, + history_prefix=list(subagent_history), + ) subagent_history.extend(build_turn_history_messages(turn)) latest_end_timestamp = _get_latest_timestamp(latest_end_timestamp, latest_turn_timestamp) if latest_turn_timestamp is not None: previous_start_timestamp = latest_turn_timestamp - subagent_span.update(output={"role": "assistant", "content": subagent_output_text}) - subagent_span.end( - end_time=to_otel_nanoseconds( - _get_latest_timestamp(latest_end_timestamp, subagent_start_timestamp) + subagent_end_timestamp = _get_latest_timestamp(latest_end_timestamp, subagent_start_timestamp) + span_exported = bool(entry and entry.get("span_exported")) + if incremental and settled and not span_exported: + subagent_span = _start_backdated( + langfuse, + parent_otel_span=carrier_span(parent_ids[0], parent_ids[1]), + **span_kwargs, ) - ) + span_exported = True + if subagent_span is not None: + subagent_span.update(output={"role": "assistant", "content": subagent_output_text}) + subagent_span.end(end_time=to_otel_nanoseconds(subagent_end_timestamp)) + + if incremental: + registry.entries[agent_id] = { + "path": str(path), + "trace_id": parent_ids[0], + "parent_span_id": parent_ids[1], + "size": size, + "span_exported": span_exported, + # Re-visited every firing while set (see agent_entry_needs_visit). + "unsettled": not settled, + "held": sorted(cursor.held), + "idle_bound_s": ( + AGENT_IDLE_SETTLE_SECONDS if streaming_key is not None else MAX_DEFER_SECONDS + ) if not settled else None, + "start": subagent_start_timestamp.isoformat() if subagent_start_timestamp else None, + "end": subagent_end_timestamp.isoformat() if subagent_end_timestamp else None, + "emitted": sorted(cursor.emitted), + "span_name": span_name, + "generation_name": generation_name, + # The journal result is re-read on refresh; storing it would only + # grow the registry. + "extra_metadata": { + k: v for k, v in (extra_metadata or {}).items() if k != "workflow_agent_result" + }, + "agent_type": subagent.get("agent_type"), + "description": description, + } return latest_end_timestamp + +def refresh_grown_agents( + langfuse: Langfuse, + registry: AgentRegistry, + *, + subagent_transcripts_by_tool_use_id: Optional[Dict[str, Dict[str, Any]]] = None, + workflow_agent_transcripts_by_run_id: Optional["WorkflowAgentTranscriptsByRunId"] = None, +) -> int: + """Continue every registered agent whose transcript grew since the last + firing (and, at SessionEnd, every agent whose span has not shipped yet), + under the span it was first emitted under. Only observations not yet + exported ship; agents launched late by these agents are found by the + walk and emitted at their first sight.""" + refreshed = 0 + force = _FORCE_FINALIZE.get() + with active_agent_registry(registry): + for agent_id, entry in list(registry.entries.items()): + path = Path(str(entry.get("path") or "")) + size = _get_file_size(path) + if not agent_entry_needs_visit(entry, size, force, path): + continue + parent = carrier_span(str(entry.get("trace_id") or ""), str(entry.get("parent_span_id") or "")) + if parent is None: + continue + extra_metadata = dict(entry.get("extra_metadata") or {}) + empty_output_fallback = None + known_finished = False + run_id = extra_metadata.get("workflow_run_id") + if isinstance(run_id, str) and run_id: + result = get_workflow_journal_results(path.parent).get(agent_id) + known_finished = result is not None + if result is not None: + empty_output_fallback, _ = truncate_text(json.dumps(result, ensure_ascii=False)) + extra_metadata["workflow_agent_result"] = empty_output_fallback + try: + emit_subagent_observations( + langfuse, + parent, + { + "path": path, + "agent_id": agent_id, + "agent_type": entry.get("agent_type"), + "description": entry.get("description"), + }, + # The stored start is applied inside, from the entry. + None, + span_name=entry.get("span_name") if isinstance(entry.get("span_name"), str) else None, + extra_metadata=extra_metadata, + generation_name=str(entry.get("generation_name") or "Subagent LLM Call"), + empty_output_fallback=empty_output_fallback, + subagent_transcripts_by_tool_use_id=subagent_transcripts_by_tool_use_id, + workflow_agent_transcripts_by_run_id=workflow_agent_transcripts_by_run_id, + known_finished=known_finished, + ) + refreshed += 1 + except Exception as e: + info(f"continuing grown agent {agent_id} failed: {type(e).__name__}: {e}") + # One agent at a time, like a backlog of turns: keeps the span queue bounded. + flush_langfuse_client(langfuse) + if refreshed: + debug(f"Continued {refreshed} grown agent transcript(s)") + return refreshed + + +def split_jsonl_lines(text: str) -> List[str]: + """Split JSONL on newline only. str.splitlines() also breaks on U+2028, + U+2029, U+0085, form feed and friends, which JSON strings may carry raw: + the halves fail to parse and the whole row (an assistant message with + its final usage, say) is silently dropped.""" + return text.split("\n") + def read_subagent_jsonl(path: Path) -> Optional[List[Dict[str, Any]]]: try: - lines = path.read_text(encoding="utf-8").splitlines() + lines = split_jsonl_lines(path.read_text(encoding="utf-8")) except Exception as e: info(f"transcript read failed ({path}): {type(e).__name__}: {e}") return None @@ -3064,6 +3792,8 @@ def read_subagent_jsonl(path: Path) -> Optional[List[Dict[str, Any]]]: if not isinstance(row, dict): info(f"transcript line skipped ({path}:{line_number}): expected JSON object") continue + if is_request_echo_row(row): + continue rows.append(row) return rows @@ -3139,6 +3869,18 @@ def is_valid_span_id_hex(span_id: Any) -> bool: ) +# Set only by the backfill: re-uploaded turns land in traces of their own, so +# they can never mix with the observations a live firing put in the original +# traces (random-id ones from older versions included). +TRACE_SEED_NAMESPACE: Optional[str] = None + + +def turn_trace_seed(session_id: str, user_row_uuid: str) -> str: + if TRACE_SEED_NAMESPACE: + return f"{TRACE_SEED_NAMESPACE}:{session_id}:{user_row_uuid}" + return f"{session_id}:{user_row_uuid}" + + def remote_parent(langfuse: Langfuse, session_id: str, user_row_uuid: Any, root_span_id: Optional[str] = None, trace_id: Optional[str] = None) -> Optional[Any]: @@ -3168,7 +3910,7 @@ def remote_parent(langfuse: Langfuse, session_id: str, user_row_uuid: Any, trace_id = None try: if trace_id is None: - trace_id = langfuse.create_trace_id(seed=f"{session_id}:{user_row_uuid}") + trace_id = langfuse.create_trace_id(seed=turn_trace_seed(session_id, user_row_uuid)) parent_context = otel_trace_api.SpanContext( trace_id=int(trace_id, 16), span_id=int(root_span_id, 16) if root_span_id else (random.getrandbits(64) or 1), @@ -3215,6 +3957,7 @@ def open_turn_root_span(langfuse: Langfuse, session_id: str, turn_num: int, turn forced_trace_id=parent_trace_id, forced_parent_span_id=parent_span_id, as_root=False, + id_key=f"root:{turn.user_msg.get('uuid') or turn_num}", input=root_input, metadata=trace_metadata, **get_status_kwargs(get_turn_status(turn)), @@ -3234,6 +3977,7 @@ def open_turn_root_span(langfuse: Langfuse, session_id: str, turn_num: int, turn parent_otel_span=None if forced_trace_id else remote_parent(langfuse, session_id, turn.user_msg.get("uuid")), forced_trace_id=forced_trace_id, as_root=True, + id_key=f"root:{turn.user_msg.get('uuid') or turn_num}", input=root_input, metadata=trace_metadata, **get_status_kwargs(get_turn_status(turn)), @@ -3484,49 +4228,48 @@ def emit_ready_observations_of_open_turn( except Exception as e: info(f"emitting ready observations of open turn failed: {type(e).__name__}: {e}") -def emit_new_turns_from_transcript( +def emit_session_firing( langfuse: Langfuse, config: LangfuseConfig, session_id: str, transcript_path: Path, + session_state: SessionState, + agent_registry: AgentRegistry, *, flush_deferred_agent_turns: bool = False, ) -> int: - key = get_session_state_key(session_id, str(transcript_path)) - - with FileLock(get_session_lock_path(key)): - with FileLock(LOCK_FILE): - state = load_hook_state() - session_state = get_session_state(state, key) - - subagent_transcripts_by_tool_use_id = get_subagent_transcripts_by_tool_use_id(transcript_path) - if subagent_transcripts_by_tool_use_id: - debug(f"Discovered {len(subagent_transcripts_by_tool_use_id)} subagent transcript(s)") - - workflow_agent_transcripts_by_run_id = WorkflowAgentTranscriptsByRunId(transcript_path) + """One firing's emission over the given state: new turns, the ready part + of the open turn, then every registered agent whose transcript grew.""" + subagent_transcripts_by_tool_use_id = get_subagent_transcripts_by_tool_use_id(transcript_path) + if subagent_transcripts_by_tool_use_id: + debug(f"Discovered {len(subagent_transcripts_by_tool_use_id)} subagent transcript(s)") + + workflow_agent_transcripts_by_run_id = WorkflowAgentTranscriptsByRunId(transcript_path) + + turns, session_state = get_new_turns_from_transcript( + transcript_path, + session_state, + subagent_transcripts_by_tool_use_id, + flush_deferred_agent_turns=flush_deferred_agent_turns, + session_id=session_id, + ) - turns, session_state = get_new_turns_from_transcript( + # One full-file pass per firing serves every turn emitted below. + session_history = None + if CAPTURE_HISTORY and (turns or session_state.open_turn): + session_history = build_session_history( transcript_path, - session_state, - subagent_transcripts_by_tool_use_id, - flush_deferred_agent_turns=flush_deferred_agent_turns, - session_id=session_id, + get_task_id_to_tool_use_id(subagent_transcripts_by_tool_use_id), ) - # One full-file pass per firing serves every turn emitted below. - session_history = None - if CAPTURE_HISTORY and (turns or session_state.open_turn): - session_history = build_session_history( - transcript_path, - get_task_id_to_tool_use_id(subagent_transcripts_by_tool_use_id), - ) - - emitted = 0 + emitted = 0 + with active_agent_registry(agent_registry), force_finalize(flush_deferred_agent_turns): if turns: turns_to_emit = get_turns_to_emit( turns, session_state, flush_deferred_agent_turns=flush_deferred_agent_turns, + newest_timestamp=get_latest_row_timestamp([r for t in turns for r in t.rows]), ) emitted = emit_and_close_ready_turns( langfuse, @@ -3561,10 +4304,60 @@ def emit_new_turns_from_transcript( session_history=session_history, ) + if config.parent_context is None: + attribute_propagation = propagate_attributes( + session_id=session_id, + user_id=config.user_id, + trace_name=TRACE_NAME, + ) + else: + attribute_propagation = contextlib.nullcontext() + try: + with attribute_propagation, force_finalize(flush_deferred_agent_turns): + refresh_grown_agents( + langfuse, + agent_registry, + subagent_transcripts_by_tool_use_id=subagent_transcripts_by_tool_use_id, + workflow_agent_transcripts_by_run_id=workflow_agent_transcripts_by_run_id, + ) + except Exception as e: + info(f"refreshing grown agents failed: {type(e).__name__}: {e}") + return emitted + + +def emit_new_turns_from_transcript( + langfuse: Langfuse, + config: LangfuseConfig, + session_id: str, + transcript_path: Path, + *, + flush_deferred_agent_turns: bool = False, +) -> int: + key = get_session_state_key(session_id, str(transcript_path)) + + with FileLock(get_session_lock_path(key)): + with FileLock(LOCK_FILE): + state = load_hook_state() + session_state = get_session_state(state, key) + # Per-session file under the session lock: it can be large, and the + # shared state file is rewritten by every session's firing. + agent_registry = AgentRegistry.load(get_agent_registry_path(key)) + + emitted = emit_session_firing( + langfuse, + config, + session_id, + transcript_path, + session_state, + agent_registry, + flush_deferred_agent_turns=flush_deferred_agent_turns, + ) + # Known limitation (accepted, like the crash-between-emit-and-save # duplicate window): progress is persisted before the SDK flush in # main(); a dropped flush leaves emitted_keys pointing at spans that # never reached the server. + agent_registry.save() with FileLock(LOCK_FILE): state = load_hook_state() save_session_state(state, key, session_state) @@ -3593,6 +4386,447 @@ def _flush_and_shutdown(): pass +# ----------------- Backfill ----------------- +DEFAULT_BACKFILL_NAMESPACE = "backfill-v1" + + +class _RandomIds: + def generate_span_id(self) -> int: + return random.getrandbits(64) or 1 + + def generate_trace_id(self) -> int: + return random.getrandbits(128) or 1 + + def is_trace_id_random(self) -> bool: + return True + + +class _RecordingTracer: + """Dry-run tracer: real OTel span contexts (so nesting and trace ids + behave as in a live run), nothing recorded or exported by OTel.""" + + def __init__(self) -> None: + self.id_generator: Any = _RandomIds() + self.names: Dict[int, str] = {} + self.parents: Dict[int, int] = {} + + def start_span(self, *, name: str, start_time: Optional[int] = None, context: Any = None) -> Any: + parent_context = otel_trace_api.get_current_span(context).get_span_context() + span_id = self.id_generator.generate_span_id() + if parent_context is not None and parent_context.is_valid: + trace_id = parent_context.trace_id + self.parents[span_id] = parent_context.span_id + else: + trace_id = self.id_generator.generate_trace_id() + self.names[span_id] = name + # NonRecordingSpan is an OTel Span, so use_span/get_current_span + # accept it as a parent for the next span. + return otel_trace_api.NonRecordingSpan(otel_trace_api.SpanContext( + trace_id=trace_id, span_id=span_id, is_remote=False, + trace_flags=otel_trace_api.TraceFlags(0x01), + )) + + +class _RecordedObservation: + def __init__(self, recorder: "RecordingLangfuse", otel_span: Any, as_type: str, + kwargs: Dict[str, Any]) -> None: + self._recorder = recorder + self._otel_span = otel_span + context = otel_span.get_span_context() + self.id = f"{context.span_id:016x}" + self.trace_id = f"{context.trace_id:032x}" + self.name = recorder._otel_tracer.names.get(context.span_id, "") + self.as_type = as_type + self.usage_details = kwargs.get("usage_details") + metadata = kwargs.get("metadata") if isinstance(kwargs.get("metadata"), dict) else {} + self.transcript_path = metadata.get("transcript_path") if as_type == "span" else None + recorder.record(self) + + def update(self, **kwargs: Any) -> None: + if "usage_details" in kwargs: + self.usage_details = kwargs["usage_details"] + + def end(self, *, end_time: Optional[int] = None) -> None: + pass + + +class RecordingLangfuse: + """Stands in for the Langfuse client in a dry run: every observation the + emission would export is recorded by id instead of sent. An id seen twice + is a replacement on the server, never a second observation.""" + + def __init__(self) -> None: + self._otel_tracer = _RecordingTracer() + self.by_id: Dict[str, _RecordedObservation] = {} + self.emissions = 0 + + @staticmethod + def create_trace_id(*, seed: Optional[str] = None) -> str: + return Langfuse.create_trace_id(seed=seed) + + def record(self, observation: _RecordedObservation) -> None: + self.emissions += 1 + self.by_id[observation.id] = observation + + def _create_observation_from_otel_span(self, *, otel_span: Any, as_type: str, **kwargs: Any) -> Any: + return _RecordedObservation(self, otel_span, as_type, kwargs) + + def flush(self) -> None: + pass + + def summary(self) -> Dict[str, Any]: + usage: Dict[str, int] = {} + generations = 0 + zero_usage_generations = 0 + traces = set() + for observation in self.by_id.values(): + traces.add(observation.trace_id) + if observation.as_type != "generation": + continue + generations += 1 + if not observation.usage_details: + zero_usage_generations += 1 + continue + for k, v in observation.usage_details.items(): + usage[k] = usage.get(k, 0) + int(v) + return { + "observations": len(self.by_id), + "emissions": self.emissions, + "traces": len(traces), + "generations": generations, + "zero_usage_generations": zero_usage_generations, + "usage": usage, + } + + def per_agent(self) -> Dict[str, Dict[str, Any]]: + """Generations and usage per agent transcript (main = the session).""" + tracer = self._otel_tracer + agent_of_span: Dict[int, str] = {} + for observation in self.by_id.values(): + if observation.transcript_path and observation.name.startswith(("Subagent", "Workflow agent")): + agent_of_span[int(observation.id, 16)] = observation.transcript_path + + def owner(span_id: int) -> str: + seen = 0 + while span_id in tracer.parents and seen < 1000: + span_id = tracer.parents[span_id] + if span_id in agent_of_span: + return agent_of_span[span_id] + seen += 1 + return "main" + + out: Dict[str, Dict[str, Any]] = {} + for observation in self.by_id.values(): + if observation.as_type != "generation": + continue + entry = out.setdefault(owner(int(observation.id, 16)), {"generations": 0, "zero": 0, "usage": {}}) + entry["generations"] += 1 + if not observation.usage_details: + entry["zero"] += 1 + for k, v in (observation.usage_details or {}).items(): + entry["usage"][k] = entry["usage"].get(k, 0) + int(v) + for path in agent_of_span.values(): + out.setdefault(path, {"generations": 0, "zero": 0, "usage": {}}) + return out + + +def get_backfill_trace_ids(langfuse: Any, session_id: str, transcript_path: Path) -> set: + """Trace ids the backfill gives the turns of this transcript.""" + trace_ids = set() + rows = read_subagent_jsonl(transcript_path) or [] + for row in rows: + uuid = row.get("uuid") + if get_user_or_assistant_role_from_row(row) == "user" and isinstance(uuid, str) and uuid: + trace_ids.add(langfuse.create_trace_id(seed=turn_trace_seed(session_id, uuid))) + return trace_ids + + +def list_session_traces(langfuse: Any, session_id: str, *, with_observations: bool = False) -> List[Tuple[Any, ...]]: + """(id, name[, observation ids]) of every trace Langfuse holds for the + session (read-only).""" + traces_out: List[Tuple[Any, ...]] = [] + page = 1 + fields = "core,observations" if with_observations else "core" + while True: + traces = langfuse.api.trace.list(session_id=session_id, page=page, limit=100, fields=fields) + data = list(getattr(traces, "data", None) or []) + for trace in data: + trace_id = getattr(trace, "id", None) + if not trace_id: + continue + if with_observations: + traces_out.append((trace_id, getattr(trace, "name", None), set(getattr(trace, "observations", None) or []))) + else: + traces_out.append((trace_id, getattr(trace, "name", None))) + total_pages = getattr(getattr(traces, "meta", None), "total_pages", None) or page + if not data or page >= total_pages: + break + page += 1 + return traces_out + + +def plan_trace_replacement( + traces: List[Tuple[str, Optional[str]]], keep: set, +) -> Dict[str, List[str]]: + """Split the session's traces: this hook's earlier turn traces (to + delete), the backfill's own (kept), and anything another emitter put + under the same session id (never touched).""" + plan: Dict[str, List[str]] = {"delete": [], "keep": [], "foreign": []} + for item in traces: + trace_id, name = item[0], item[1] + if trace_id in keep: + plan["keep"].append(trace_id) + elif name == TRACE_NAME: + plan["delete"].append(trace_id) + else: + plan["foreign"].append(trace_id) + return plan + + +BACKFILL_VERIFY_ATTEMPTS = 40 +BACKFILL_VERIFY_INTERVAL_S = 15.0 + + +def record_uploaded_observation_ids(langfuse: Any) -> Dict[str, set]: + """Wrap the client so every observation the backfill creates is noted + per trace: the read-back compares the server against exactly this.""" + expected: Dict[str, set] = {} + create = langfuse._create_observation_from_otel_span + + def recording_create(*args: Any, **kwargs: Any) -> Any: + observation = create(*args, **kwargs) + trace_id, observation_id = getattr(observation, "trace_id", None), getattr(observation, "id", None) + if trace_id and observation_id: + expected.setdefault(trace_id, set()).add(observation_id) + return observation + + langfuse._create_observation_from_otel_span = recording_create + return expected + + +def verify_upload(langfuse: Any, session_id: str, expected: Dict[str, set]) -> Dict[str, int]: + """Read back until every uploaded observation is visible, or give up. + + flush() does not raise on a rejected batch (the exporter only logs it), + so this is the only proof the upload landed. Returns missing observation + counts per trace; empty means verified.""" + missing: Dict[str, int] = {t: len(ids) for t, ids in expected.items()} + for attempt in range(max(1, BACKFILL_VERIFY_ATTEMPTS)): + present = {item[0]: item[2] for item in list_session_traces(langfuse, session_id, with_observations=True)} + missing = { + trace_id: len(ids - present.get(trace_id, set())) + for trace_id, ids in expected.items() + if ids - present.get(trace_id, set()) + } + if not missing: + return {} + if attempt + 1 < BACKFILL_VERIFY_ATTEMPTS: + time.sleep(BACKFILL_VERIFY_INTERVAL_S) + return missing + + +def delete_traces(langfuse: Any, trace_ids: List[str]) -> int: + for i in range(0, len(trace_ids), 100): + langfuse.api.trace.delete_multiple(trace_ids=trace_ids[i:i + 100]) + return len(trace_ids) + + +def get_transcript_session_ids(transcript_path: Path) -> set: + ids = set() + for row in read_subagent_jsonl(transcript_path) or []: + session_id = row.get("sessionId") + if isinstance(session_id, str) and session_id: + ids.add(session_id) + return ids + + +BACKFILL_MIN_IDLE_MINUTES = 30.0 + + +def check_backfill_target(transcript_path: Path, session_id: str, *, force: bool) -> Optional[str]: + """Why the backfill must not run on this transcript, or None.""" + if transcript_path.stem != session_id: + return (f"session id {session_id!r} is not this transcript's ({transcript_path.stem!r}); " + "a wrong id would replace another session's traces") + if session_id not in get_transcript_session_ids(transcript_path): + return f"no row of {transcript_path.name} belongs to session {session_id!r}" + if not force: + try: + newest = transcript_path.stat().st_mtime + session_dir = transcript_path.with_suffix("") + if session_dir.is_dir(): + # Agents and workflows keep writing under the session + # directory after the main transcript goes quiet. + for child in session_dir.rglob("*"): + try: + newest = max(newest, child.stat().st_mtime) + except OSError: + continue + idle_minutes = (time.time() - newest) / 60 + except OSError as e: + return f"cannot stat {transcript_path}: {e}" + if idle_minutes < BACKFILL_MIN_IDLE_MINUTES: + return (f"{transcript_path.name} changed {idle_minutes:.0f} min ago; the session may still be " + f"live, or one of its agents (a live hook would add turns beside the backfill). Wait " + f"{BACKFILL_MIN_IDLE_MINUTES:.0f} min after it ends, or pass --force") + return None + + +def backfill_session( + langfuse: Any, + config: LangfuseConfig, + session_id: str, + transcript_path: Path, +) -> int: + """Emit a whole past session from its transcript in one pass, as at + SessionEnd: fresh state, every turn closed, every agent read in full. + Trace ids come from the backfill namespace and observation ids are + deterministic, so a second run would hit the same ids. Langfuse v4 does + not merge those at read time, so run_backfill refuses a namespace that + already has traces for the session instead of uploading twice.""" + session_state = SessionState() + registry = AgentRegistry(None) + return emit_session_firing( + langfuse, config, session_id, transcript_path, session_state, registry, + flush_deferred_agent_turns=True, + ) + + +def run_backfill(argv: List[str]) -> int: + import argparse + parser = argparse.ArgumentParser( + prog="langfuse_hook.py --backfill", + description="Re-upload one finished session from its transcript.", + ) + parser.add_argument("--backfill", required=True, metavar="TRANSCRIPT", + help="the session's main transcript, .jsonl") + parser.add_argument("--session-id", default=None, + help="must equal the transcript's own session id (default: its file name)") + parser.add_argument("--namespace", default=DEFAULT_BACKFILL_NAMESPACE, + help="trace-id namespace of the re-uploaded traces; a namespace is used once per session") + parser.add_argument("--dry-run", action="store_true", + help="build every observation and send nothing; with --replace-session-traces " + "and Langfuse keys, also list (read-only) the traces that would be deleted") + parser.add_argument("--per-agent-out", default=None, metavar="FILE", + help="dry run: write generations and usage per agent transcript as JSON") + parser.add_argument("--replace-session-traces", action="store_true", + help="after the upload, delete this hook's earlier turn traces of the session") + parser.add_argument("--verify-only", action="store_true", + help="upload nothing: read back an earlier upload of this namespace (ids are " + "deterministic) and, with --replace-session-traces, delete the old traces once it verifies") + parser.add_argument("--verify-minutes", type=float, default=None, + help="how long the read-back keeps retrying (default 10)") + parser.add_argument("--force", action="store_true", + help=f"run on a transcript modified less than {BACKFILL_MIN_IDLE_MINUTES:.0f} min ago") + args = parser.parse_args(argv) + + global TRACE_SEED_NAMESPACE, BACKFILL_VERIFY_ATTEMPTS + TRACE_SEED_NAMESPACE = args.namespace or DEFAULT_BACKFILL_NAMESPACE + if args.verify_minutes is not None: + BACKFILL_VERIFY_ATTEMPTS = max(1, int(args.verify_minutes * 60 / max(BACKFILL_VERIFY_INTERVAL_S, 1e-9)) + 1) + transcript_path = Path(args.backfill).expanduser() + if not transcript_path.is_file(): + print(f"no such transcript: {transcript_path}", file=sys.stderr) + return 2 + session_id = args.session_id or transcript_path.stem + refusal = check_backfill_target(transcript_path, session_id, force=args.force) + if refusal is not None: + print(f"refused: {refusal}", file=sys.stderr) + return 3 + + config = get_langfuse_config() + if config is not None and (config.trace_seed or config.parent_context): + print("backfill ignores CC_LANGFUSE_TRACE_SEED / parent trace context", file=sys.stderr) + config.trace_seed = None + config.parent_trace_id = config.parent_span_id = None + langfuse = create_langfuse_client(config) if config is not None else None + + keep_seed_client = langfuse if langfuse is not None else RecordingLangfuse() + keep = get_backfill_trace_ids(keep_seed_client, session_id, transcript_path) + existing: Optional[List[Tuple[str, Optional[str]]]] = None + # A dry run reads Langfuse only when asked for the delete plan. + if langfuse is not None and (not args.dry_run or args.replace_session_traces): + existing = list_session_traces(langfuse, session_id) + already = [item[0] for item in existing if item[0] in keep] + if already and not args.verify_only: + print(f"refused: namespace {TRACE_SEED_NAMESPACE!r} already holds {len(already)} trace(s) of " + f"session {session_id}; uploading again would count them twice. Use a new --namespace " + "with --replace-session-traces to supersede them.", file=sys.stderr) + if not args.dry_run: + return 3 + + if args.dry_run: + dry_config = config or LangfuseConfig(public_key="", secret_key="", host="", user_id=None) + recorder = RecordingLangfuse() + turns = backfill_session(recorder, dry_config, session_id, transcript_path) + summary = recorder.summary() + summary.update({"session_id": session_id, "namespace": TRACE_SEED_NAMESPACE, "turns": turns, + "agent_spans": sum(1 for o in recorder.by_id.values() + if o.as_type == "span" and o.name.startswith(("Subagent", "Workflow agent")))}) + if args.replace_session_traces: + if existing is None: + summary["replace_plan"] = "not listed: no Langfuse keys in the environment" + else: + plan = plan_trace_replacement(existing, keep) + summary["replace_plan"] = {k: len(v) for k, v in plan.items()} + summary["would_delete"] = plan["delete"] + print(json.dumps(summary, indent=2, sort_keys=True)) + if args.per_agent_out: + Path(args.per_agent_out).write_text( + json.dumps(recorder.per_agent(), indent=1, sort_keys=True), encoding="utf-8" + ) + if langfuse is not None: + langfuse.shutdown() + return 0 + + if langfuse is None: + log_missing_langfuse_config() + print("Langfuse keys missing (LANGFUSE_PUBLIC_KEY / LANGFUSE_SECRET_KEY)", file=sys.stderr) + return 2 + try: + if args.verify_only: + # Ids are deterministic: rebuild what the upload sent, send nothing. + recorder = RecordingLangfuse() + turns = backfill_session(recorder, config, session_id, transcript_path) + expected: Dict[str, set] = {} + for observation in recorder.by_id.values(): + expected.setdefault(observation.trace_id, set()).add(observation.id) + else: + # Upload first: if it fails part-way, the old traces are still there. + expected = record_uploaded_observation_ids(langfuse) + turns = backfill_session(langfuse, config, session_id, transcript_path) + langfuse.flush() + print(f"uploaded {turns} turn(s) of session {session_id} (namespace {TRACE_SEED_NAMESPACE})") + print(f"verifying {sum(len(v) for v in expected.values())} observation(s) in {len(expected)} trace(s)") + if not expected: + # Nothing to compare against would verify vacuously. + print("refused: the backfill produced no observations to verify; nothing was deleted.", + file=sys.stderr) + return 4 + missing = verify_upload(langfuse, session_id, expected) + if missing: + print(f"refused: {sum(missing.values())} uploaded observation(s) in {len(missing)} trace(s) " + f"are not readable back from Langfuse. Nothing was deleted.\n" + f" Still ingesting? Re-check without uploading: --verify-only with the same " + f"--namespace {TRACE_SEED_NAMESPACE} (add --replace-session-traces to delete the old " + f"traces once it verifies; --verify-minutes to wait longer).\n" + f" Upload failed? Start over with a new --namespace and --replace-session-traces; " + f"that also removes this partial upload.", file=sys.stderr) + return 4 + print("verified: every uploaded observation is readable back") + if args.replace_session_traces: + plan = plan_trace_replacement(list_session_traces(langfuse, session_id), keep) + deleted = delete_traces(langfuse, plan["delete"]) + print(f"deleted {deleted} earlier trace(s) of session {session_id}; kept " + f"{len(plan['foreign'])} trace(s) this hook did not name {TRACE_NAME!r}") + finally: + try: + langfuse.flush() + finally: + langfuse.shutdown() + return 0 + + # ----------------- Main ----------------- def main() -> int: start = time.time() @@ -3645,4 +4879,6 @@ def main() -> int: flush_and_shutdown_langfuse_client(langfuse) if __name__ == "__main__": + if "--backfill" in sys.argv[1:]: + sys.exit(run_backfill(sys.argv[1:])) sys.exit(main()) diff --git a/tests/conftest.py b/tests/conftest.py index 0dc1020..449c34e 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -95,6 +95,10 @@ def __init__(self, trace_id: int, span_id: int, is_remote: bool, trace_flags: An self.is_remote = is_remote self.trace_flags = trace_flags + @property + def is_valid(self) -> bool: + return bool(self.trace_id) and bool(self.span_id) + class NonRecordingSpan: def __init__(self, span_context: SpanContext) -> None: self._span_context = span_context @@ -102,14 +106,25 @@ def __init__(self, span_context: SpanContext) -> None: def get_span_context(self) -> SpanContext: return self._span_context + def set_attribute(self, key: str, value: Any) -> None: + pass + def set_span_in_context(span: Any, context: Any = None) -> dict[str, Any]: return {"current_span": span} + def get_current_span(context: Any = None) -> Any: + if isinstance(context, dict) and context.get("current_span") is not None: + return context["current_span"] + if _ACTIVE_SPAN_STACK and _ACTIVE_SPAN_STACK[-1] is not None: + return _ACTIVE_SPAN_STACK[-1] + return NonRecordingSpan(SpanContext(0, 0, False)) + trace_module.use_span = use_span trace_module.TraceFlags = TraceFlags trace_module.SpanContext = SpanContext trace_module.NonRecordingSpan = NonRecordingSpan trace_module.set_span_in_context = set_span_in_context + trace_module.get_current_span = get_current_span opentelemetry_module.trace = trace_module sys.modules["opentelemetry"] = opentelemetry_module sys.modules["opentelemetry.trace"] = trace_module @@ -145,8 +160,33 @@ def read_fixture_jsonl() -> Any: return read_jsonl +class FakeIdGenerator: + """Counter-based stand-in for OTel's RandomIdGenerator.""" + + def __init__(self) -> None: + self._span_ids = itertools.count(1) + self._trace_ids = itertools.count(1) + + def generate_span_id(self) -> int: + return next(self._span_ids) + + def generate_trace_id(self) -> int: + return (1 << 100) + next(self._trace_ids) + + def is_trace_id_random(self) -> bool: + return True + + +class _FakeSpanContext: + def __init__(self, trace_id: int, span_id: int) -> None: + self.trace_id = trace_id + self.span_id = span_id + self.is_remote = False + + class FakeOtelSpan: - def __init__(self, name: str, start_time: int | None, context: Any = None) -> None: + def __init__(self, name: str, start_time: int | None, context: Any = None, + trace_id: int = 0, span_id: int = 0) -> None: self.name = name self.start_time = start_time self.context = context @@ -154,17 +194,44 @@ def __init__(self, name: str, start_time: int | None, context: Any = None) -> No # The span this one was started under (via the stubbed use_span); # None for roots and carrier-context spans. self.parent = _ACTIVE_SPAN_STACK[-1] if _ACTIVE_SPAN_STACK else None + self._span_context = _FakeSpanContext(trace_id, span_id) + + def get_span_context(self) -> Any: + return self._span_context def set_attribute(self, key: str, value: Any) -> None: self.attributes[key] = value +def nests_under(observation: Any, parent_observation: Any) -> bool: + """Nesting as Langfuse sees it: the parent's span id, whether the child + was started under the parent object or under a carrier with its ids.""" + parent = observation._otel_span.parent + if parent is None or not hasattr(parent, "get_span_context"): + return False + a = parent.get_span_context() + b = parent_observation._otel_span.get_span_context() + return (a.trace_id, a.span_id) == (b.trace_id, b.span_id) + + class FakeTracer: - def start_span(self, *, name: str, start_time: int | None = None, context: Any = None) -> FakeOtelSpan: - return FakeOtelSpan(name, start_time, context) + """Mirrors the SDK tracer: the span id comes from self.id_generator, the + trace id from the parent span (active span or context carrier).""" + def __init__(self) -> None: + self.id_generator: Any = FakeIdGenerator() -_fake_observation_counter = itertools.count(1) + def start_span(self, *, name: str, start_time: int | None = None, context: Any = None) -> FakeOtelSpan: + parent = _ACTIVE_SPAN_STACK[-1] if _ACTIVE_SPAN_STACK else None + if context is not None and isinstance(context, dict): + parent = context.get("current_span", parent) + trace_id = 0 + if parent is not None and hasattr(parent, "get_span_context"): + trace_id = parent.get_span_context().trace_id + if not trace_id: + trace_id = self.id_generator.generate_trace_id() + span_id = self.id_generator.generate_span_id() + return FakeOtelSpan(name, start_time, context, trace_id=trace_id, span_id=span_id) class FakeObservation: @@ -175,10 +242,11 @@ def __init__(self, otel_span: FakeOtelSpan, as_type: str, kwargs: dict[str, Any] self.kwargs = kwargs self.output: Any = None self.end_time: int | None = None - # Mirror the SDK's hex id/trace_id attributes (span.py sets both). - n = next(_fake_observation_counter) - self.id = f"{n:016x}" - self.trace_id = f"{n:032x}" + # Mirror the SDK's hex id/trace_id attributes (span.py sets both, + # from the OTel span context). + context = otel_span.get_span_context() + self.id = f"{context.span_id:016x}" + self.trace_id = f"{context.trace_id:032x}" def update(self, **kwargs: Any) -> None: if "output" in kwargs: diff --git a/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript.jsonl b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript.jsonl new file mode 100644 index 0000000..4f2afe5 --- /dev/null +++ b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript.jsonl @@ -0,0 +1,11 @@ +{"type": "user", "timestamp": "2026-08-01T10:00:00.000Z", "sessionId": "session-resume", "uuid": "u-main-1", "version": "2.1.301", "message": {"role": "user", "content": "Run the batch."}} +{"type": "api-request", "sessionId": "session-resume", "id": "req-echo", "timestamp": "2026-08-01T10:00:01.000Z", "params": {"model": "claude-test"}, "tail": ["0000000000000000000000000000000000000000000000000000000000000000"]} +{"type": "api-request-blob", "sessionId": "session-resume", "hash": "0000000000000000000000000000000000000000000000000000000000000000", "message": {"role": "user", "content": "Run the batch."}} +{"type": "assistant", "timestamp": "2026-08-01T10:00:02.000Z", "sessionId": "session-resume", "uuid": "a-main-1", "version": "2.1.301", "message": {"id": "msg_main_1", "type": "message", "role": "assistant", "model": "claude-test", "content": [{"type": "tool_use", "id": "toolu_orch", "name": "Agent", "input": {"description": "Batch orchestrator", "prompt": "Drive the batch", "run_in_background": true}}], "stop_reason": "tool_use", "usage": {"input_tokens": 3, "output_tokens": 40, "cache_read_input_tokens": 1000, "cache_creation_input_tokens": 200, "service_tier": "standard", "speed": "standard", "cache_creation": {"ephemeral_5m_input_tokens": 200, "ephemeral_1h_input_tokens": 0}}}} +{"type": "user", "timestamp": "2026-08-01T10:00:03.000Z", "sessionId": "session-resume", "uuid": "r-main-1", "version": "2.1.301", "message": {"role": "user", "content": [{"tool_use_id": "toolu_orch", "type": "tool_result", "content": [{"type": "text", "text": "Async agent launched successfully.\nagentId: orch\nYou will be notified automatically when the agent completes."}]}]}, "toolUseResult": {"isAsync": true, "status": "async_launched", "agentId": "orch"}} +{"type": "assistant", "timestamp": "2026-08-01T10:00:04.000Z", "sessionId": "session-resume", "uuid": "a-main-2", "version": "2.1.301", "message": {"id": "msg_main_2", "type": "message", "role": "assistant", "model": "claude-test", "content": [{"type": "text", "text": "Launched."}], "stop_reason": "end_turn", "usage": {"input_tokens": 3, "output_tokens": 5, "cache_read_input_tokens": 1200, "cache_creation_input_tokens": 0, "service_tier": "standard", "speed": "standard"}}} +{"type": "user", "timestamp": "2026-08-01T10:05:00.000Z", "sessionId": "session-resume", "uuid": "u-main-s", "version": "2.1.301", "message": {"role": "user", "content": "Status?"}} +{"type": "assistant", "timestamp": "2026-08-01T10:05:02.000Z", "sessionId": "session-resume", "uuid": "a-main-s", "version": "2.1.301", "message": {"id": "msg_main_s", "type": "message", "role": "assistant", "model": "claude-test", "content": [{"type": "text", "text": "Still running."}], "stop_reason": "end_turn", "usage": {"input_tokens": 3, "output_tokens": 4, "cache_read_input_tokens": 1250, "cache_creation_input_tokens": 0, "service_tier": "standard", "speed": "standard"}}} +{"type": "user", "timestamp": "2026-08-01T10:09:00.000Z", "sessionId": "session-resume", "uuid": "u-main-2", "version": "2.1.301", "message": {"role": "user", "content": "\norch\ncompleted\nAgent finished\nThis agent stopped with background work of its own still running. It may resume on its own when that work completes or reports, and the same task-id notifies again if it does; the result below may be interim.\nWaiting on my background work.\n"}, "origin": {"kind": "task-notification"}, "promptSource": "system"} +{"type": "api-request-blob", "sessionId": "session-resume", "hash": "0000000000000000000000000000000000000000000000000000000000000000", "message": {"role": "assistant", "content": [{"type": "text", "text": "Launched."}]}} +{"type": "assistant", "timestamp": "2026-08-01T10:09:05.000Z", "sessionId": "session-resume", "uuid": "a-main-3", "version": "2.1.301", "message": {"id": "msg_main_3", "type": "message", "role": "assistant", "model": "claude-test", "content": [{"type": "text", "text": "Noted."}], "stop_reason": "end_turn", "usage": {"input_tokens": 3, "output_tokens": 4, "cache_read_input_tokens": 1300, "cache_creation_input_tokens": 0, "service_tier": "standard", "speed": "standard"}}} diff --git a/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-child1.jsonl b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-child1.jsonl new file mode 100644 index 0000000..24e3faa --- /dev/null +++ b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-child1.jsonl @@ -0,0 +1,4 @@ +{"type": "user", "timestamp": "2026-08-01T10:01:05.000Z", "sessionId": "session-resume", "uuid": "u-c1-1", "version": "2.1.301", "message": {"role": "user", "content": "Generate"}} +{"type": "api-request-blob", "sessionId": "session-resume", "hash": "0000000000000000000000000000000000000000000000000000000000000000", "message": {"role": "user", "content": "Generate"}} +{"type": "assistant", "timestamp": "2026-08-01T10:02:00.000Z", "sessionId": "session-resume", "uuid": "a-c1-1", "version": "2.1.301", "message": {"id": "msg_c1_1", "type": "message", "role": "assistant", "model": "claude-test", "content": [{"type": "tool_use", "id": "toolu_grand", "name": "Agent", "input": {"description": "Review grand", "prompt": "Review"}}], "stop_reason": "tool_use", "usage": {"input_tokens": 2, "output_tokens": 20, "cache_read_input_tokens": 7000, "cache_creation_input_tokens": 100, "service_tier": "standard", "speed": "standard", "cache_creation": {"ephemeral_5m_input_tokens": 100, "ephemeral_1h_input_tokens": 0}}}} +{"type": "api-request-blob", "sessionId": "session-resume", "hash": "0000000000000000000000000000000000000000000000000000000000000000", "message": {"role": "assistant", "content": [{"type": "tool_use", "id": "toolu_grand", "name": "Agent", "input": {"description": "Review grand"}}]}} diff --git a/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-child1.meta.json b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-child1.meta.json new file mode 100644 index 0000000..83b4cfe --- /dev/null +++ b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-child1.meta.json @@ -0,0 +1 @@ +{"agentType": "codegen-agent", "description": "Codegen child1", "toolUseId": "toolu_child1", "spawnDepth": 2, "parentAgentId": "orch", "requestShape": "background"} \ No newline at end of file diff --git a/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-grand.jsonl b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-grand.jsonl new file mode 100644 index 0000000..0c6f9ba --- /dev/null +++ b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-grand.jsonl @@ -0,0 +1,2 @@ +{"type": "user", "timestamp": "2026-08-01T10:02:05.000Z", "sessionId": "session-resume", "uuid": "u-g-1", "version": "2.1.301", "message": {"role": "user", "content": "Review"}} +{"type": "assistant", "timestamp": "2026-08-01T10:03:00.000Z", "sessionId": "session-resume", "uuid": "a-g-1", "version": "2.1.301", "message": {"id": "msg_g_1", "type": "message", "role": "assistant", "model": "claude-test", "content": [{"type": "text", "text": "Reviewing."}], "stop_reason": "end_turn", "usage": {"input_tokens": 2, "output_tokens": 6, "cache_read_input_tokens": 800, "cache_creation_input_tokens": 50, "service_tier": "standard", "speed": "standard", "cache_creation": {"ephemeral_5m_input_tokens": 50, "ephemeral_1h_input_tokens": 0}}}} diff --git a/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-grand.meta.json b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-grand.meta.json new file mode 100644 index 0000000..402c9b7 --- /dev/null +++ b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-grand.meta.json @@ -0,0 +1 @@ +{"agentType": "review-codegen-agent", "description": "Review grand", "toolUseId": "toolu_grand", "spawnDepth": 3, "parentAgentId": "child1"} \ No newline at end of file diff --git a/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-orch.jsonl b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-orch.jsonl new file mode 100644 index 0000000..4ca2d50 --- /dev/null +++ b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-orch.jsonl @@ -0,0 +1,11 @@ +{"type": "user", "timestamp": "2026-08-01T10:00:05.000Z", "sessionId": "session-resume", "uuid": "u-orch-1", "version": "2.1.301", "message": {"role": "user", "content": "Drive the batch"}} +{"type": "api-request", "sessionId": "session-resume", "id": "req-echo", "timestamp": "2026-08-01T10:00:06.000Z", "params": {"model": "claude-test"}, "tail": ["0000000000000000000000000000000000000000000000000000000000000000"]} +{"type": "api-request-blob", "sessionId": "session-resume", "hash": "0000000000000000000000000000000000000000000000000000000000000000", "message": {"role": "system", "content": "sys"}} +{"type": "api-request-blob", "sessionId": "session-resume", "hash": "0000000000000000000000000000000000000000000000000000000000000000", "message": {"role": "user", "content": "Drive the batch"}} +{"type": "assistant", "timestamp": "2026-08-01T10:01:00.000Z", "sessionId": "session-resume", "uuid": "a-orch-1a", "version": "2.1.301", "message": {"id": "msg_orch_1", "type": "message", "role": "assistant", "model": "claude-test", "content": [{"type": "thinking", "thinking": "plan", "signature": "x"}], "stop_reason": null, "usage": {"input_tokens": 2, "output_tokens": 7, "cache_read_input_tokens": 5000, "cache_creation_input_tokens": 300, "service_tier": "standard", "speed": "standard", "cache_creation": {"ephemeral_5m_input_tokens": 300, "ephemeral_1h_input_tokens": 0}}}} +{"type": "assistant", "timestamp": "2026-08-01T10:01:01.000Z", "sessionId": "session-resume", "uuid": "a-orch-1b", "version": "2.1.301", "message": {"id": "msg_orch_1", "type": "message", "role": "assistant", "model": "claude-test", "content": [{"type": "tool_use", "id": "toolu_child1", "name": "Agent", "input": {"description": "Codegen child1", "prompt": "Generate", "run_in_background": true}}], "stop_reason": "tool_use", "usage": {"input_tokens": 2, "output_tokens": 90, "cache_read_input_tokens": 5000, "cache_creation_input_tokens": 300, "service_tier": "standard", "speed": "standard", "cache_creation": {"ephemeral_5m_input_tokens": 300, "ephemeral_1h_input_tokens": 0}}}} +{"type": "user", "timestamp": "2026-08-01T10:01:02.000Z", "sessionId": "session-resume", "uuid": "r-orch-1", "version": "2.1.301", "message": {"role": "user", "content": [{"tool_use_id": "toolu_child1", "type": "tool_result", "content": [{"type": "text", "text": "Async agent launched successfully.\nagentId: child1\nYou will be notified automatically when the agent completes."}]}]}, "toolUseResult": {"isAsync": true, "status": "async_launched", "agentId": "child1"}} +{"type": "api-request-blob", "sessionId": "session-resume", "hash": "0000000000000000000000000000000000000000000000000000000000000000", "message": {"role": "assistant", "content": [{"type": "tool_use", "id": "toolu_child1", "name": "Agent", "input": {"description": "Codegen child1"}}]}} +{"type": "assistant", "timestamp": "2026-08-01T10:01:03.000Z", "sessionId": "session-resume", "uuid": "a-orch-2", "version": "2.1.301", "message": {"id": "msg_orch_2", "type": "message", "role": "assistant", "model": "claude-test", "content": [{"type": "tool_use", "id": "toolu_wf", "name": "Workflow", "input": {"script": "round"}}], "stop_reason": "tool_use", "usage": {"input_tokens": 2, "output_tokens": 30, "cache_read_input_tokens": 5400, "cache_creation_input_tokens": 0, "service_tier": "standard", "speed": "standard"}}} +{"type": "user", "timestamp": "2026-08-01T10:02:00.000Z", "sessionId": "session-resume", "uuid": "r-orch-2", "version": "2.1.301", "message": {"role": "user", "content": [{"tool_use_id": "toolu_wf", "type": "tool_result", "content": "Workflow finished."}]}, "toolUseResult": {"taskType": "local_workflow", "runId": "wf_t1", "workflowName": "round"}} +{"type": "assistant", "timestamp": "2026-08-01T10:08:00.000Z", "sessionId": "session-resume", "uuid": "a-orch-3", "version": "2.1.301", "message": {"id": "msg_orch_3", "type": "message", "role": "assistant", "model": "claude-test", "content": [{"type": "text", "text": "Waiting on my background work."}], "stop_reason": "end_turn", "usage": {"input_tokens": 2, "output_tokens": 9, "cache_read_input_tokens": 5600, "cache_creation_input_tokens": 0, "service_tier": "standard", "speed": "standard"}}} diff --git a/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-orch.meta.json b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-orch.meta.json new file mode 100644 index 0000000..9176b52 --- /dev/null +++ b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-orch.meta.json @@ -0,0 +1 @@ +{"agentType": "general-purpose", "description": "Batch orchestrator", "toolUseId": "toolu_orch", "spawnDepth": 1, "requestShape": "background"} \ No newline at end of file diff --git a/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-wchild.jsonl b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-wchild.jsonl new file mode 100644 index 0000000..7335398 --- /dev/null +++ b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-wchild.jsonl @@ -0,0 +1,2 @@ +{"type": "user", "timestamp": "2026-08-01T10:01:25.000Z", "sessionId": "session-resume", "uuid": "u-wc-1", "version": "2.1.301", "message": {"role": "user", "content": "Help"}} +{"type": "assistant", "timestamp": "2026-08-01T10:01:30.000Z", "sessionId": "session-resume", "uuid": "a-wc-1", "version": "2.1.301", "message": {"id": "msg_wc_1", "type": "message", "role": "assistant", "model": "claude-test", "content": [{"type": "text", "text": "helped"}], "stop_reason": "end_turn", "usage": {"input_tokens": 2, "output_tokens": 4, "cache_read_input_tokens": 400, "cache_creation_input_tokens": 0, "service_tier": "standard", "speed": "standard"}}} diff --git a/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-wchild.meta.json b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-wchild.meta.json new file mode 100644 index 0000000..056d3cd --- /dev/null +++ b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-wchild.meta.json @@ -0,0 +1 @@ +{"agentType": "general-purpose", "description": "Helper wchild", "toolUseId": "toolu_wchild", "spawnDepth": 2} \ No newline at end of file diff --git a/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/workflows/wf_t1/agent-w1.jsonl b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/workflows/wf_t1/agent-w1.jsonl new file mode 100644 index 0000000..8808eb1 --- /dev/null +++ b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/workflows/wf_t1/agent-w1.jsonl @@ -0,0 +1,4 @@ +{"type": "user", "timestamp": "2026-08-01T10:01:10.000Z", "sessionId": "session-resume", "uuid": "u-w1-1", "version": "2.1.301", "message": {"role": "user", "content": "Write the unit"}} +{"type": "assistant", "timestamp": "2026-08-01T10:01:20.000Z", "sessionId": "session-resume", "uuid": "a-w1-1", "version": "2.1.301", "message": {"id": "msg_w1_1", "type": "message", "role": "assistant", "model": "claude-test", "content": [{"type": "tool_use", "id": "toolu_wchild", "name": "Agent", "input": {"description": "Helper wchild", "prompt": "Help"}}], "stop_reason": "tool_use", "usage": {"input_tokens": 2, "output_tokens": 15, "cache_read_input_tokens": 3000, "cache_creation_input_tokens": 0, "service_tier": "standard", "speed": "standard"}}} +{"type": "user", "timestamp": "2026-08-01T10:01:40.000Z", "sessionId": "session-resume", "uuid": "r-w1-1", "version": "2.1.301", "message": {"role": "user", "content": [{"tool_use_id": "toolu_wchild", "type": "tool_result", "content": [{"type": "text", "text": "helped"}]}]}, "toolUseResult": {"status": "completed"}} +{"type": "assistant", "timestamp": "2026-08-01T10:01:50.000Z", "sessionId": "session-resume", "uuid": "a-w1-2", "version": "2.1.301", "message": {"id": "msg_w1_2", "type": "message", "role": "assistant", "model": "claude-test", "content": [{"type": "text", "text": "unit written"}], "stop_reason": "end_turn", "usage": {"input_tokens": 2, "output_tokens": 3, "cache_read_input_tokens": 3100, "cache_creation_input_tokens": 0, "service_tier": "standard", "speed": "standard"}}} diff --git a/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/workflows/wf_t1/agent-w1.meta.json b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/workflows/wf_t1/agent-w1.meta.json new file mode 100644 index 0000000..62ca119 --- /dev/null +++ b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/workflows/wf_t1/agent-w1.meta.json @@ -0,0 +1 @@ +{"agentType": "round-writer"} \ No newline at end of file diff --git a/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/workflows/wf_t1/journal.jsonl b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/workflows/wf_t1/journal.jsonl new file mode 100644 index 0000000..493c1a3 --- /dev/null +++ b/tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/workflows/wf_t1/journal.jsonl @@ -0,0 +1 @@ +{"type": "result", "agentId": "w1", "result": {"ok": true}} diff --git a/tests/fixtures/transcripts/resumed_background_agent/phase2/transcript.jsonl b/tests/fixtures/transcripts/resumed_background_agent/phase2/transcript.jsonl new file mode 100644 index 0000000..b140912 --- /dev/null +++ b/tests/fixtures/transcripts/resumed_background_agent/phase2/transcript.jsonl @@ -0,0 +1,5 @@ +{"type": "user", "timestamp": "2026-08-01T10:40:00.000Z", "sessionId": "session-resume", "uuid": "u-main-3", "version": "2.1.301", "message": {"role": "user", "content": "\norch\ncompleted\nAgent finished\nBatch done.\n"}, "origin": {"kind": "task-notification"}, "promptSource": "system"} +{"type": "api-request-blob", "sessionId": "session-resume", "hash": "0000000000000000000000000000000000000000000000000000000000000000", "message": {"role": "user", "content": "echo"}} +{"type": "assistant", "timestamp": "2026-08-01T10:40:05.000Z", "sessionId": "session-resume", "uuid": "a-main-4", "version": "2.1.301", "message": {"id": "msg_main_4", "type": "message", "role": "assistant", "model": "claude-test", "content": [{"type": "text", "text": "Batch closed."}], "stop_reason": "end_turn", "usage": {"input_tokens": 3, "output_tokens": 6, "cache_read_input_tokens": 1400, "cache_creation_input_tokens": 0, "service_tier": "standard", "speed": "standard"}}} +{"type": "user", "timestamp": "2026-08-01T10:45:00.000Z", "sessionId": "session-resume", "uuid": "u-main-4", "version": "2.1.301", "message": {"role": "user", "content": "Thanks."}} +{"type": "assistant", "timestamp": "2026-08-01T10:45:02.000Z", "sessionId": "session-resume", "uuid": "a-main-5", "version": "2.1.301", "message": {"id": "msg_main_5", "type": "message", "role": "assistant", "model": "claude-test", "content": [{"type": "text", "text": "OK."}], "stop_reason": "end_turn", "usage": {"input_tokens": 3, "output_tokens": 2, "cache_read_input_tokens": 1500, "cache_creation_input_tokens": 0, "service_tier": "standard", "speed": "standard"}}} diff --git a/tests/fixtures/transcripts/resumed_background_agent/phase2/transcript/subagents/agent-child1.jsonl b/tests/fixtures/transcripts/resumed_background_agent/phase2/transcript/subagents/agent-child1.jsonl new file mode 100644 index 0000000..535909a --- /dev/null +++ b/tests/fixtures/transcripts/resumed_background_agent/phase2/transcript/subagents/agent-child1.jsonl @@ -0,0 +1,2 @@ +{"type": "user", "timestamp": "2026-08-01T10:15:00.000Z", "sessionId": "session-resume", "uuid": "r-c1-1", "version": "2.1.301", "message": {"role": "user", "content": [{"tool_use_id": "toolu_grand", "type": "tool_result", "content": [{"type": "text", "text": "Review passed."}]}]}, "toolUseResult": {"status": "completed"}} +{"type": "assistant", "timestamp": "2026-08-01T10:19:00.000Z", "sessionId": "session-resume", "uuid": "a-c1-2", "version": "2.1.301", "message": {"id": "msg_c1_2", "type": "message", "role": "assistant", "model": "claude-test", "content": [{"type": "text", "text": "child1 done"}], "stop_reason": "end_turn", "usage": {"input_tokens": 2, "output_tokens": 8, "cache_read_input_tokens": 7100, "cache_creation_input_tokens": 0, "service_tier": "standard", "speed": "standard"}}} diff --git a/tests/fixtures/transcripts/resumed_background_agent/phase2/transcript/subagents/agent-child2.jsonl b/tests/fixtures/transcripts/resumed_background_agent/phase2/transcript/subagents/agent-child2.jsonl new file mode 100644 index 0000000..a5fbd8a --- /dev/null +++ b/tests/fixtures/transcripts/resumed_background_agent/phase2/transcript/subagents/agent-child2.jsonl @@ -0,0 +1,2 @@ +{"type": "user", "timestamp": "2026-08-01T10:21:05.000Z", "sessionId": "session-resume", "uuid": "u-c2-1", "version": "2.1.301", "message": {"role": "user", "content": "Generate more"}} +{"type": "assistant", "timestamp": "2026-08-01T10:30:00.000Z", "sessionId": "session-resume", "uuid": "a-c2-1", "version": "2.1.301", "message": {"id": "msg_c2_1", "type": "message", "role": "assistant", "model": "claude-test", "content": [{"type": "text", "text": "child2 done"}], "stop_reason": "end_turn", "usage": {"input_tokens": 2, "output_tokens": 70, "cache_read_input_tokens": 8000, "cache_creation_input_tokens": 400, "service_tier": "standard", "speed": "standard", "cache_creation": {"ephemeral_5m_input_tokens": 400, "ephemeral_1h_input_tokens": 0}}}} diff --git a/tests/fixtures/transcripts/resumed_background_agent/phase2/transcript/subagents/agent-child2.meta.json b/tests/fixtures/transcripts/resumed_background_agent/phase2/transcript/subagents/agent-child2.meta.json new file mode 100644 index 0000000..c07b2e6 --- /dev/null +++ b/tests/fixtures/transcripts/resumed_background_agent/phase2/transcript/subagents/agent-child2.meta.json @@ -0,0 +1 @@ +{"agentType": "codegen-agent", "description": "Codegen child2", "toolUseId": "toolu_child2", "spawnDepth": 2, "parentAgentId": "orch", "requestShape": "background"} \ No newline at end of file diff --git a/tests/fixtures/transcripts/resumed_background_agent/phase2/transcript/subagents/agent-grand.jsonl b/tests/fixtures/transcripts/resumed_background_agent/phase2/transcript/subagents/agent-grand.jsonl new file mode 100644 index 0000000..9d872e4 --- /dev/null +++ b/tests/fixtures/transcripts/resumed_background_agent/phase2/transcript/subagents/agent-grand.jsonl @@ -0,0 +1,2 @@ +{"type": "user", "timestamp": "2026-08-01T10:14:00.000Z", "sessionId": "session-resume", "uuid": "u-g-2", "version": "2.1.301", "message": {"role": "user", "content": "Anything else?"}} +{"type": "assistant", "timestamp": "2026-08-01T10:14:30.000Z", "sessionId": "session-resume", "uuid": "a-g-2", "version": "2.1.301", "message": {"id": "msg_g_2", "type": "message", "role": "assistant", "model": "claude-test", "content": [{"type": "text", "text": "Review passed."}], "stop_reason": "end_turn", "usage": {"input_tokens": 2, "output_tokens": 5, "cache_read_input_tokens": 900, "cache_creation_input_tokens": 0, "service_tier": "standard", "speed": "standard"}}} diff --git a/tests/fixtures/transcripts/resumed_background_agent/phase2/transcript/subagents/agent-orch.jsonl b/tests/fixtures/transcripts/resumed_background_agent/phase2/transcript/subagents/agent-orch.jsonl new file mode 100644 index 0000000..e4ecdf6 --- /dev/null +++ b/tests/fixtures/transcripts/resumed_background_agent/phase2/transcript/subagents/agent-orch.jsonl @@ -0,0 +1,10 @@ +{"type": "attachment", "timestamp": "2026-08-01T10:20:00.000Z", "sessionId": "session-resume", "uuid": "n-orch-2", "version": "2.1.301", "attachment": {"type": "queued_command", "prompt": "\nchild1\ntoolu_child1\ncompleted\nAgent finished\nchild1 done\n", "commandMode": "task-notification", "origin": {"kind": "task-notification"}}} +{"type": "api-request", "sessionId": "session-resume", "id": "req-echo", "timestamp": "2026-08-01T10:20:01.000Z", "params": {"model": "claude-test"}, "tail": ["0000000000000000000000000000000000000000000000000000000000000000"]} +{"type": "api-request-blob", "sessionId": "session-resume", "hash": "0000000000000000000000000000000000000000000000000000000000000000", "message": {"role": "assistant", "content": [{"type": "text", "text": "Waiting on my background work."}]}} +{"type": "assistant", "timestamp": "2026-08-01T10:21:00.000Z", "sessionId": "session-resume", "uuid": "a-orch-4", "version": "2.1.301", "message": {"id": "msg_orch_4", "type": "message", "role": "assistant", "model": "claude-test", "content": [{"type": "tool_use", "id": "toolu_child2", "name": "Agent", "input": {"description": "Codegen child2", "prompt": "Generate more", "run_in_background": true}}], "stop_reason": "tool_use", "usage": {"input_tokens": 2, "output_tokens": 50, "cache_read_input_tokens": 6000, "cache_creation_input_tokens": 0, "service_tier": "standard", "speed": "standard"}}} +{"type": "user", "timestamp": "2026-08-01T10:21:01.000Z", "sessionId": "session-resume", "uuid": "r-orch-3", "version": "2.1.301", "message": {"role": "user", "content": [{"tool_use_id": "toolu_child2", "type": "tool_result", "content": [{"type": "text", "text": "Async agent launched successfully.\nagentId: child2\nYou will be notified automatically when the agent completes."}]}]}, "toolUseResult": {"isAsync": true, "status": "async_launched", "agentId": "child2"}} +{"type": "assistant", "timestamp": "2026-08-01T10:21:02.000Z", "sessionId": "session-resume", "uuid": "a-orch-5", "version": "2.1.301", "message": {"id": "msg_orch_5", "type": "message", "role": "assistant", "model": "claude-test", "content": [{"type": "text", "text": "Waiting again."}], "stop_reason": "end_turn", "usage": {"input_tokens": 2, "output_tokens": 4, "cache_read_input_tokens": 6100, "cache_creation_input_tokens": 0, "service_tier": "standard", "speed": "standard"}}} +{"type": "user", "timestamp": "2026-08-01T10:25:00.000Z", "sessionId": "session-resume", "uuid": "u-orch-msg", "version": "2.1.301", "message": {"role": "user", "content": "Status of child2?"}} +{"type": "assistant", "timestamp": "2026-08-01T10:25:02.000Z", "sessionId": "session-resume", "uuid": "a-orch-m", "version": "2.1.301", "message": {"id": "msg_orch_m", "type": "message", "role": "assistant", "model": "claude-test", "content": [{"type": "text", "text": "Still waiting."}], "stop_reason": "end_turn", "usage": {"input_tokens": 2, "output_tokens": 3, "cache_read_input_tokens": 6150, "cache_creation_input_tokens": 0, "service_tier": "standard", "speed": "standard"}}} +{"type": "attachment", "timestamp": "2026-08-01T10:35:00.000Z", "sessionId": "session-resume", "uuid": "n-orch-3", "version": "2.1.301", "attachment": {"type": "queued_command", "prompt": "\nchild2\ntoolu_child2\ncompleted\nAgent finished\nchild2 done\n", "commandMode": "task-notification", "origin": {"kind": "task-notification"}}} +{"type": "assistant", "timestamp": "2026-08-01T10:39:00.000Z", "sessionId": "session-resume", "uuid": "a-orch-6", "version": "2.1.301", "message": {"id": "msg_orch_6", "type": "message", "role": "assistant", "model": "claude-test", "content": [{"type": "text", "text": "Batch done."}], "stop_reason": "end_turn", "usage": {"input_tokens": 2, "output_tokens": 11, "cache_read_input_tokens": 6200, "cache_creation_input_tokens": 0, "service_tier": "standard", "speed": "standard"}}} diff --git a/tests/integration/test_agent_completion.py b/tests/integration/test_agent_completion.py new file mode 100644 index 0000000..c38f005 --- /dev/null +++ b/tests/integration/test_agent_completion.py @@ -0,0 +1,396 @@ +"""When an agent (and a waiting turn) counts as finished. + +Synthetic transcripts in the Claude Code 2.1.301 shapes. Every test counts +RAW exports: Langfuse v4 reads do not merge two exports of one id. +""" +from __future__ import annotations + +import json +from collections import Counter +from pathlib import Path +from typing import Any, Dict, List + +SESSION = "session-completion" + + +def ts(minute: int, second: int = 0, hour: int = 10) -> str: + return f"2026-08-02T{hour:02d}:{minute:02d}:{second:02d}.000Z" + + +def user(uuid: str, t: str, content: Any, **extra: Any) -> Dict[str, Any]: + row = {"type": "user", "uuid": uuid, "timestamp": t, "sessionId": SESSION, + "message": {"role": "user", "content": content}} + row.update(extra) + return row + + +def asst(uuid: str, t: str, mid: str, content: List[Any], output: int, stop: Any) -> Dict[str, Any]: + return {"type": "assistant", "uuid": uuid, "timestamp": t, "sessionId": SESSION, + "message": {"id": mid, "role": "assistant", "model": "claude-test", "content": content, + "stop_reason": stop, "usage": {"input_tokens": 1, "output_tokens": output}}} + + +def agent_launch(tid: str, description: str) -> Dict[str, Any]: + return {"type": "tool_use", "id": tid, "name": "Agent", + "input": {"description": description, "prompt": "go", "run_in_background": True}} + + +def launched(uuid: str, t: str, tid: str, agent_id: str) -> Dict[str, Any]: + return user(uuid, t, [{"type": "tool_result", "tool_use_id": tid, + "content": [{"type": "text", "text": "Async agent launched successfully."}]}], + toolUseResult={"isAsync": True, "status": "async_launched", "agentId": agent_id}) + + +def notification_text(task_id: str, tid: str, result: str) -> str: + return (f"\n{task_id}\n{tid}\n" + f"completed\n{result}\n") + + +def write(path: Path, rows: List[Dict[str, Any]], mode: str = "w") -> None: + path.parent.mkdir(parents=True, exist_ok=True) + with path.open(mode, encoding="utf-8") as f: + for row in rows: + f.write(json.dumps(row) + "\n") + + +def setup_session(tmp_path: Path, agent_rows: List[Dict[str, Any]]) -> Path: + """main launches agent x in the background; x's final notification + reaches main, so main's turn emits x at the first firing.""" + sub = tmp_path / "transcript" / "subagents" + sub.mkdir(parents=True) + (sub / "agent-x.meta.json").write_text(json.dumps({"description": "Agent x", "toolUseId": "toolu_x"})) + write(sub / "agent-x.jsonl", agent_rows) + (sub / "agent-y.meta.json").write_text(json.dumps({"description": "Agent y", "toolUseId": "toolu_y"})) + write(sub / "agent-y.jsonl", [ + user("y-u", ts(1, 10), "go"), + asst("y-a", ts(1, 20), "msg_y", [{"type": "text", "text": "y done"}], 5, "end_turn"), + ]) + transcript = tmp_path / "transcript.jsonl" + write(transcript, [ + user("m-u1", ts(0), "start"), + asst("m-a1", ts(0, 1), "msg_m1", [agent_launch("toolu_x", "Agent x")], 2, "tool_use"), + launched("m-r1", ts(0, 2), "toolu_x", "x"), + asst("m-a2", ts(0, 3), "msg_m2", [{"type": "text", "text": "launched"}], 2, "end_turn"), + user("m-n1", ts(3), notification_text("x", "toolu_x", "x said done"), origin={"kind": "task-notification"}), + user("m-u2", ts(4), "next"), + asst("m-a3", ts(4, 1), "msg_m3", [{"type": "text", "text": "ok"}], 2, "end_turn"), + ]) + return transcript + + +def fire(hook_module: Any, fake_langfuse: Any, transcript: Path, *, end: bool = False) -> None: + config = hook_module.LangfuseConfig("public", "secret", "https://example.test", None) + hook_module.emit_new_turns_from_transcript(fake_langfuse, config, SESSION, transcript, + flush_deferred_agent_turns=end) + + +def spans_of(fake_langfuse: Any, description: str) -> List[Any]: + return [o for o in fake_langfuse.observations if o.name == f"Subagent: {description}"] + + +def generation_outputs(fake_langfuse: Any) -> List[int]: + return sorted(int((o.kwargs.get("usage_details") or {}).get("output", 0)) + for o in fake_langfuse.observations if o.as_type == "generation") + + +def assert_no_id_twice(fake_langfuse: Any) -> None: + counts = Counter(o.id for o in fake_langfuse.observations) + assert [i for i, n in counts.items() if n > 1] == [] + + +# x launches y in the background; y's notification reaches x as an isMeta +# user row, the way a subagent receives it. +X_WITH_META_NOTIFICATION = [ + user("x-u", ts(0, 5), "go"), + asst("x-a1", ts(1), "msg_x1", [agent_launch("toolu_y", "Agent y")], 3, "tool_use"), + launched("x-r1", ts(1, 1), "toolu_y", "y"), + asst("x-a2", ts(1, 2), "msg_x2", [{"type": "text", "text": "waiting"}], 3, "end_turn"), + user("x-n1", ts(2), "[SYSTEM NOTIFICATION - NOT USER INPUT]\n" + notification_text("y", "toolu_y", "y done"), + isMeta=True, origin={"kind": "task-notification"}), + asst("x-a3", ts(2, 30), "msg_x3", [{"type": "text", "text": "x done"}], 7, "end_turn"), +] + + +def test_meta_notification_resolves_the_launch_and_the_agent_settles(hook_module, fake_langfuse, tmp_path): + transcript = setup_session(tmp_path, X_WITH_META_NOTIFICATION) + fire(hook_module, fake_langfuse, transcript) + assert len(spans_of(fake_langfuse, "Agent x")) == 1, "x did not settle at the Stop" + # x's three generations ship at the Stop, not only at SessionEnd. + assert [3, 3, 7] == sorted(o for o in generation_outputs(fake_langfuse) if o in (3, 7)) + assert_no_id_twice(fake_langfuse) + + +def test_last_message_still_being_written_is_held(hook_module, fake_langfuse, tmp_path): + rows = [ + user("x-u", ts(0, 5), "go"), + asst("x-a1", ts(1), "msg_x1", [{"type": "text", "text": "step"}], 9, "end_turn"), + # Only the first part of msg_x2 is on disk: partial usage, no stop_reason. + asst("x-a2a", ts(1, 5), "msg_x2", [{"type": "thinking", "thinking": "hm", "signature": "s"}], 4, None), + ] + transcript = setup_session(tmp_path, rows) + fire(hook_module, fake_langfuse, transcript) + assert spans_of(fake_langfuse, "Agent x") == [], "a half-written agent settled" + assert 4 not in generation_outputs(fake_langfuse), "a partial generation shipped" + write(tmp_path / "transcript" / "subagents" / "agent-x.jsonl", + [asst("x-a2b", ts(1, 9), "msg_x2", [{"type": "text", "text": "x done"}], 336, "end_turn")], mode="a") + fire(hook_module, fake_langfuse, transcript) + assert len(spans_of(fake_langfuse, "Agent x")) == 1 + assert generation_outputs(fake_langfuse).count(336) == 1 + assert 4 not in generation_outputs(fake_langfuse) + assert_no_id_twice(fake_langfuse) + + +UNRESOLVED = [ + user("x-u", ts(0, 5), "go"), + asst("x-a1", ts(1), "msg_x1", [agent_launch("toolu_y", "Agent y")], 3, "tool_use"), + launched("x-r1", ts(1, 1), "toolu_y", "y"), + # Written after the launch whose result never arrives: mutable. + asst("x-a2", ts(1, 2), "msg_x2", [{"type": "text", "text": "waiting"}], 11, "end_turn"), +] + + +def test_running_agent_ships_only_what_cannot_change_then_sessionend_finalizes(hook_module, fake_langfuse, tmp_path): + transcript = setup_session(tmp_path, UNRESOLVED) + fire(hook_module, fake_langfuse, transcript) + assert spans_of(fake_langfuse, "Agent x") == [] + assert 11 not in generation_outputs(fake_langfuse), "a generation after an unresolved launch shipped" + assert 3 in generation_outputs(fake_langfuse), "the launch generation itself is final and ships" + fire(hook_module, fake_langfuse, transcript, end=True) + assert len(spans_of(fake_langfuse, "Agent x")) == 1, "SessionEnd did not finalize the unsettled agent" + assert generation_outputs(fake_langfuse).count(11) == 1 + assert_no_id_twice(fake_langfuse) + + +# ---------------------------------------------------- waiting main turns + +def workflow_turn_rows(stop_result: Any, stop_hours_later: int = 0) -> List[Dict[str, Any]]: + stop_row = user("m-r2", ts(6, 2, 10 + stop_hours_later), [{"type": "tool_result", "tool_use_id": "toolu_stop", + "content": json.dumps(stop_result)}]) + if isinstance(stop_result, dict): + stop_row["toolUseResult"] = stop_result + else: + stop_row["toolUseResult"] = stop_result + stop_row["message"]["content"][0]["is_error"] = True + return [ + user("m-u1", ts(0), "start a workflow"), + asst("m-a1", ts(0, 1), "msg_m1", [{"type": "tool_use", "id": "toolu_wf", "name": "Workflow", + "input": {"script": "round"}}], 2, "tool_use"), + user("m-r1", ts(0, 2), [{"type": "tool_result", "tool_use_id": "toolu_wf", "content": "Workflow launched."}], + toolUseResult={"status": "async_launched", "isAsync": True, "taskId": "wtask1", + "taskType": "local_workflow", "runId": "wf_none"}), + asst("m-a2", ts(0, 3), "msg_m2", [{"type": "text", "text": "running"}], 2, "end_turn"), + user("m-u2", ts(6, 0, 10 + stop_hours_later), "stop it"), + asst("m-a3", ts(6, 1, 10 + stop_hours_later), "msg_m3", + [{"type": "tool_use", "id": "toolu_stop", "name": "TaskStop", "input": {"task_id": "wtask1"}}], 2, "tool_use"), + stop_row, + asst("m-a4", ts(6, 3, 10 + stop_hours_later), "msg_m4", [{"type": "text", "text": "stopped"}], 2, "end_turn"), + user("m-u3", ts(7, 0, 10 + stop_hours_later), "thanks"), + ] + + +def roots_by_user_uuid(fake_langfuse: Any) -> List[str]: + return [o.kwargs["metadata"].get("user_row_uuid") or o.kwargs["input"]["content"] + for o in fake_langfuse.observations if o.name == "Conversational Turn"] + + +def test_taskstop_resolves_a_launch_that_will_never_notify(hook_module, fake_langfuse, tmp_path): + transcript = tmp_path / "transcript.jsonl" + write(transcript, workflow_turn_rows({"message": "Successfully stopped task: wtask1", "task_id": "wtask1", + "task_type": "local_workflow"})) + fire(hook_module, fake_langfuse, transcript) + assert "start a workflow" in roots_by_user_uuid(fake_langfuse) + + +def test_control_failed_taskstop_keeps_the_turn_waiting(hook_module, fake_langfuse, tmp_path): + transcript = tmp_path / "transcript.jsonl" + write(transcript, workflow_turn_rows("Error: Task wtask1 is not running (status: failed)")) + fire(hook_module, fake_langfuse, transcript) + assert "start a workflow" not in roots_by_user_uuid(fake_langfuse) + + +def test_a_turn_waiting_past_the_bound_ships(hook_module, fake_langfuse, tmp_path): + # The failed stop leaves the launch unresolved; 13 h later it ships anyway. + transcript = tmp_path / "transcript.jsonl" + write(transcript, workflow_turn_rows("Error: not running", stop_hours_later=13)) + fire(hook_module, fake_langfuse, transcript) + assert "start a workflow" in roots_by_user_uuid(fake_langfuse) + + +def _age(path: Path, seconds: float) -> None: + import os + import time + then = time.time() - seconds + os.utime(path, (then, then)) + + +def test_agent_idle_past_the_bound_settles_despite_a_launch_that_never_notifies(hook_module, fake_langfuse, tmp_path): + transcript = setup_session(tmp_path, UNRESOLVED) + _age(tmp_path / "transcript" / "subagents" / "agent-x.jsonl", hook_module.MAX_DEFER_SECONDS + 60) + fire(hook_module, fake_langfuse, transcript) + assert len(spans_of(fake_langfuse, "Agent x")) == 1 + assert generation_outputs(fake_langfuse).count(11) == 1 + + +def test_agent_killed_mid_message_settles_after_the_idle_bound(hook_module, fake_langfuse, tmp_path): + rows = [ + user("x-u", ts(0, 5), "go"), + asst("x-a1", ts(1), "msg_x1", [{"type": "thinking", "thinking": "hm", "signature": "s"}], 4, None), + ] + transcript = setup_session(tmp_path, rows) + _age(tmp_path / "transcript" / "subagents" / "agent-x.jsonl", hook_module.AGENT_IDLE_SETTLE_SECONDS + 60) + fire(hook_module, fake_langfuse, transcript) + assert len(spans_of(fake_langfuse, "Agent x")) == 1 + + +# ------------------------------------------------ revisits between Stops + +SETTLED_X = [ + user("x-u", ts(0, 5), "go"), + asst("x-a1", ts(1), "msg_x1", [{"type": "text", "text": "x done"}], 5, "end_turn"), +] + + +def test_woken_agents_final_message_ships_even_when_never_given_a_stop_reason(hook_module, fake_langfuse, tmp_path): + transcript = setup_session(tmp_path, SETTLED_X) + fire(hook_module, fake_langfuse, transcript) + assert len(spans_of(fake_langfuse, "Agent x")) == 1 + # Woken by a notification; its new final message is written with + # stop_reason null and never completed. + write(tmp_path / "transcript" / "subagents" / "agent-x.jsonl", [ + user("x-n", ts(5), "[SYSTEM NOTIFICATION - NOT USER INPUT]\n" + notification_text("z", "toolu_z", "late"), + isMeta=True, origin={"kind": "task-notification"}), + asst("x-a2", ts(5, 10), "msg_x2", [{"type": "text", "text": "noted"}], 77, None), + ], mode="a") + fire(hook_module, fake_langfuse, transcript) + assert 77 not in generation_outputs(fake_langfuse), "held message shipped while it may still grow" + fire(hook_module, fake_langfuse, transcript) + fire(hook_module, fake_langfuse, transcript, end=True) + assert generation_outputs(fake_langfuse).count(77) == 1, "the woken agent's last message was lost" + assert len(spans_of(fake_langfuse, "Agent x")) == 1 + assert_no_id_twice(fake_langfuse) + + +def test_held_message_ships_after_the_idle_bound_without_sessionend(hook_module, fake_langfuse, tmp_path): + transcript = setup_session(tmp_path, SETTLED_X) + fire(hook_module, fake_langfuse, transcript) + path = tmp_path / "transcript" / "subagents" / "agent-x.jsonl" + write(path, [asst("x-a2", ts(5, 10), "msg_x2", [{"type": "text", "text": "noted"}], 77, None)], mode="a") + fire(hook_module, fake_langfuse, transcript) # first seen fresh: held + assert 77 not in generation_outputs(fake_langfuse) + _age(path, hook_module.AGENT_IDLE_SETTLE_SECONDS + 60) # then it ages, unchanged + fire(hook_module, fake_langfuse, transcript) + assert generation_outputs(fake_langfuse).count(77) == 1 + + +def test_unresolved_agent_seen_fresh_settles_once_it_ages(hook_module, fake_langfuse, tmp_path): + transcript = setup_session(tmp_path, UNRESOLVED) + fire(hook_module, fake_langfuse, transcript) + assert spans_of(fake_langfuse, "Agent x") == [] + fire(hook_module, fake_langfuse, transcript) + assert spans_of(fake_langfuse, "Agent x") == [] + _age(tmp_path / "transcript" / "subagents" / "agent-x.jsonl", hook_module.MAX_DEFER_SECONDS + 60) + fire(hook_module, fake_langfuse, transcript) + assert len(spans_of(fake_langfuse, "Agent x")) == 1 + + +def test_background_shell_keeps_the_agent_awake_until_it_notifies(hook_module, fake_langfuse, tmp_path): + rows = [ + user("x-u", ts(0, 5), "go"), + asst("x-a1", ts(1), "msg_x1", [{"type": "tool_use", "id": "toolu_sh", "name": "Bash", + "input": {"command": "sleep 600", "run_in_background": True}}], 3, "tool_use"), + user("x-r1", ts(1, 1), [{"type": "tool_result", "tool_use_id": "toolu_sh", + "content": "Command running in background with ID: bsh1"}], + toolUseResult={"stdout": "", "stderr": "", "interrupted": False, "backgroundTaskId": "bsh1"}), + asst("x-a2", ts(1, 2), "msg_x2", [{"type": "text", "text": "waiting for the shell"}], 3, "end_turn"), + ] + transcript = setup_session(tmp_path, rows) + fire(hook_module, fake_langfuse, transcript) + assert spans_of(fake_langfuse, "Agent x") == [], "span shipped while the agent's shell still runs" + write(tmp_path / "transcript" / "subagents" / "agent-x.jsonl", [ + # The shell's notification names only its task id. + user("x-n", ts(9), "\nbsh1\ncompleted\n" + "shell done\n", origin={"kind": "task-notification"}), + asst("x-a3", ts(9, 5), "msg_x3", [{"type": "text", "text": "x done"}], 21, "end_turn"), + ], mode="a") + fire(hook_module, fake_langfuse, transcript) + [span] = spans_of(fake_langfuse, "Agent x") + assert span.output == {"role": "assistant", "content": "x done"} + + +# ------------------------------------------------------------- TaskStop + +def test_control_failed_taskstop_with_a_dict_result_resolves_nothing(hook_module): + row = user("r", ts(1), [{"type": "tool_result", "tool_use_id": "toolu_stop", "is_error": True, + "content": "not running"}], + toolUseResult={"task_id": "wtask1", "message": "not running"}) + assert hook_module.get_stopped_task_id(row) is None + + +def taskstop_row(task_id: str = "wtask1") -> Dict[str, Any]: + return user("m-stop", ts(6, 2), [{"type": "tool_result", "tool_use_id": "toolu_stop", + "content": f"Successfully stopped task: {task_id}"}], + toolUseResult={"message": f"Successfully stopped task: {task_id}", "task_id": task_id, + "task_type": "local_workflow"}) + + +def test_taskstop_expansion_is_idempotent(hook_module): + launch = user("m-r1", ts(0, 2), [{"type": "tool_result", "tool_use_id": "toolu_wf", "content": "launched"}], + toolUseResult={"status": "async_launched", "taskId": "wtask1"}) + once = hook_module.expand_task_stop_rows([launch, taskstop_row()], [launch, taskstop_row()]) + twice = hook_module.expand_task_stop_rows(once, once) + assert len(once) == 3 and len(twice) == 3 + + +def test_taskstop_falls_back_to_the_task_id_map(hook_module): + rows = [taskstop_row("agent7")] + expanded = hook_module.expand_task_stop_rows(rows, rows, {"agent7": "toolu_agent7"}) + assert len(expanded) == 2 + assert hook_module.get_tool_use_id_from_task_notification(expanded[1]) == "toolu_agent7" + assert len(hook_module.expand_task_stop_rows(rows, rows, {})) == 1 + + +def test_taskstop_in_a_later_firing_releases_the_deferred_turn(hook_module, fake_langfuse, tmp_path): + rows = workflow_turn_rows({"message": "Successfully stopped task: wtask1", "task_id": "wtask1", + "task_type": "local_workflow"}) + transcript = tmp_path / "transcript.jsonl" + stop_index = next(i for i, r in enumerate(rows) if r["uuid"] == "m-u2") + write(transcript, rows[:stop_index] + [user("m-human", ts(5), "how is it going?"), + asst("m-ah", ts(5, 1), "msg_mh", [{"type": "text", "text": "running"}], 1, "end_turn")]) + fire(hook_module, fake_langfuse, transcript) + assert "start a workflow" not in roots_by_user_uuid(fake_langfuse) # deferred, waiting + write(transcript, rows[stop_index:], mode="a") + fire(hook_module, fake_langfuse, transcript) + assert "start a workflow" in roots_by_user_uuid(fake_langfuse) + + +def test_agent_settles_when_it_stops_its_own_workflow(hook_module, fake_langfuse, tmp_path): + rows = [ + user("x-u", ts(0, 5), "go"), + asst("x-a1", ts(1), "msg_x1", [{"type": "tool_use", "id": "toolu_wf", "name": "Workflow", + "input": {"script": "r"}}], 3, "tool_use"), + user("x-r1", ts(1, 1), [{"type": "tool_result", "tool_use_id": "toolu_wf", "content": "launched"}], + toolUseResult={"status": "async_launched", "isAsync": True, "taskId": "wtask9", "runId": "wf_none"}), + asst("x-a2", ts(1, 2), "msg_x2", [{"type": "tool_use", "id": "toolu_stop", "name": "TaskStop", + "input": {"task_id": "wtask9"}}], 3, "tool_use"), + user("x-r2", ts(1, 3), [{"type": "tool_result", "tool_use_id": "toolu_stop", "content": "stopped"}], + toolUseResult={"message": "Successfully stopped task: wtask9", "task_id": "wtask9"}), + asst("x-a3", ts(1, 4), "msg_x3", [{"type": "text", "text": "x done"}], 8, "end_turn"), + ] + transcript = setup_session(tmp_path, rows) + fire(hook_module, fake_langfuse, transcript) + assert len(spans_of(fake_langfuse, "Agent x")) == 1 + + +def test_deferred_turn_queue_ages_out(hook_module, fake_langfuse, tmp_path): + rows = workflow_turn_rows("Error: not running") + transcript = tmp_path / "transcript.jsonl" + stop_index = next(i for i, r in enumerate(rows) if r["uuid"] == "m-u2") + write(transcript, rows[:stop_index] + [user("m-human", ts(5), "status?"), + asst("m-ah", ts(5, 1), "msg_mh", [{"type": "text", "text": "running"}], 1, "end_turn")]) + fire(hook_module, fake_langfuse, transcript) # turn 1 goes to the deferred queue + assert "start a workflow" not in roots_by_user_uuid(fake_langfuse) + write(transcript, [user("m-late", ts(0, 0, 23), "hours later"), + asst("m-al", ts(0, 1, 23), "msg_ml", [{"type": "text", "text": "ok"}], 1, "end_turn"), + user("m-late2", ts(1, 0, 23), "again")], mode="a") + fire(hook_module, fake_langfuse, transcript) + assert "start a workflow" in roots_by_user_uuid(fake_langfuse) diff --git a/tests/integration/test_backfill_guards.py b/tests/integration/test_backfill_guards.py new file mode 100644 index 0000000..121f8a4 --- /dev/null +++ b/tests/integration/test_backfill_guards.py @@ -0,0 +1,261 @@ +"""--backfill refuses what could delete or double-count the wrong traces.""" +from __future__ import annotations + +import json +import os +import time +from pathlib import Path +from types import SimpleNamespace +from typing import Any, List + +import pytest + +from conftest import FakeLangfuse + + +SESSION = "11111111-2222-3333-4444-555555555555" + + +def write_transcript(directory: Path, session_id: str = SESSION, *, age_minutes: float = 120) -> Path: + path = directory / f"{session_id}.jsonl" + rows = [ + {"type": "user", "uuid": "u1", "sessionId": session_id, "timestamp": "2026-08-01T10:00:00.000Z", + "message": {"role": "user", "content": "hi"}}, + {"type": "assistant", "uuid": "a1", "sessionId": session_id, "timestamp": "2026-08-01T10:00:01.000Z", + "message": {"id": "m1", "role": "assistant", "content": [{"type": "text", "text": "hello"}], + "stop_reason": "end_turn", "usage": {"input_tokens": 1, "output_tokens": 2}}}, + ] + path.write_text("".join(json.dumps(r) + "\n" for r in rows), encoding="utf-8") + then = time.time() - age_minutes * 60 + os.utime(path, (then, then)) + return path + + +class FakeTraceApi: + """Session trace list: preset traces plus whatever the client's flushes + landed (unless the server rejects uploads).""" + + def __init__(self, journal: List[str], traces: List[Any]) -> None: + self.journal = journal + self.traces = traces + self.landed: dict = {} + self.deleted: List[str] = [] + + def list(self, **kwargs: Any) -> Any: + self.journal.append("list") + landed = [SimpleNamespace(id=t, name="Claude Code Turn", observations=sorted(ids)) + for t, ids in self.landed.items() if t not in self.deleted] + return SimpleNamespace(data=list(self.traces) + landed, meta=SimpleNamespace(total_pages=1)) + + def delete_multiple(self, *, trace_ids: List[str]) -> None: + self.journal.append("delete") + self.deleted += list(trace_ids) + + +class RecordingClient(FakeLangfuse): + def __init__(self, traces: List[Any], *, reject_uploads: bool = False) -> None: + super().__init__() + self.journal: List[str] = [] + self.reject_uploads = reject_uploads + self.api = SimpleNamespace(trace=FakeTraceApi(self.journal, traces)) + + def flush(self) -> None: + # Like the SDK: a rejected batch is only logged, flush() never raises. + self.journal.append(f"flush:{len(self.observations)}") + if not self.reject_uploads: + for o in self.observations: + self.api.trace.landed.setdefault(o.trace_id, set()).add(o.id) + + def shutdown(self) -> None: + pass + + +def trace(trace_id: str, name: Any) -> Any: + return SimpleNamespace(id=trace_id, name=name) + + +@pytest.fixture +def client(hook_module, monkeypatch): + monkeypatch.setattr(hook_module, "BACKFILL_VERIFY_ATTEMPTS", 2) + monkeypatch.setattr(hook_module, "BACKFILL_VERIFY_INTERVAL_S", 0.0) + + def make(traces: List[Any], **kwargs: Any) -> RecordingClient: + instance = RecordingClient(traces, **kwargs) + config = hook_module.LangfuseConfig("pk", "sk", "https://example.test", None) + monkeypatch.setattr(hook_module, "get_langfuse_config", lambda: config) + monkeypatch.setattr(hook_module, "create_langfuse_client", lambda c: instance) + monkeypatch.setattr(hook_module, "TRACE_SEED_NAMESPACE", None) + return instance + return make + + +def test_mismatched_session_id_is_refused_and_nothing_is_touched(hook_module, client, tmp_path): + transcript = write_transcript(tmp_path) + c = client([trace("o1", hook_module.TRACE_NAME)]) + code = hook_module.run_backfill(["--backfill", str(transcript), "--session-id", "OTHER", + "--replace-session-traces"]) + assert code == 3 + assert c.api.trace.deleted == [] and c.journal == [] + + +def test_transcript_named_for_another_session_is_refused(hook_module, client, tmp_path): + # Rows belong to SESSION, but the file (so the live traces) is another's. + transcript = write_transcript(tmp_path) + renamed = tmp_path / "99999999-0000-0000-0000-000000000000.jsonl" + renamed.write_text(transcript.read_text(encoding="utf-8"), encoding="utf-8") + then = time.time() - 7200 + os.utime(renamed, (then, then)) + c = client([trace("o1", hook_module.TRACE_NAME)]) + assert hook_module.run_backfill(["--backfill", str(renamed), "--session-id", SESSION, + "--replace-session-traces"]) == 3 + assert c.api.trace.deleted == [] and c.observations == [] + + +def test_recently_modified_transcript_is_refused_without_force(hook_module, client, tmp_path): + transcript = write_transcript(tmp_path, age_minutes=1) + c = client([]) + assert hook_module.run_backfill(["--backfill", str(transcript)]) == 3 + assert c.observations == [] + assert hook_module.run_backfill(["--backfill", str(transcript), "--force"]) == 0 + assert c.observations + + +def test_upload_happens_before_delete_and_only_hook_traces_go(hook_module, client, tmp_path): + transcript = write_transcript(tmp_path) + c = client([trace("old-turn", hook_module.TRACE_NAME), trace("foreign", "Some other app")]) + assert hook_module.run_backfill(["--backfill", str(transcript), "--replace-session-traces"]) == 0 + assert c.api.trace.deleted == ["old-turn"] + first_delete = c.journal.index("delete") + flushes_before = [j for j in c.journal[:first_delete] if j.startswith("flush:")] + assert flushes_before and int(flushes_before[-1].split(":")[1]) > 0, c.journal + + +def test_the_backfills_own_traces_are_kept(hook_module, client, tmp_path): + transcript = write_transcript(tmp_path) + c = client([]) + keep = hook_module.get_backfill_trace_ids(c, SESSION, transcript) + # keep is computed under the default namespace the run will set. + hook_module.TRACE_SEED_NAMESPACE = hook_module.DEFAULT_BACKFILL_NAMESPACE + keep = hook_module.get_backfill_trace_ids(c, SESSION, transcript) + plan = hook_module.plan_trace_replacement( + [(t, hook_module.TRACE_NAME) for t in keep] + [("old", hook_module.TRACE_NAME)], keep) + assert plan["delete"] == ["old"] and sorted(plan["keep"]) == sorted(keep) + + +def test_second_run_in_the_same_namespace_is_refused(hook_module, client, tmp_path): + transcript = write_transcript(tmp_path) + c = client([]) + assert hook_module.run_backfill(["--backfill", str(transcript)]) == 0 + before = len(c.observations) + assert hook_module.run_backfill(["--backfill", str(transcript)]) == 3 + assert len(c.observations) == before + + +def test_dry_run_lists_the_delete_plan_and_deletes_nothing(hook_module, client, tmp_path, capsys): + transcript = write_transcript(tmp_path) + c = client([trace("old-turn", hook_module.TRACE_NAME), trace("foreign", None)]) + assert hook_module.run_backfill(["--backfill", str(transcript), "--dry-run", + "--replace-session-traces"]) == 0 + out = json.loads(capsys.readouterr().out) + assert out["would_delete"] == ["old-turn"] + assert out["replace_plan"] == {"delete": 1, "keep": 0, "foreign": 1} + assert c.api.trace.deleted == [] and c.observations == [] + + +def test_failed_upload_deletes_nothing_and_exits_non_zero(hook_module, client, tmp_path): + transcript = write_transcript(tmp_path) + c = client([trace("old-turn", hook_module.TRACE_NAME)], reject_uploads=True) + code = hook_module.run_backfill(["--backfill", str(transcript), "--replace-session-traces"]) + assert code == 4 + assert c.api.trace.deleted == [] + assert "delete" not in c.journal + + +def test_partly_landed_upload_deletes_nothing(hook_module, client, tmp_path, monkeypatch): + transcript = write_transcript(tmp_path) + c = client([trace("old-turn", hook_module.TRACE_NAME)]) + real_flush = c.flush + + def lossy_flush(): + real_flush() + for ids in c.api.trace.landed.values(): + if ids: + ids.pop() + + monkeypatch.setattr(c, "flush", lossy_flush) + assert hook_module.run_backfill(["--backfill", str(transcript), "--replace-session-traces"]) == 4 + assert c.api.trace.deleted == [] + + +def test_rows_of_another_session_are_refused(hook_module, client, tmp_path): + # The file is named SESSION but its rows carry another session id. + other = write_transcript(tmp_path, "99999999-0000-0000-0000-000000000000") + named = tmp_path / f"{SESSION}.jsonl" + named.write_text(other.read_text(encoding="utf-8"), encoding="utf-8") + then = time.time() - 7200 + os.utime(named, (then, then)) + c = client([trace("o1", hook_module.TRACE_NAME)]) + assert hook_module.run_backfill(["--backfill", str(named), "--replace-session-traces"]) == 3 + assert c.api.trace.deleted == [] and c.observations == [] + + +def test_a_recently_written_agent_transcript_counts_as_live(hook_module, client, tmp_path): + transcript = write_transcript(tmp_path) # main is two hours old + agent = tmp_path / SESSION / "subagents" / "agent-x.jsonl" + agent.parent.mkdir(parents=True) + agent.write_text("{}\n", encoding="utf-8") # written just now + c = client([]) + assert hook_module.run_backfill(["--backfill", str(transcript)]) == 3 + assert c.observations == [] + + +def test_read_back_retries_until_ingestion_catches_up(hook_module, client, tmp_path): + transcript = write_transcript(tmp_path) + c = client([trace("old-turn", hook_module.TRACE_NAME)]) + real_list = c.api.trace.list + calls = {"n": 0} + + def slow_list(**kwargs): + # The first read-back sees nothing yet; the second sees the upload. + if "observations" in str(kwargs.get("fields")): + calls["n"] += 1 + if calls["n"] == 1: + return SimpleNamespace(data=list(c.api.trace.traces), meta=SimpleNamespace(total_pages=1)) + return real_list(**kwargs) + + c.api.trace.list = slow_list + assert hook_module.run_backfill(["--backfill", str(transcript), "--replace-session-traces"]) == 0 + assert c.api.trace.deleted == ["old-turn"] + + +def test_verify_only_uploads_nothing_and_finishes_the_replacement(hook_module, client, tmp_path): + transcript = write_transcript(tmp_path) + c = client([trace("old-turn", hook_module.TRACE_NAME)]) + assert hook_module.run_backfill(["--backfill", str(transcript)]) == 0 + uploaded = len(c.observations) + code = hook_module.run_backfill(["--backfill", str(transcript), "--verify-only", "--replace-session-traces"]) + assert code == 0 + assert len(c.observations) == uploaded, "--verify-only uploaded again" + assert c.api.trace.deleted == ["old-turn"] + + +def test_verify_only_refuses_when_nothing_landed(hook_module, client, tmp_path): + transcript = write_transcript(tmp_path) + c = client([trace("old-turn", hook_module.TRACE_NAME)]) + assert hook_module.run_backfill(["--backfill", str(transcript), "--verify-only", + "--replace-session-traces"]) == 4 + assert c.observations == [] and c.api.trace.deleted == [] + + +def test_nothing_to_verify_never_counts_as_verified(hook_module, client, tmp_path): + # A transcript the emission turns into zero observations: an empty + # expectation must not "verify" and license the delete. + path = tmp_path / f"{SESSION}.jsonl" + path.write_text(json.dumps({"type": "user", "uuid": "u1", "sessionId": SESSION, + "timestamp": "2026-08-01T10:00:00.000Z", + "message": {"role": "user", "content": "hi"}}) + "\n", encoding="utf-8") + then = time.time() - 7200 + os.utime(path, (then, then)) + c = client([trace("old-turn", hook_module.TRACE_NAME)]) + assert hook_module.run_backfill(["--backfill", str(path), "--replace-session-traces"]) == 4 + assert c.api.trace.deleted == [] diff --git a/tests/integration/test_resumed_nested_agents.py b/tests/integration/test_resumed_nested_agents.py new file mode 100644 index 0000000..2354f81 --- /dev/null +++ b/tests/integration/test_resumed_nested_agents.py @@ -0,0 +1,429 @@ +"""Nested and resumed agents reach Langfuse whole, ONCE, with their usage. + +Fixture (synthetic rows in the Claude Code 2.1.301 shapes): + + main --bg--> orch --bg--> child1 --sync--> grand (depth 3) + \\--Workflow wf_t1 --> w1 --sync--> wchild + \\--bg--> child2 (phase 2 only) + +phase1 is the disk at the first Stop: orch has ended a turn while child1 +still runs, so main got an interim "completed" notification for orch. phase2 +is appended before the second Stop: orch received child1's notification +(as a queued_command attachment, the way a working agent receives it), +launched child2, got a message that opened a new turn, received child2's +notification in that later turn, and finished. Every transcript also +carries api-request / api-request-blob echo rows. + +Langfuse v4 reads do not merge two exports of one observation id, so every +assertion here counts RAW exports: an id exported twice is a defect. +""" +from __future__ import annotations + +import json +import shutil +from collections import Counter, defaultdict +from pathlib import Path +from typing import Any, Dict, List, Optional + +from conftest import FakeLangfuse, nests_under + + +FIXTURE = Path(__file__).resolve().parents[1] / "fixtures" / "transcripts" / "resumed_background_agent" +SESSION = "session-resume" +AGENTS = ["orch", "child1", "grand", "child2", "w1", "wchild"] + + +def apply_phase(phase: str, dst: Path, only: Optional[str] = None) -> None: + """Append every file of the phase to the same relative path under dst.""" + src_root = FIXTURE / phase + for src in sorted(p for p in src_root.rglob("*") if p.is_file()): + if only is not None and only not in src.name: + continue + target = dst / src.relative_to(src_root) + target.parent.mkdir(parents=True, exist_ok=True) + if src.name.endswith(".meta.json"): + shutil.copyfile(src, target) + continue + with target.open("a", encoding="utf-8") as f: + f.write(src.read_text(encoding="utf-8")) + + +def fire(hook_module: Any, fake_langfuse: Any, transcript: Path, *, end: bool = False) -> None: + config = hook_module.LangfuseConfig("public", "secret", "https://example.test", "user-1") + hook_module.emit_new_turns_from_transcript( + fake_langfuse, config, SESSION, transcript, flush_deferred_agent_turns=end, + ) + + +def run_session(hook_module: Any, fake_langfuse: Any, tmp_path: Path) -> Path: + apply_phase("phase1", tmp_path) + transcript = tmp_path / "transcript.jsonl" + fire(hook_module, fake_langfuse, transcript) + apply_phase("phase2", tmp_path) + fire(hook_module, fake_langfuse, transcript) + fire(hook_module, fake_langfuse, transcript, end=True) + return transcript + + +def by_id(observations: List[Any]) -> Dict[str, Any]: + return {o.id: o for o in observations} + + +def parent_id(observation: Any) -> Optional[str]: + parent = observation._otel_span.parent + if parent is None: + return None + return f"{parent.get_span_context().span_id:016x}" + + +def agent_name(observation: Any) -> Optional[str]: + if observation.as_type == "span" and observation.name.startswith(("Subagent", "Workflow agent")): + path = observation.kwargs.get("metadata", {}).get("transcript_path") or "" + return path[len("agent-"):-len(".jsonl")] + return None + + +def agent_spans(observations: List[Any]) -> Dict[str, List[Any]]: + spans: Dict[str, List[Any]] = defaultdict(list) + for observation in observations: + name = agent_name(observation) + if name: + spans[name].append(observation) + return spans + + +def agent_of(observation: Any, ids: Dict[str, Any], agent_span_ids: Dict[str, str]) -> str: + """Walk parent ids; an agent's children may be exported before its span.""" + current = parent_id(observation) + while current is not None: + if current in agent_span_ids: + return agent_span_ids[current] + parent = ids.get(current) + current = parent_id(parent) if parent is not None else None + return "main" + + +def generations_by_agent(hook_module: Any, observations: List[Any]) -> Dict[str, List[Any]]: + ids = by_id(observations) + # Agent span ids are deterministic: derive them so children exported + # before their agent span still resolve. + agent_span_ids = {o.id: agent_name(o) for o in observations if agent_name(o)} + out: Dict[str, List[Any]] = defaultdict(list) + for o in observations: + if o.as_type == "generation": + out[agent_of(o, ids, agent_span_ids)].append(o) + return out + + +def transcript_usage(tmp_path: Path, agent: str) -> Dict[str, Any]: + """Independent oracle: the agent's own transcript, echo rows skipped, + one entry per message.id, the LAST row's usage (the complete one).""" + path = next(tmp_path.rglob(f"agent-{agent}.jsonl")) + by_message: Dict[str, Dict[str, Any]] = {} + for line in path.read_text(encoding="utf-8").splitlines(): + row = json.loads(line) + if row.get("type") != "assistant": + continue + by_message[row["message"]["id"]] = row["message"]["usage"] + totals: Counter = Counter() + for u in by_message.values(): + totals["output"] += u["output_tokens"] + totals["cache_read_input_tokens"] += u["cache_read_input_tokens"] + return {"messages": len(by_message), "totals": totals} + + +def emitted_usage(generations: List[Any]) -> Dict[str, Any]: + totals: Counter = Counter() + zero = 0 + for g in generations: + usage = g.kwargs.get("usage_details") or {} + if not usage: + zero += 1 + totals["output"] += usage.get("output", 0) + totals["cache_read_input_tokens"] += usage.get("cache_read_input_tokens", 0) + return {"messages": len(generations), "totals": totals, "zero": zero} + + +def ts_ns(hook_module: Any, iso: str) -> int: + return hook_module.to_otel_nanoseconds(hook_module.parse_timestamp(iso)) + + +def FIRST_SIGHTING_NS(hook_module: Any) -> int: + # The launch ack (10:00:03) plus the 1 us display offset. + return ts_ns(hook_module, "2026-08-01T10:00:03.000Z") + 1000 + + +# ---------------------------------------------------------------- the fix + +def test_no_observation_is_ever_exported_twice(hook_module, fake_langfuse, tmp_path): + run_session(hook_module, fake_langfuse, tmp_path) + counts = Counter(o.id for o in fake_langfuse.observations) + assert [i for i, n in counts.items() if n > 1] == [] + + +def test_every_agent_at_every_depth_arrives_exactly_once(hook_module, fake_langfuse, tmp_path): + run_session(hook_module, fake_langfuse, tmp_path) + spans = agent_spans(fake_langfuse.observations) + for agent in AGENTS: + assert len(spans.get(agent, [])) == 1, f"{agent}: {spans.get(agent)}" + + +def test_each_agent_carries_every_message_once_with_its_final_usage(hook_module, fake_langfuse, tmp_path): + run_session(hook_module, fake_langfuse, tmp_path) + generations = generations_by_agent(hook_module, fake_langfuse.observations) + for agent in AGENTS: + expected = transcript_usage(tmp_path, agent) + got = emitted_usage(generations[agent]) + assert got["zero"] == 0, f"{agent}: zero-usage generations" + assert got["messages"] == expected["messages"], agent + assert got["totals"] == expected["totals"], agent + + +def test_resumed_agent_span_ships_once_after_it_settles(hook_module, fake_langfuse, tmp_path): + apply_phase("phase1", tmp_path) + transcript = tmp_path / "transcript.jsonl" + fire(hook_module, fake_langfuse, transcript) + # Interim: orch still waits on child1, so its span must not ship yet. + assert "orch" not in agent_spans(fake_langfuse.observations) + apply_phase("phase2", tmp_path) + fire(hook_module, fake_langfuse, transcript) + # Settled now (both children's notifications arrived, the last one in a + # later turn): the span ships at this Stop, not only at SessionEnd. + assert len(agent_spans(fake_langfuse.observations).get("orch", [])) == 1 + fire(hook_module, fake_langfuse, transcript, end=True) + [orch] = agent_spans(fake_langfuse.observations)["orch"] + assert orch.end_time == ts_ns(hook_module, "2026-08-01T10:39:00.000Z") + assert orch.output == {"role": "assistant", "content": "Batch done."} + # Start: where main first showed it (just after the launch ack), kept + # through the refresh that finalized it - not the agent's own first row. + assert orch._otel_span.start_time == FIRST_SIGHTING_NS(hook_module) + + +def test_children_exported_before_their_agent_span_point_at_it(hook_module, fake_langfuse, tmp_path): + run_session(hook_module, fake_langfuse, tmp_path) + spans = agent_spans(fake_langfuse.observations) + orch = spans["orch"][0] + child2 = spans["child2"][0] + assert nests_under(child2, orch) + assert child2.trace_id == orch.trace_id + # Every generation of orch points at orch's (deterministic) span id. + gens = generations_by_agent(hook_module, fake_langfuse.observations)["orch"] + assert gens and all(nests_under(g, orch) for g in gens) + + +def test_quiet_firing_exports_nothing(hook_module, fake_langfuse, tmp_path): + transcript = run_session(hook_module, fake_langfuse, tmp_path) + before = len(fake_langfuse.observations) + fire(hook_module, fake_langfuse, transcript) + fire(hook_module, fake_langfuse, transcript, end=True) + assert len(fake_langfuse.observations) == before + + +def test_growing_agent_across_many_firings_exports_each_observation_once(hook_module, fake_langfuse, tmp_path): + """orch's phase-2 rows arrive one per firing (main unchanged): every + firing may export only what is new and final; raw exports are counted.""" + apply_phase("phase1", tmp_path) + transcript = tmp_path / "transcript.jsonl" + fire(hook_module, fake_langfuse, transcript) + # Everything except orch's own phase-2 rows and main's phase-2 rows. + for src in sorted((FIXTURE / "phase2").rglob("*")): + if src.is_file() and "agent-orch" not in src.name and src.name != "transcript.jsonl": + target = tmp_path / src.relative_to(FIXTURE / "phase2") + target.parent.mkdir(parents=True, exist_ok=True) + if src.name.endswith(".meta.json"): + shutil.copyfile(src, target) + else: + with target.open("a", encoding="utf-8") as f: + f.write(src.read_text(encoding="utf-8")) + orch_path = tmp_path / "transcript" / "subagents" / "agent-orch.jsonl" + orch_rows = (FIXTURE / "phase2" / "transcript" / "subagents" / "agent-orch.jsonl").read_text(encoding="utf-8").splitlines() + exports_per_firing = [] + for row in orch_rows: + with orch_path.open("a", encoding="utf-8") as f: + f.write(row + "\n") + before = len(fake_langfuse.observations) + fire(hook_module, fake_langfuse, transcript) + exports_per_firing.append(len(fake_langfuse.observations) - before) + apply_phase("phase2", tmp_path, only="transcript.jsonl") + fire(hook_module, fake_langfuse, transcript, end=True) + + counts = Counter(o.id for o in fake_langfuse.observations) + assert [i for i, n in counts.items() if n > 1] == [] + generations = generations_by_agent(hook_module, fake_langfuse.observations) + assert emitted_usage(generations["orch"])["messages"] == transcript_usage(tmp_path, "orch")["messages"] + # A row that adds nothing final (an echo row) costs no export. + assert 0 in exports_per_firing + + +def test_registry_lives_in_its_own_session_file(hook_module, fake_langfuse, tmp_path, isolated_hook_state): + run_session(hook_module, fake_langfuse, tmp_path) + registries = list(isolated_hook_state.glob("langfuse_agents.*.json")) + assert len(registries) == 1 + entries = json.loads(registries[0].read_text(encoding="utf-8"))["agents"] + assert set(entries) == set(AGENTS) + assert all(e["span_exported"] for e in entries.values()) + state = json.loads((isolated_hook_state / "langfuse_state.json").read_text(encoding="utf-8")) + assert all("agents" not in v for v in state.values()) + + +def test_registry_keeps_the_first_parent(hook_module, fake_langfuse, tmp_path): + apply_phase("phase1", tmp_path) + agent_path = tmp_path / "transcript" / "subagents" / "agent-grand.jsonl" + registry = hook_module.AgentRegistry(None) + first = hook_module.carrier_span("11" * 16, "22" * 8) + second = hook_module.carrier_span("33" * 16, "44" * 8) + subagent = {"path": agent_path, "agent_id": "grand", "description": "Review grand"} + with hook_module.active_agent_registry(registry): + hook_module.emit_subagent_observations(fake_langfuse, first, subagent, None) + apply_phase("phase2", tmp_path, only="agent-grand") + hook_module.emit_subagent_observations(fake_langfuse, second, subagent, None) + assert (registry.entries["grand"]["trace_id"], registry.entries["grand"]["parent_span_id"]) == ("11" * 16, "22" * 8) + assert {o.trace_id for o in fake_langfuse.observations} == {"11" * 16} + + +# ------------------------------------------------------- negative controls +# Each one switches one part of the fix off and shows the fixture then +# reproduces the measured defect, so the assertions above can fail. + +def test_control_without_refresh_late_work_is_lost(hook_module, fake_langfuse, tmp_path, monkeypatch): + monkeypatch.setattr(hook_module, "refresh_grown_agents", lambda *a, **k: 0) + run_session(hook_module, fake_langfuse, tmp_path) + spans = agent_spans(fake_langfuse.observations) + assert "child2" not in spans, "an agent launched after the interim notification arrived anyway" + + +def test_control_without_echo_filter_zero_usage_generations_appear(hook_module, fake_langfuse, tmp_path, monkeypatch): + monkeypatch.setattr(hook_module, "is_request_echo_row", lambda row: False) + real_role = hook_module.get_user_or_assistant_role_from_row + + def old_role(row): + role = real_role(row) + if role is None and isinstance(row.get("message"), dict): + # The pre-fix fallback: any row with a nested message.role. + nested = row["message"].get("role") + return nested if nested in ("user", "assistant") else None + return role + + monkeypatch.setattr(hook_module, "get_user_or_assistant_role_from_row", old_role) + run_session(hook_module, fake_langfuse, tmp_path) + generations = generations_by_agent(hook_module, fake_langfuse.observations) + assert sum(emitted_usage(generations[a])["zero"] for a in AGENTS) > 0 + + +def test_control_without_attachment_notifications_the_agent_never_settles(hook_module, fake_langfuse, tmp_path, monkeypatch): + real_text = hook_module.get_task_notification_text + monkeypatch.setattr( + hook_module, "get_task_notification_text", + lambda row: "" if row.get("type") == "attachment" else real_text(row), + ) + apply_phase("phase1", tmp_path) + transcript = tmp_path / "transcript.jsonl" + fire(hook_module, fake_langfuse, transcript) + apply_phase("phase2", tmp_path) + fire(hook_module, fake_langfuse, transcript) + # Not settled: child1/child2 never resolve, so orch's later generations + # and its span wait for SessionEnd. + assert "orch" not in agent_spans(fake_langfuse.observations) + + +def test_control_without_deterministic_ids_late_work_is_lost(hook_module, fake_langfuse, tmp_path, monkeypatch): + # Without deterministic ids the agent ships one-shot (old behavior). + monkeypatch.setattr(hook_module, "DETERMINISTIC_IDS", False) + run_session(hook_module, fake_langfuse, tmp_path) + spans = agent_spans(fake_langfuse.observations) + assert "child2" not in spans + + +def test_control_without_map_passthrough_workflow_children_are_lost(hook_module, fake_langfuse, tmp_path, monkeypatch): + real = hook_module.emit_subagent_observations + + def without_maps(*args, **kwargs): + kwargs["workflow_agent_transcripts_by_run_id"] = None + if str(kwargs.get("span_name") or "").startswith("Workflow agent"): + kwargs["subagent_transcripts_by_tool_use_id"] = None + return real(*args, **kwargs) + + monkeypatch.setattr(hook_module, "emit_subagent_observations", without_maps) + run_session(hook_module, fake_langfuse, tmp_path) + spans = agent_spans(fake_langfuse.observations) + assert "w1" not in spans and "wchild" not in spans + + +def test_control_stored_start_ignored_moves_the_span_start(hook_module, fake_langfuse, tmp_path, monkeypatch): + real = hook_module.emit_subagent_observations + + def without_stored_start(langfuse, parent, subagent, start, *args, **kwargs): + registry = hook_module._ACTIVE_AGENT_REGISTRY.get() + if registry is not None and subagent.get("agent_id") in registry.entries: + registry.entries[subagent["agent_id"]]["start"] = None + return real(langfuse, parent, subagent, start, *args, **kwargs) + + monkeypatch.setattr(hook_module, "emit_subagent_observations", without_stored_start) + run_session(hook_module, fake_langfuse, tmp_path) + [orch] = agent_spans(fake_langfuse.observations)["orch"] + assert orch._otel_span.start_time != FIRST_SIGHTING_NS(hook_module) + + +# ------------------------------------------------------------ the backfill + +def test_backfill_is_idempotent_and_complete(hook_module, tmp_path, monkeypatch): + apply_phase("phase1", tmp_path) + apply_phase("phase2", tmp_path) + transcript = tmp_path / "transcript.jsonl" + monkeypatch.setattr(hook_module, "TRACE_SEED_NAMESPACE", "backfill-test") + config = hook_module.LangfuseConfig("public", "secret", "https://example.test", None) + + first, second = FakeLangfuse(), FakeLangfuse() + hook_module.backfill_session(first, config, SESSION, transcript) + hook_module.backfill_session(second, config, SESSION, transcript) + assert [o.id for o in first.observations] == [o.id for o in second.observations] + assert len({o.id for o in first.observations}) == len(first.observations) + generations = generations_by_agent(hook_module, first.observations) + for agent in AGENTS: + assert len(agent_spans(first.observations).get(agent, [])) == 1, agent + assert emitted_usage(generations[agent])["messages"] == transcript_usage(tmp_path, agent)["messages"], agent + + +def test_backfill_traces_never_share_ids_with_live_traces(hook_module, fake_langfuse, tmp_path, monkeypatch): + transcript = run_session(hook_module, fake_langfuse, tmp_path) + live_traces = {o.trace_id for o in fake_langfuse.observations} + monkeypatch.setattr(hook_module, "TRACE_SEED_NAMESPACE", "backfill-test") + backfill = FakeLangfuse() + config = hook_module.LangfuseConfig("public", "secret", "https://example.test", None) + hook_module.backfill_session(backfill, config, SESSION, transcript) + assert live_traces.isdisjoint({o.trace_id for o in backfill.observations}) + keep = hook_module.get_backfill_trace_ids(backfill, SESSION, transcript) + assert {o.trace_id for o in backfill.observations} <= keep + + +def test_sync_agent_ending_on_a_tool_call_ships_when_its_result_arrives(hook_module, fake_langfuse, tmp_path): + """The parent's sync tool_result proves the agent is done even though + its own transcript ends on a tool call (so it never looks settled).""" + session = "session-sync" + sub = tmp_path / "transcript" / "subagents" + sub.mkdir(parents=True) + (sub / "agent-s1.meta.json").write_text(json.dumps({"description": "Sync s1", "toolUseId": "toolu_s1"})) + rows_s1 = [ + {"type": "user", "uuid": "s-u1", "timestamp": "2026-08-01T11:00:01.000Z", "message": {"role": "user", "content": "go"}}, + {"type": "assistant", "uuid": "s-a1", "timestamp": "2026-08-01T11:00:02.000Z", + "message": {"id": "msg_s1", "role": "assistant", "stop_reason": "tool_use", "usage": {"output_tokens": 3}, + "content": [{"type": "tool_use", "id": "toolu_so", "name": "StructuredOutput", "input": {}}]}}, + ] + (sub / "agent-s1.jsonl").write_text("".join(json.dumps(r) + "\n" for r in rows_s1)) + main = [ + {"type": "user", "uuid": "m-u1", "timestamp": "2026-08-01T11:00:00.000Z", "message": {"role": "user", "content": "run"}}, + {"type": "assistant", "uuid": "m-a1", "timestamp": "2026-08-01T11:00:00.500Z", + "message": {"id": "msg_m1", "role": "assistant", "usage": {"output_tokens": 1}, + "content": [{"type": "tool_use", "id": "toolu_s1", "name": "Agent", "input": {"description": "Sync s1"}}]}}, + {"type": "user", "uuid": "m-r1", "timestamp": "2026-08-01T11:00:03.000Z", "toolUseResult": {"status": "completed"}, + "message": {"role": "user", "content": [{"type": "tool_result", "tool_use_id": "toolu_s1", "content": "ok"}]}}, + {"type": "assistant", "uuid": "m-a2", "timestamp": "2026-08-01T11:00:04.000Z", + "message": {"id": "msg_m2", "role": "assistant", "stop_reason": "end_turn", "usage": {"output_tokens": 1}, + "content": [{"type": "text", "text": "done"}]}}, + {"type": "user", "uuid": "m-u2", "timestamp": "2026-08-01T11:01:00.000Z", "message": {"role": "user", "content": "next"}}, + ] + transcript = tmp_path / "transcript.jsonl" + transcript.write_text("".join(json.dumps(r) + "\n" for r in main)) + config = hook_module.LangfuseConfig("public", "secret", "https://example.test", None) + hook_module.emit_new_turns_from_transcript(fake_langfuse, config, session, transcript) + assert len(agent_spans(fake_langfuse.observations).get("s1", [])) == 1 diff --git a/tests/integration/test_state_lock_contention.py b/tests/integration/test_state_lock_contention.py index 899105b..b108bc7 100644 --- a/tests/integration/test_state_lock_contention.py +++ b/tests/integration/test_state_lock_contention.py @@ -111,7 +111,9 @@ def test_entry_of_another_session_survives_the_emit( def other_session_saves() -> None: with hook_module.FileLock(hook_module.LOCK_FILE): state = hook_module.load_hook_state() - state["other-session-key"] = {"offset": 42, "updated": "2026-09-10T00:00:00+00:00"} + # A fresh timestamp: a fixed date ages past the 30-day sweep and the + # test then fails for a reason unrelated to the lock. + state["other-session-key"] = {"offset": 42, "updated": datetime.now(timezone.utc).isoformat()} hook_module.save_hook_state(state) _during_emit(hook_module, monkeypatch, other_session_saves) diff --git a/tests/integration/test_workflow_subagent_emission.py b/tests/integration/test_workflow_subagent_emission.py index 9a78e7e..d5297ef 100644 --- a/tests/integration/test_workflow_subagent_emission.py +++ b/tests/integration/test_workflow_subagent_emission.py @@ -5,6 +5,8 @@ from pathlib import Path from typing import Any +from conftest import nests_under + def copy_workflow_fixture(fixture_transcript_path: Any, tmp_path: Path) -> tuple[Path, list[dict[str, Any]]]: """Copy the workflow fixture's transcript directory (agent transcripts, @@ -123,7 +125,7 @@ def roots(): # carry the journal's per-agent result in their metadata. agent_spans = [o for o in fake_langfuse.observations if o.name.startswith("Workflow agent: ")] assert len(agent_spans) == 2 - assert all(o._otel_span.parent is tool_span._otel_span for o in agent_spans) + assert all(nests_under(o, tool_span) for o in agent_spans) r1_span = next(o for o in agent_spans if o.name.endswith("/r1")) assert r1_span.kwargs["metadata"]["workflow_agent_id"] == "r1" assert json.loads(r1_span.kwargs["metadata"]["workflow_agent_result"]) == { @@ -140,10 +142,9 @@ def roots(): # Generations nest under their agent spans and share the plain "LLM Call" # name (context lives on the parent); token math: TOTAL_AGENT_OUTPUT_TOKENS. - agent_otel_spans = {o._otel_span for o in agent_spans} agent_generations = [ o for o in fake_langfuse.observations - if o.as_type == "generation" and o._otel_span.parent in agent_otel_spans + if o.as_type == "generation" and any(nests_under(o, a) for a in agent_spans) ] assert len(agent_generations) == 4 assert all(o.name == "LLM Call" for o in agent_generations) @@ -193,7 +194,7 @@ def test_session_end_flush_emits_never_completed_workflow_turn_with_agents( assert "Workflow agent: verify-claims/r2" in names tool_span = next(o for o in fake_langfuse.observations if o.name == "Tool: Workflow") agent_spans = [o for o in fake_langfuse.observations if o.name.startswith("Workflow agent: ")] - assert all(o._otel_span.parent is tool_span._otel_span for o in agent_spans) + assert all(nests_under(o, tool_span) for o in agent_spans) # The agents' end timestamps must propagate through workflow_end_timestamp # to both the tool span and the root: every parent-turn row predates the @@ -232,7 +233,7 @@ def test_structured_output_ending_agent_falls_back_to_journal_result_output( o for o in fake_langfuse.observations if o.name == "Tool: StructuredOutput" ] assert len(structured_output_spans) == 2 - assert all(o._otel_span.parent is r2_span._otel_span for o in structured_output_spans) + assert all(nests_under(o, r2_span) for o in structured_output_spans) # D1: r2's final message is tool_use-only, so its text extracts empty; the # span output falls back to the agent's journal result as a JSON string. @@ -248,10 +249,9 @@ def test_structured_output_ending_agent_falls_back_to_journal_result_output( # Generation split/merge arithmetic stays documented: r1 = 2 whole # messages, r2 = 2 merged messages (split rows share message.id). - agent_otel_spans = {o._otel_span for o in agent_spans} agent_generations = [ o for o in fake_langfuse.observations - if o.as_type == "generation" and o._otel_span.parent in agent_otel_spans + if o.as_type == "generation" and any(nests_under(o, a) for a in agent_spans) ] assert len(agent_generations) == 4 assert sum(g.kwargs["usage_details"]["output"] for g in agent_generations) == TOTAL_AGENT_OUTPUT_TOKENS @@ -467,7 +467,7 @@ def test_workflow_launch_without_workflow_name_falls_back_to_run_id_labels( assert tool_span.kwargs["metadata"]["workflow_run_id"] == "wf_test001" assert "workflow_name" not in tool_span.kwargs["metadata"] agent_spans = [o for o in fake_langfuse.observations if o.name.startswith("Workflow agent: ")] - assert all(o._otel_span.parent is tool_span._otel_span for o in agent_spans) + assert all(nests_under(o, tool_span) for o in agent_spans) assert all("workflow_name" not in o.kwargs["metadata"] for o in agent_spans) diff --git a/tests/unit/test_deterministic_span_ids.py b/tests/unit/test_deterministic_span_ids.py new file mode 100644 index 0000000..2f30080 --- /dev/null +++ b/tests/unit/test_deterministic_span_ids.py @@ -0,0 +1,91 @@ +from __future__ import annotations + +import json + + +def test_span_id_depends_on_trace_and_key_only(hook_module): + a = hook_module.derive_span_id("ab" * 16, "gen:msg_1") + assert a == hook_module.derive_span_id("ab" * 16, "gen:msg_1") + assert a != hook_module.derive_span_id("ab" * 16, "gen:msg_2") + assert a != hook_module.derive_span_id("cd" * 16, "gen:msg_1") + assert 0 < a < 2 ** 64 + + +def test_positional_keys_are_scoped(hook_module): + with hook_module.id_scope("agent1:0"): + first = hook_module.derive_span_id("ab" * 16, "gen:noid:0") + with hook_module.id_scope("agent1:1"): + second = hook_module.derive_span_id("ab" * 16, "gen:noid:0") + assert first != second + # Natural ids ignore the scope, so a turn re-indexing cannot move them. + with hook_module.id_scope("agent1:0"): + natural = hook_module.derive_span_id("ab" * 16, "gen:msg_1") + assert natural == hook_module.derive_span_id("ab" * 16, "gen:msg_1") + + +def test_preset_id_is_one_shot(hook_module, fake_langfuse): + generator = hook_module.install_deterministic_span_ids(fake_langfuse) + assert generator is hook_module.install_deterministic_span_ids(fake_langfuse) + generator.next_span_id = 0xABC + assert generator.generate_span_id() == 0xABC + assert generator.generate_span_id() != 0xABC + + +def test_same_key_same_parent_same_observation_id(hook_module, fake_langfuse): + parent = hook_module.carrier_span("12" * 16, "34" * 8) + ids = [ + hook_module._start_backdated(fake_langfuse, name="x", as_type="span", start_time=None, + parent_otel_span=parent, id_key="agent:a1").id + for _ in range(2) + ] + assert ids[0] == ids[1] == f"{hook_module.derive_span_id('12' * 16, 'agent:a1'):016x}" + + +def test_control_without_a_key_ids_stay_random(hook_module, fake_langfuse): + parent = hook_module.carrier_span("12" * 16, "34" * 8) + ids = { + hook_module._start_backdated(fake_langfuse, name="x", as_type="span", start_time=None, + parent_otel_span=parent).id + for _ in range(2) + } + assert len(ids) == 2 + + +def test_corrupt_registry_starts_empty(hook_module, tmp_path): + path = tmp_path / "langfuse_agents.0123456789abcdef.json" + path.write_text("{not json", encoding="utf-8") + registry = hook_module.AgentRegistry.load(path) + assert registry.entries == {} + registry.entries["a"] = {"size": 1} + registry.save() + assert json.loads(path.read_text(encoding="utf-8")) == {"agents": {"a": {"size": 1}}} + + +def test_corrupt_registry_falls_back_to_the_previous_version(hook_module, tmp_path, caplog): + path = tmp_path / "langfuse_agents.0123456789abcdef.json" + registry = hook_module.AgentRegistry(path) + registry.entries = {"a": {"size": 1}} + registry.save() + registry.entries = {"a": {"size": 2}} + registry.save() # the first version is now the .bak + path.write_text("{torn", encoding="utf-8") + with caplog.at_level("INFO"): + loaded = hook_module.AgentRegistry.load(path) + assert loaded.entries == {"a": {"size": 1}} + assert any("WARNING agent registry unreadable" in r.getMessage() for r in caplog.records) + + +def test_stray_registry_tmp_is_swept(hook_module, isolated_hook_state): + import os + import time + from datetime import datetime, timezone + isolated_hook_state.mkdir(parents=True, exist_ok=True) + stray = isolated_hook_state / "langfuse_agents.0123456789abcdef.tmp" + stray.write_text("{}", encoding="utf-8") + old = time.time() - 2 * 24 * 3600 + os.utime(stray, (old, old)) + fresh = isolated_hook_state / "langfuse_agents.fedcba9876543210.tmp" + fresh.write_text("{}", encoding="utf-8") + hook_module.save_hook_state({"x": {"updated": datetime.now(timezone.utc).isoformat()}}) + assert not stray.exists() + assert fresh.exists() diff --git a/tests/unit/test_emission_gate.py b/tests/unit/test_emission_gate.py index b42fc99..1342eb0 100644 --- a/tests/unit/test_emission_gate.py +++ b/tests/unit/test_emission_gate.py @@ -28,3 +28,30 @@ def test_rows_without_notifications_pass_the_gate(hook_module): {"type": "queue-operation", "operation": "remove", "content": None}, ] assert hook_module.get_undelivered_queued_notification_ids(rows) == [] + + +def test_remove_with_content_clears_a_notification_routed_elsewhere(hook_module): + # A subagent's child notifies: enqueued on the main queue, removed at once + # (routed to that subagent), never delivered as a main user row. + rows = [ + {"type": "queue-operation", "operation": "enqueue", "content": NOTIFICATION}, + {"type": "queue-operation", "operation": "remove", "content": NOTIFICATION}, + ] + assert hook_module.get_undelivered_queued_notification_ids(rows) == [] + + +def test_remove_clears_one_enqueue_only(hook_module): + rows = [ + {"type": "queue-operation", "operation": "enqueue", "content": NOTIFICATION}, + {"type": "queue-operation", "operation": "enqueue", "content": NOTIFICATION}, + {"type": "queue-operation", "operation": "remove", "content": NOTIFICATION}, + ] + assert hook_module.get_undelivered_queued_notification_ids(rows) == ["toolu_X"] + + +def test_request_echo_of_a_notification_is_not_a_delivery(hook_module): + rows = [ + {"type": "queue-operation", "operation": "enqueue", "content": NOTIFICATION}, + {"type": "api-request-blob", "message": {"role": "user", "content": NOTIFICATION}}, + ] + assert hook_module.get_undelivered_queued_notification_ids(rows) == ["toolu_X"] diff --git a/tests/unit/test_request_echo_rows.py b/tests/unit/test_request_echo_rows.py new file mode 100644 index 0000000..36af2e4 --- /dev/null +++ b/tests/unit/test_request_echo_rows.py @@ -0,0 +1,93 @@ +"""Claude Code 2.1.301+ writes echo rows of every API request (api-request, +api-request-shape, api-request-blob). A blob carries message.role but no id, +usage or timestamp; it must never be read as a chat row.""" +from __future__ import annotations + +from typing import Any + + +def blob(role: str, content: Any) -> dict: + return {"type": "api-request-blob", "sessionId": "s", "hash": "0" * 64, + "message": {"role": role, "content": content}} + + +def test_blob_is_not_a_chat_row(hook_module): + for role in ("user", "assistant", "system"): + assert hook_module.get_user_or_assistant_role_from_row(blob(role, "x")) is None + + +def test_untyped_rows_keep_the_message_role_fallback(hook_module): + assert hook_module.get_user_or_assistant_role_from_row({"message": {"role": "assistant"}}) == "assistant" + + +def test_echo_rows_are_recognised(hook_module): + for row_type in ("api-request", "api-request-blob", "api-request-shape"): + assert hook_module.is_request_echo_row({"type": row_type}) + assert not hook_module.is_request_echo_row({"type": "assistant"}) + assert not hook_module.is_request_echo_row({"message": {"role": "user"}}) + + +def test_blob_echoing_a_notification_is_not_a_notification(hook_module): + text = "a1r" + assert not hook_module.is_task_notification_row(blob("user", text)) + assert hook_module.is_task_notification_row({"type": "user", "message": {"role": "user", "content": text}}) + + +def test_blobs_neither_split_turns_nor_add_generations(hook_module): + rows = [ + {"type": "user", "uuid": "u1", "timestamp": "2026-08-01T10:00:00.000Z", + "message": {"role": "user", "content": "go"}}, + {"type": "assistant", "uuid": "a1", "timestamp": "2026-08-01T10:00:01.000Z", + "message": {"id": "m1", "role": "assistant", "content": [{"type": "text", "text": "one"}], + "usage": {"input_tokens": 1, "output_tokens": 2}}}, + blob("user", "go"), + blob("assistant", [{"type": "text", "text": "one"}]), + {"type": "assistant", "uuid": "a2", "timestamp": "2026-08-01T10:00:02.000Z", + "message": {"id": "m2", "role": "assistant", "content": [{"type": "text", "text": "two"}], + "usage": {"input_tokens": 1, "output_tokens": 3}}}, + ] + turns = hook_module.build_turns(rows) + assert len(turns) == 1 + assert [hook_module.get_message_id(m) for m in turns[0].assistant_msgs] == ["m1", "m2"] + assert all(hook_module.get_usage_details_from_row(m) for m in turns[0].assistant_msgs) + + +def test_control_with_the_old_role_fallback_blobs_split_the_turn(hook_module): + # What the unfixed reader did: a nested message.role made any row a chat row. + rows = [ + {"type": "user", "uuid": "u1", "message": {"role": "user", "content": "go"}}, + {"type": "assistant", "message": {"id": "m1", "role": "assistant", "content": "one"}}, + {"message": {"role": "user", "content": "go"}}, + {"message": {"role": "assistant", "content": "one"}}, + ] + turns = hook_module.build_turns(rows) + assert len(turns) == 2 + assert hook_module.get_message_id(turns[1].assistant_msgs[0]) is None + + +def test_raw_unicode_line_separator_in_a_string_keeps_the_row(hook_module, tmp_path): + # JSON permits U+2028 / U+0085 unescaped inside strings; str.splitlines() + # splits on them and the row with the final usage was dropped. + import json as _json + rows = [ + {"type": "assistant", "message": {"id": "m1", "role": "assistant", + "content": [{"type": "text", "text": "a
b\x85c"}], + "usage": {"output_tokens": 7}}}, + ] + path = tmp_path / "agent.jsonl" + path.write_text("\n".join(_json.dumps(r, ensure_ascii=False) for r in rows) + "\n", encoding="utf-8") + assert "
" in path.read_text(encoding="utf-8") + read = hook_module.read_subagent_jsonl(path) + assert [r["message"]["usage"]["output_tokens"] for r in read] == [7] + + +def test_control_splitlines_drops_that_row(tmp_path): + import json as _json + text = _json.dumps({"t": "a
b"}, ensure_ascii=False) + parsed = [] + for line in text.splitlines(): + try: + parsed.append(_json.loads(line)) + except ValueError: + pass + assert parsed == []