From bb9a1b1997e7ca1884dc236b0d5cb94cc11ba524 Mon Sep 17 00:00:00 2001 From: Miguel Pereira Date: Sat, 17 Oct 2026 12:26:37 +0100 Subject: [PATCH 1/5] Stop the lock-contention test from failing once its fixed date ages out The other session's entry carried a hard-coded 2026-09-10 timestamp, which the 30-day sweep in save_hook_state now deletes, so the test failed for a reason unrelated to the lock. Use the current time. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01Ga4FKjMftJRxoPaQaiPLHy --- tests/integration/test_state_lock_contention.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) 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) From 7aee27ea6ea868cc0fe313f8009ef0d97b8f5b69 Mon Sep 17 00:00:00 2001 From: Miguel Pereira Date: Sat, 17 Oct 2026 12:26:37 +0100 Subject: [PATCH 2/5] Trace nested and resumed agents whole, once, with their real usage Three gaps measured on a long multi-agent session against live Langfuse: - A background agent that ends a turn while its own background work runs notifies "completed" with an interim result, then resumes and keeps writing. The hook emitted each agent once, at that first notification, so everything it did and launched afterwards (at any depth) was lost. An agent registry (per-session file beside the state file) now records each emitted agent's parent span and exported keys; every firing re-emits agents whose transcript grew, under the same parent. - Observation ids are now derived from the trace id plus a stable key (message id, tool_use id, agent id), so a re-emitted agent span or an incomplete observation replaces its earlier copy (ReplacingMergeTree on span id) instead of duplicating it. CC_LANGFUSE_DETERMINISTIC_IDS=false restores random ids. - Claude Code 2.1.301 writes api-request / api-request-blob echo rows. A blob carries message.role without id, usage or timestamp; the role fallback read it as a chat row, giving one zero-usage generation per echoed assistant message and phantom turns per echoed user message. Typed non-chat rows no longer fall back to message.role, and echo rows are dropped at read time. Also: JSONL is split on newline only (str.splitlines broke rows holding a raw U+2028/U+0085 and dropped them); workflow and subagent maps pass through workflow agents and subagents; a queue remove row carrying a notification clears it from the emission gate; and a --backfill mode re-uploads a finished session from its transcript into namespaced traces with deterministic ids (--dry-run, --replace-session-traces). Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01Ga4FKjMftJRxoPaQaiPLHy --- .claude-plugin/plugin.json | 8 +- README.md | 19 + hooks/langfuse_hook.py | 811 ++++++++++++++++-- tests/conftest.py | 58 +- .../phase1/transcript.jsonl | 11 + .../transcript/subagents/agent-child1.jsonl | 4 + .../subagents/agent-child1.meta.json | 1 + .../transcript/subagents/agent-grand.jsonl | 2 + .../subagents/agent-grand.meta.json | 1 + .../transcript/subagents/agent-orch.jsonl | 11 + .../transcript/subagents/agent-orch.meta.json | 1 + .../transcript/subagents/agent-wchild.jsonl | 2 + .../subagents/agent-wchild.meta.json | 1 + .../subagents/workflows/wf_t1/agent-w1.jsonl | 4 + .../workflows/wf_t1/agent-w1.meta.json | 1 + .../subagents/workflows/wf_t1/journal.jsonl | 1 + .../phase2/transcript.jsonl | 5 + .../transcript/subagents/agent-child1.jsonl | 2 + .../transcript/subagents/agent-child2.jsonl | 2 + .../subagents/agent-child2.meta.json | 1 + .../transcript/subagents/agent-grand.jsonl | 2 + .../transcript/subagents/agent-orch.jsonl | 8 + .../integration/test_resumed_nested_agents.py | 272 ++++++ tests/unit/test_deterministic_span_ids.py | 61 ++ tests/unit/test_emission_gate.py | 27 + tests/unit/test_request_echo_rows.py | 93 ++ 26 files changed, 1345 insertions(+), 64 deletions(-) create mode 100644 tests/fixtures/transcripts/resumed_background_agent/phase1/transcript.jsonl create mode 100644 tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-child1.jsonl create mode 100644 tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-child1.meta.json create mode 100644 tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-grand.jsonl create mode 100644 tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-grand.meta.json create mode 100644 tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-orch.jsonl create mode 100644 tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-orch.meta.json create mode 100644 tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-wchild.jsonl create mode 100644 tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/agent-wchild.meta.json create mode 100644 tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/workflows/wf_t1/agent-w1.jsonl create mode 100644 tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/workflows/wf_t1/agent-w1.meta.json create mode 100644 tests/fixtures/transcripts/resumed_background_agent/phase1/transcript/subagents/workflows/wf_t1/journal.jsonl create mode 100644 tests/fixtures/transcripts/resumed_background_agent/phase2/transcript.jsonl create mode 100644 tests/fixtures/transcripts/resumed_background_agent/phase2/transcript/subagents/agent-child1.jsonl create mode 100644 tests/fixtures/transcripts/resumed_background_agent/phase2/transcript/subagents/agent-child2.jsonl create mode 100644 tests/fixtures/transcripts/resumed_background_agent/phase2/transcript/subagents/agent-child2.meta.json create mode 100644 tests/fixtures/transcripts/resumed_background_agent/phase2/transcript/subagents/agent-grand.jsonl create mode 100644 tests/fixtures/transcripts/resumed_background_agent/phase2/transcript/subagents/agent-orch.jsonl create mode 100644 tests/integration/test_resumed_nested_agents.py create mode 100644 tests/unit/test_deterministic_span_ids.py create mode 100644 tests/unit/test_request_echo_rows.py diff --git a/.claude-plugin/plugin.json b/.claude-plugin/plugin.json index 50018ef..3d08587 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). A re-emitted observation, such as a background agent that resumed after an interim result, then replaces its earlier copy instead of duplicating it. Set to false for random ids.", + "default": true + }, "CC_LANGFUSE_STATE_DIR": { "type": "string", "title": "State directory", diff --git a/README.md b/README.md index 04e0b6a..5c75fa5 100644 --- a/README.md +++ b/README.md @@ -71,6 +71,25 @@ 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`) with deterministic +observation ids, so a second run replaces the first. Add +`--replace-session-traces` to delete the session's other traces, the ones a +live hook exported before, so the session is not counted twice. + ## Troubleshooting The hook explains nearly every failure in diff --git a/hooks/langfuse_hook.py b/hooks/langfuse_hook.py index b5da67c..58e9a88 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,11 @@ 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, so a re-emitted observation +# (a resumed agent, a backfill re-run, a replay after a crash) overwrites its +# earlier copy instead of adding a second one. +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 +630,19 @@ def sweep_stale_session_locks(state: Dict[str, Any], cutoff: datetime) -> None: lock.unlink() except OSError: pass + try: + registries = list(STATE_DIR.glob("langfuse_agents.*.json")) + except OSError: + return + for registry in registries: + stem = registry.name[len("langfuse_agents."):-len(".json")] + if len(stem) != 16 or stem in live: + continue + try: + if registry.stat().st_mtime < cutoff.timestamp(): + registry.unlink() + except OSError: + pass def save_hook_state(state: Dict[str, Any]) -> None: @@ -665,12 +684,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 +981,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 ----------------- @@ -980,6 +1019,9 @@ def _extract_xml_tag_value(text: str, tag: str) -> Optional[str]: return text[i + len(start):j] 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 @@ -1210,6 +1252,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 +1269,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) @@ -1681,7 +1734,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 +1806,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 +1995,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 +2116,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 +2143,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,12 +2552,18 @@ class EmissionCursor: emitted: set completed_only: bool = False newly_emitted: List[str] = field(default_factory=list) + # Agent transcripts: emit an incomplete observation now but do not record + # it, so the next firing emits it again in its final form. Its id is + # deterministic, so the second copy replaces the first. + reemit_incomplete: bool = False def should_emit(self, key: str, complete: bool = True) -> bool: if key in self.emitted: return False if self.completed_only and not complete: return False + if self.reemit_incomplete and not complete: + return True self.emitted.add(key) self.newly_emitted.append(key) return True @@ -2468,6 +2643,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 +2678,7 @@ 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, ) workflow_end_timestamp = None @@ -2523,6 +2700,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 +2897,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 +2905,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 +2958,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 +3021,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 +3095,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 +3140,86 @@ 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, ) 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]] = {} + + @classmethod + def load(cls, path: Optional[Path]) -> "AgentRegistry": + registry = cls(path) + if path is None: + return registry + try: + data = json.loads(path.read_text(encoding="utf-8")) + if isinstance(data, dict) and isinstance(data.get("agents"), dict): + registry.entries = { + k: v for k, v in data["agents"].items() if isinstance(k, str) and isinstance(v, dict) + } + except FileNotFoundError: + pass + except Exception as e: + info(f"agent registry unreadable, starting empty ({path}): {type(e).__name__}: {e}") + 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") + os.replace(tmp, self.path) + except Exception as e: + info(f"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_size(path: Path) -> Optional[int]: + try: + return path.stat().st_size + except OSError: + return None + + def emit_subagent_observations(langfuse: Langfuse, parent_otel_span: Any, subagent: Dict[str, Any], start_timestamp: Optional[datetime], @@ -2967,20 +3228,37 @@ 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, ) -> Optional[datetime]: 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 + size = _get_file_size(path) + if entry is not None and size is not None and entry.get("size") == size: + # Already exported as it is on disk now. + 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. + turns = build_turns(rows, get_task_id_to_tool_use_id(subagent_transcripts_by_tool_use_id)) if not turns: return start_timestamp first_turn = turns[0] - subagent_start_timestamp = start_timestamp or parse_timestamp(first_turn.user_msg) + # A re-emitted agent span keeps the start it was first exported 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] @@ -3009,44 +3287,140 @@ def emit_subagent_observations(langfuse: Langfuse, parent_otel_span: Any, 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)), ) + if registry is not None: + cursor = EmissionCursor( + emitted=set(k for k in (entry or {}).get("emitted", []) if isinstance(k, str)), + reemit_incomplete=True, + ) + else: + 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. 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, + 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, + 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_end_timestamp = _get_latest_timestamp(latest_end_timestamp, subagent_start_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_span.end(end_time=to_otel_nanoseconds(subagent_end_timestamp)) + + parent_ids = get_span_context_hex(parent_otel_span) if parent_otel_span is not None else None + if registry is not None and parent_ids is not None and size is not None: + previous = entry or {} + registry.entries[agent_id] = { + "path": str(path), + "trace_id": previous.get("trace_id") or parent_ids[0], + "parent_span_id": previous.get("parent_span_id") or parent_ids[1], + "size": size, + "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: + """Re-emit every registered agent whose transcript grew since it was last + exported, under the span it was first emitted under. New observations + ship once; incomplete ones and the agent span itself replace their + earlier copies (same deterministic ids). Agents launched late by these + agents are found by the walk and emitted at their first sight.""" + refreshed = 0 + 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 size is None or size == entry.get("size"): + 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 + 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) + 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"), + }, + parse_timestamp(entry.get("start")), + 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, + ) + refreshed += 1 + except Exception as e: + info(f"re-emitting 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"Re-emitted {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 +3438,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 +3515,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 +3556,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 +3603,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 +3623,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,44 +3874,42 @@ 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): if turns: turns_to_emit = get_turns_to_emit( turns, @@ -3561,10 +3949,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: + 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 +4031,267 @@ 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 delete_other_session_traces(langfuse: Any, session_id: str, keep: set) -> int: + """Delete every trace of the session whose id is not in keep: the copies + a live hook exported before (random observation ids, partial agents).""" + doomed: List[str] = [] + page = 1 + while True: + traces = langfuse.api.trace.list(session_id=session_id, page=page, limit=100, fields="core") + data = list(getattr(traces, "data", None) or []) + doomed += [t.id for t in data if getattr(t, "id", None) and t.id not in keep] + total_pages = getattr(getattr(traces, "meta", None), "total_pages", None) or page + if not data or page >= total_pages: + break + page += 1 + for i in range(0, len(doomed), 100): + langfuse.api.trace.delete_multiple(trace_ids=doomed[i:i + 100]) + return len(doomed) + + +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. + Observation ids are deterministic and trace ids come from the backfill + namespace, so running it again replaces its own output.""" + 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 past session from its transcript (idempotent).", + ) + parser.add_argument("--backfill", required=True, metavar="TRANSCRIPT", + help="the session's main transcript, .jsonl") + parser.add_argument("--session-id", default=None, + help="defaults to the transcript file name") + parser.add_argument("--namespace", default=DEFAULT_BACKFILL_NAMESPACE, + help="trace-id namespace of the re-uploaded traces") + parser.add_argument("--dry-run", action="store_true", + help="build every observation, send nothing, print a summary") + 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="delete the session's traces that are not the backfill's own") + args = parser.parse_args(argv) + + global TRACE_SEED_NAMESPACE + TRACE_SEED_NAMESPACE = args.namespace or DEFAULT_BACKFILL_NAMESPACE + 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 + + if args.dry_run: + config = LangfuseConfig(public_key="", secret_key="", host="", user_id=None) + recorder = RecordingLangfuse() + turns = backfill_session(recorder, 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")))}) + 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" + ) + return 0 + + config = get_langfuse_config() + if config is None: + log_missing_langfuse_config() + print("Langfuse keys missing (LANGFUSE_PUBLIC_KEY / LANGFUSE_SECRET_KEY)", file=sys.stderr) + return 2 + if 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 langfuse is None: + return 2 + try: + if args.replace_session_traces: + keep = get_backfill_trace_ids(langfuse, session_id, transcript_path) + deleted = delete_other_session_traces(langfuse, session_id, keep) + print(f"deleted {deleted} earlier trace(s) of session {session_id}") + turns = backfill_session(langfuse, config, session_id, transcript_path) + print(f"backfilled {turns} turn(s) of session {session_id} (namespace {TRACE_SEED_NAMESPACE})") + finally: + try: + langfuse.flush() + finally: + langfuse.shutdown() + return 0 + + # ----------------- Main ----------------- def main() -> int: start = time.time() @@ -3645,4 +4344,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..aea462e 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -145,8 +145,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 +179,33 @@ 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 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 +216,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..f1c25a2 --- /dev/null +++ b/tests/fixtures/transcripts/resumed_background_agent/phase2/transcript/subagents/agent-orch.jsonl @@ -0,0 +1,8 @@ +{"type": "user", "timestamp": "2026-08-01T10:20:00.000Z", "sessionId": "session-resume", "uuid": "u-orch-2", "version": "2.1.301", "message": {"role": "user", "content": "\nchild1\ncompleted\nAgent finished\nchild1 done\n"}, "origin": {"kind": "task-notification"}, "promptSource": "system"} +{"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:35:00.000Z", "sessionId": "session-resume", "uuid": "u-orch-3", "version": "2.1.301", "message": {"role": "user", "content": "\nchild2\ncompleted\nAgent finished\nchild2 done\n"}, "origin": {"kind": "task-notification"}, "promptSource": "system"} +{"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_resumed_nested_agents.py b/tests/integration/test_resumed_nested_agents.py new file mode 100644 index 0000000..951144f --- /dev/null +++ b/tests/integration/test_resumed_nested_agents.py @@ -0,0 +1,272 @@ +"""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 resumed on child1's notification, +launched child2 and finished. Every transcript also carries api-request / +api-request-blob echo rows. + +The "server view" dedupes observations by id with the last copy winning, +which is how Langfuse stores an observation exported twice. +""" +from __future__ import annotations + +import json +import shutil +from collections import Counter, defaultdict +from pathlib import Path +from typing import Any, Dict, List, Optional + + + +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) -> 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()): + 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 server_view(fake_langfuse: Any) -> Dict[str, Any]: + view: Dict[str, Any] = {} + for observation in fake_langfuse.observations: + view[observation.id] = observation + return view + + +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_of(observation: Any, view: Dict[str, Any]) -> str: + current: Optional[Any] = observation + while current is not None: + if current.as_type == "span" and current.name.startswith(("Subagent", "Workflow agent")): + path = current.kwargs.get("metadata", {}).get("transcript_path") or "" + return path[len("agent-"):-len(".jsonl")] + current = view.get(parent_id(current) or "") + return "main" + + +def agent_spans(view: Dict[str, Any]) -> Dict[str, List[str]]: + spans: Dict[str, List[str]] = defaultdict(list) + for observation in view.values(): + if observation.as_type == "span" and observation.name.startswith(("Subagent", "Workflow agent")): + path = observation.kwargs.get("metadata", {}).get("transcript_path") or "" + spans[path[len("agent-"):-len(".jsonl")]].append(observation.id) + return spans + + +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(view: Dict[str, Any], agent: str) -> Dict[str, Any]: + generations = [o for o in view.values() if o.as_type == "generation" and agent_of(o, view) == agent] + 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} + + +# ---------------------------------------------------------------- the fix + +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(server_view(fake_langfuse)) + 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) + view = server_view(fake_langfuse) + for agent in AGENTS: + expected = transcript_usage(tmp_path, agent) + got = emitted_usage(view, 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_is_replaced_not_duplicated(hook_module, fake_langfuse, tmp_path): + run_session(hook_module, fake_langfuse, tmp_path) + exported = [o for o in fake_langfuse.observations + if o.as_type == "span" and o.name == "Subagent: Batch orchestrator"] + # Exported at the first Stop (interim) and again once it grew ... + assert len(exported) >= 2 + # ... always under one id, the last copy reaching the agent's real end. + assert len({o.id for o in exported}) == 1 + final = server_view(fake_langfuse)[exported[0].id] + assert final.end_time == hook_module.to_otel_nanoseconds(hook_module.parse_timestamp("2026-08-01T10:39:00.000Z")) + assert final.output == {"role": "assistant", "content": "Batch done."} + + +def test_late_agent_nests_under_the_agent_that_launched_it(hook_module, fake_langfuse, tmp_path): + run_session(hook_module, fake_langfuse, tmp_path) + view = server_view(fake_langfuse) + spans = agent_spans(view) + child2 = view[spans["child2"][0]] + assert parent_id(child2) == spans["orch"][0] + assert child2.trace_id == view[spans["orch"][0]].trace_id + + +def test_quiet_firing_re_emits_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, end=True) + assert len(fake_langfuse.observations) == before + + +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) + 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()) + + +# ------------------------------------------------------- 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) + view = server_view(fake_langfuse) + spans = agent_spans(view) + assert "child2" not in spans, "an agent launched after the interim notification arrived anyway" + orch = emitted_usage(view, "orch") + assert orch["messages"] < transcript_usage(tmp_path, "orch")["messages"] + + +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) + view = server_view(fake_langfuse) + assert sum(emitted_usage(view, a)["zero"] for a in AGENTS) > 0 + + +def test_control_without_deterministic_ids_a_resumed_agent_duplicates(hook_module, fake_langfuse, tmp_path, monkeypatch): + monkeypatch.setattr(hook_module, "DETERMINISTIC_IDS", False) + run_session(hook_module, fake_langfuse, tmp_path) + spans = agent_spans(server_view(fake_langfuse)) + assert len(spans["orch"]) > 1 + + +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 kwargs.get("span_name", "") and str(kwargs.get("span_name")).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(server_view(fake_langfuse)) + assert "w1" not in spans and "wchild" not in spans + + +# ------------------------------------------------------------ the backfill + +def test_backfill_is_idempotent_and_complete(hook_module, tmp_path, monkeypatch): + from conftest import FakeLangfuse + + 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) + first_view, second_view = server_view(first), server_view(second) + assert set(first_view) == set(second_view), "a re-run must hit the same observation ids" + assert {o.trace_id for o in first_view.values()} == {o.trace_id for o in second_view.values()} + for agent in AGENTS: + assert len(agent_spans(first_view).get(agent, [])) == 1, agent + assert emitted_usage(first_view, 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): + from conftest import FakeLangfuse + + 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 diff --git a/tests/unit/test_deterministic_span_ids.py b/tests/unit/test_deterministic_span_ids.py new file mode 100644 index 0000000..6d5343c --- /dev/null +++ b/tests/unit/test_deterministic_span_ids.py @@ -0,0 +1,61 @@ +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}}} 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 == [] From cc4ef31ec78c5f3ca6bd643f8e19e030ecb1b606 Mon Sep 17 00:00:00 2001 From: Miguel Pereira Date: Sat, 17 Oct 2026 13:03:42 +0100 Subject: [PATCH 3/5] Export every agent observation once, in final form; guard the backfill Review found the previous commit relied on Langfuse merging two exports of one observation id. Langfuse v4 reads do not (events_core/events_full are read without FINAL or LIMIT BY; duplicates collapse only at background merge), so each re-send counted twice. - No re-send at all. While an agent runs, only observations that can no longer change ship; the agent span ships once, when the agent settles (no pending async launch, no unresolved tool call) or at SessionEnd. Children exported earlier point at its deterministic span id. A sync launch's tool_result and a workflow journal result also count as proof the agent is done. - Notifications a working agent receives arrive as attachment rows ({"type": "queued_command", "prompt": "..."}). They were not recognised, so every async launch inside a subagent stayed unresolved and its later generations were never final. - Backfill: refuses a --session-id that is not the transcript's own, a transcript modified in the last 30 min (unless --force), and a namespace that already holds traces of the session; uploads and flushes before it deletes; deletes only traces named "Claude Code Turn" outside its own set; --dry-run prints the delete plan. - Registry: keeps the previous version as .bak and loads it when the file is torn, logs a WARNING when late work may be lost, sweeps stray .tmp. - Tests count raw exports (no server-side dedupe assumed); every new guard has a test that a mutation of it fails. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01Ga4FKjMftJRxoPaQaiPLHy --- .claude-plugin/plugin.json | 2 +- README.md | 17 +- hooks/langfuse_hook.py | 397 ++++++++++++++---- tests/conftest.py | 11 + .../transcript/subagents/agent-orch.jsonl | 6 +- tests/integration/test_backfill_guards.py | 150 +++++++ .../integration/test_resumed_nested_agents.py | 299 +++++++++---- .../test_workflow_subagent_emission.py | 16 +- tests/unit/test_deterministic_span_ids.py | 30 ++ 9 files changed, 754 insertions(+), 174 deletions(-) create mode 100644 tests/integration/test_backfill_guards.py diff --git a/.claude-plugin/plugin.json b/.claude-plugin/plugin.json index 3d08587..6b52808 100644 --- a/.claude-plugin/plugin.json +++ b/.claude-plugin/plugin.json @@ -70,7 +70,7 @@ "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). A re-emitted observation, such as a background agent that resumed after an interim result, then replaces its earlier copy instead of duplicating it. Set to false for random 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": { diff --git a/README.md b/README.md index 5c75fa5..b658cfe 100644 --- a/README.md +++ b/README.md @@ -84,11 +84,18 @@ uv run --script hooks/langfuse_hook.py \ `--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`) with deterministic -observation ids, so a second run replaces the first. Add -`--replace-session-traces` to delete the session's other traces, the ones a -live hook exported before, so the session is not counted twice. +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. +- `--replace-session-traces` deletes, after the upload has been flushed, 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, and a transcript modified in + the last 30 minutes is refused unless `--force` is passed. ## Troubleshooting diff --git a/hooks/langfuse_hook.py b/hooks/langfuse_hook.py index 58e9a88..a87b46d 100644 --- a/hooks/langfuse_hook.py +++ b/hooks/langfuse_hook.py @@ -49,9 +49,11 @@ def _opt(name: str) -> str: # 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, so a re-emitted observation -# (a resumed agent, a backfill re-run, a replay after a crash) overwrites its -# earlier copy instead of adding a second one. +# 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: @@ -631,15 +633,21 @@ def sweep_stale_session_locks(state: Dict[str, Any], cutoff: datetime) -> None: except OSError: pass try: - registries = list(STATE_DIR.glob("langfuse_agents.*.json")) + 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."):-len(".json")] - if len(stem) != 16 or stem in live: - continue + stem = registry.name[len("langfuse_agents."):].rsplit(".", 1)[0] try: - if registry.stat().st_mtime < cutoff.timestamp(): + 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 @@ -1018,6 +1026,19 @@ 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. @@ -1026,16 +1047,16 @@ def is_task_notification_row(row: Dict[str, Any]) -> bool: 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 @@ -1056,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 @@ -2552,18 +2573,12 @@ class EmissionCursor: emitted: set completed_only: bool = False newly_emitted: List[str] = field(default_factory=list) - # Agent transcripts: emit an incomplete observation now but do not record - # it, so the next firing emits it again in its final form. Its id is - # deterministic, so the second copy replaces the first. - reemit_incomplete: bool = False def should_emit(self, key: str, complete: bool = True) -> bool: if key in self.emitted: return False if self.completed_only and not complete: return False - if self.reemit_incomplete and not complete: - return True self.emitted.add(key) self.newly_emitted.append(key) return True @@ -2679,6 +2694,11 @@ def emit_single_tool_observation( 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 @@ -3143,6 +3163,7 @@ def emit_workflow_agent_observations( # 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 @@ -3164,21 +3185,37 @@ 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: + if path is None or not path.exists(): return registry try: - data = json.loads(path.read_text(encoding="utf-8")) - if isinstance(data, dict) and isinstance(data.get("agents"), dict): - registry.entries = { - k: v for k, v in data["agents"].items() if isinstance(k, str) and isinstance(v, dict) - } - except FileNotFoundError: - pass + registry.entries = cls._read(path) + return registry except Exception as e: - info(f"agent registry unreadable, starting empty ({path}): {type(e).__name__}: {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: @@ -3188,9 +3225,11 @@ def save(self) -> None: 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"agent registry save failed ({self.path}): {type(e).__name__}: {e}") + info(f"WARNING agent registry save failed ({self.path}): {type(e).__name__}: {e}") def get_agent_registry_path(session_state_key: str) -> Path: @@ -3220,6 +3259,45 @@ def _get_file_size(path: Path) -> Optional[int]: 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) + + +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): + 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 + return True + + def emit_subagent_observations(langfuse: Langfuse, parent_otel_span: Any, subagent: Dict[str, Any], start_timestamp: Optional[datetime], @@ -3229,7 +3307,24 @@ def emit_subagent_observations(langfuse: Langfuse, parent_otel_span: Any, 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 @@ -3239,9 +3334,15 @@ def emit_subagent_observations(langfuse: Langfuse, parent_otel_span: Any, 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 entry.get("size") == size: - # Already exported as it is on disk now. + if ( + entry is not None + and size is not None + and entry.get("size") == size + and (entry.get("span_exported") or not force) + ): + # Nothing new on disk, and nothing left to finalize. return parse_timestamp(entry.get("end")) or start_timestamp rows = read_subagent_jsonl(path) @@ -3254,7 +3355,7 @@ def emit_subagent_observations(langfuse: Langfuse, parent_otel_span: Any, return start_timestamp first_turn = turns[0] - # A re-emitted agent span keeps the start it was first exported with. + # 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) @@ -3281,36 +3382,54 @@ 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)), ) - if registry is not None: + # 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) + settled = force or known_finished or agent_is_settled(turns) cursor = EmissionCursor( emitted=set(k for k in (entry or {}).get("emitted", []) if isinstance(k, str)), - reemit_incomplete=True, + completed_only=not settled, ) 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_index, turn in enumerate(turns): with id_scope(f"{agent_id}:{turn_index}"): latest_turn_timestamp = emit_turn_observations( langfuse, - subagent_span._otel_span, + children_parent, turn, previous_start_timestamp, generation_name=generation_name, @@ -3326,17 +3445,25 @@ def emit_subagent_observations(langfuse: Langfuse, parent_otel_span: Any, previous_start_timestamp = latest_turn_timestamp subagent_end_timestamp = _get_latest_timestamp(latest_end_timestamp, subagent_start_timestamp) - subagent_span.update(output={"role": "assistant", "content": subagent_output_text}) - subagent_span.end(end_time=to_otel_nanoseconds(subagent_end_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)) - parent_ids = get_span_context_hex(parent_otel_span) if parent_otel_span is not None else None - if registry is not None and parent_ids is not None and size is not None: - previous = entry or {} + if incremental: registry.entries[agent_id] = { "path": str(path), - "trace_id": previous.get("trace_id") or parent_ids[0], - "parent_span_id": previous.get("parent_span_id") or parent_ids[1], + "trace_id": parent_ids[0], + "parent_span_id": parent_ids[1], "size": size, + "span_exported": span_exported, "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), @@ -3361,26 +3488,31 @@ def refresh_grown_agents( subagent_transcripts_by_tool_use_id: Optional[Dict[str, Dict[str, Any]]] = None, workflow_agent_transcripts_by_run_id: Optional["WorkflowAgentTranscriptsByRunId"] = None, ) -> int: - """Re-emit every registered agent whose transcript grew since it was last - exported, under the span it was first emitted under. New observations - ship once; incomplete ones and the agent span itself replace their - earlier copies (same deterministic ids). Agents launched late by these - agents are found by the walk and emitted at their first sight.""" + """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 size is None or size == entry.get("size"): + if size is None: + continue + if size == entry.get("size") and (entry.get("span_exported") or not force): 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 @@ -3394,23 +3526,26 @@ def refresh_grown_agents( "agent_type": entry.get("agent_type"), "description": entry.get("description"), }, - parse_timestamp(entry.get("start")), + # 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"re-emitting grown agent {agent_id} failed: {type(e).__name__}: {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"Re-emitted {refreshed} grown agent transcript(s)") + 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: @@ -3909,7 +4044,7 @@ def emit_session_firing( ) emitted = 0 - with active_agent_registry(agent_registry): + with active_agent_registry(agent_registry), force_finalize(flush_deferred_agent_turns): if turns: turns_to_emit = get_turns_to_emit( turns, @@ -3958,7 +4093,7 @@ def emit_session_firing( else: attribute_propagation = contextlib.nullcontext() try: - with attribute_propagation: + with attribute_propagation, force_finalize(flush_deferred_agent_turns): refresh_grown_agents( langfuse, agent_registry, @@ -4186,22 +4321,76 @@ def get_backfill_trace_ids(langfuse: Any, session_id: str, transcript_path: Path return trace_ids -def delete_other_session_traces(langfuse: Any, session_id: str, keep: set) -> int: - """Delete every trace of the session whose id is not in keep: the copies - a live hook exported before (random observation ids, partial agents).""" - doomed: List[str] = [] +def list_session_traces(langfuse: Any, session_id: str) -> List[Tuple[str, Optional[str]]]: + """(id, name) of every trace Langfuse holds for the session (read-only).""" + traces_out: List[Tuple[str, Optional[str]]] = [] page = 1 while True: traces = langfuse.api.trace.list(session_id=session_id, page=page, limit=100, fields="core") data = list(getattr(traces, "data", None) or []) - doomed += [t.id for t in data if getattr(t, "id", None) and t.id not in keep] + for trace in data: + trace_id = getattr(trace, "id", None) + if trace_id: + 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 - for i in range(0, len(doomed), 100): - langfuse.api.trace.delete_multiple(trace_ids=doomed[i:i + 100]) - return len(doomed) + 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 trace_id, name in traces: + 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 + + +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: + idle_minutes = (time.time() - transcript_path.stat().st_mtime) / 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 (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( @@ -4212,8 +4401,10 @@ def backfill_session( ) -> 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. - Observation ids are deterministic and trace ids come from the backfill - namespace, so running it again replaces its own output.""" + 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( @@ -4226,20 +4417,23 @@ def run_backfill(argv: List[str]) -> int: import argparse parser = argparse.ArgumentParser( prog="langfuse_hook.py --backfill", - description="Re-upload one past session from its transcript (idempotent).", + 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="defaults to the transcript file name") + 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") + 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, send nothing, print a summary") + 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="delete the session's traces that are not the backfill's own") + help="after the upload, delete this hook's earlier turn traces of the session") + 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 @@ -4249,41 +4443,70 @@ def run_backfill(argv: List[str]) -> int: 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 = [trace_id for trace_id, _ in existing if trace_id in keep] + if already: + 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: - config = LangfuseConfig(public_key="", secret_key="", host="", user_id=None) + dry_config = config or LangfuseConfig(public_key="", secret_key="", host="", user_id=None) recorder = RecordingLangfuse() - turns = backfill_session(recorder, config, session_id, transcript_path) + 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 - config = get_langfuse_config() - if config is None: + if langfuse is None: log_missing_langfuse_config() print("Langfuse keys missing (LANGFUSE_PUBLIC_KEY / LANGFUSE_SECRET_KEY)", file=sys.stderr) return 2 - if 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 langfuse is None: - return 2 try: - if args.replace_session_traces: - keep = get_backfill_trace_ids(langfuse, session_id, transcript_path) - deleted = delete_other_session_traces(langfuse, session_id, keep) - print(f"deleted {deleted} earlier trace(s) of session {session_id}") + # Upload first: if it fails part-way, the old traces are still there. turns = backfill_session(langfuse, config, session_id, transcript_path) + langfuse.flush() print(f"backfilled {turns} turn(s) of session {session_id} (namespace {TRACE_SEED_NAMESPACE})") + 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() diff --git a/tests/conftest.py b/tests/conftest.py index aea462e..7a0d259 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -188,6 +188,17 @@ 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: """Mirrors the SDK tracer: the span id comes from self.id_generator, the trace id from the parent span (active span or context carrier).""" 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 index f1c25a2..e4ecdf6 100644 --- 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 @@ -1,8 +1,10 @@ -{"type": "user", "timestamp": "2026-08-01T10:20:00.000Z", "sessionId": "session-resume", "uuid": "u-orch-2", "version": "2.1.301", "message": {"role": "user", "content": "\nchild1\ncompleted\nAgent finished\nchild1 done\n"}, "origin": {"kind": "task-notification"}, "promptSource": "system"} +{"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:35:00.000Z", "sessionId": "session-resume", "uuid": "u-orch-3", "version": "2.1.301", "message": {"role": "user", "content": "\nchild2\ncompleted\nAgent finished\nchild2 done\n"}, "origin": {"kind": "task-notification"}, "promptSource": "system"} +{"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_backfill_guards.py b/tests/integration/test_backfill_guards.py new file mode 100644 index 0000000..e8366a8 --- /dev/null +++ b/tests/integration/test_backfill_guards.py @@ -0,0 +1,150 @@ +"""--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: + def __init__(self, journal: List[str], traces: List[Any]) -> None: + self.journal = journal + self.traces = traces + self.deleted: List[str] = [] + + def list(self, **kwargs: Any) -> Any: + self.journal.append("list") + return SimpleNamespace(data=list(self.traces), 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]) -> None: + super().__init__() + self.journal: List[str] = [] + self.api = SimpleNamespace(trace=FakeTraceApi(self.journal, traces)) + + def flush(self) -> None: + self.journal.append(f"flush:{len(self.observations)}") + + 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): + def make(traces: List[Any]) -> RecordingClient: + instance = RecordingClient(traces) + 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 + uploaded = {o.trace_id for o in c.observations} + c.api.trace.traces = [trace(t, hook_module.TRACE_NAME) for t in uploaded] + 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 == [] diff --git a/tests/integration/test_resumed_nested_agents.py b/tests/integration/test_resumed_nested_agents.py index 951144f..2354f81 100644 --- a/tests/integration/test_resumed_nested_agents.py +++ b/tests/integration/test_resumed_nested_agents.py @@ -1,4 +1,4 @@ -"""Nested and resumed agents reach Langfuse whole, once, with their usage. +"""Nested and resumed agents reach Langfuse whole, ONCE, with their usage. Fixture (synthetic rows in the Claude Code 2.1.301 shapes): @@ -8,12 +8,14 @@ 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 resumed on child1's notification, -launched child2 and finished. Every transcript also carries api-request / -api-request-blob echo rows. - -The "server view" dedupes observations by id with the last copy winning, -which is how Langfuse stores an observation exported twice. +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 @@ -23,6 +25,7 @@ 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" @@ -30,10 +33,12 @@ AGENTS = ["orch", "child1", "grand", "child2", "w1", "wchild"] -def apply_phase(phase: str, dst: Path) -> None: +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"): @@ -60,11 +65,8 @@ def run_session(hook_module: Any, fake_langfuse: Any, tmp_path: Path) -> Path: return transcript -def server_view(fake_langfuse: Any) -> Dict[str, Any]: - view: Dict[str, Any] = {} - for observation in fake_langfuse.observations: - view[observation.id] = observation - return view +def by_id(observations: List[Any]) -> Dict[str, Any]: + return {o.id: o for o in observations} def parent_id(observation: Any) -> Optional[str]: @@ -74,23 +76,43 @@ def parent_id(observation: Any) -> Optional[str]: return f"{parent.get_span_context().span_id:016x}" -def agent_of(observation: Any, view: Dict[str, Any]) -> str: - current: Optional[Any] = observation +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.as_type == "span" and current.name.startswith(("Subagent", "Workflow agent")): - path = current.kwargs.get("metadata", {}).get("transcript_path") or "" - return path[len("agent-"):-len(".jsonl")] - current = view.get(parent_id(current) or "") + 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 agent_spans(view: Dict[str, Any]) -> Dict[str, List[str]]: - spans: Dict[str, List[str]] = defaultdict(list) - for observation in view.values(): - if observation.as_type == "span" and observation.name.startswith(("Subagent", "Workflow agent")): - path = observation.kwargs.get("metadata", {}).get("transcript_path") or "" - spans[path[len("agent-"):-len(".jsonl")]].append(observation.id) - return spans +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]: @@ -110,8 +132,7 @@ def transcript_usage(tmp_path: Path, agent: str) -> Dict[str, Any]: return {"messages": len(by_message), "totals": totals} -def emitted_usage(view: Dict[str, Any], agent: str) -> Dict[str, Any]: - generations = [o for o in view.values() if o.as_type == "generation" and agent_of(o, view) == agent] +def emitted_usage(generations: List[Any]) -> Dict[str, Any]: totals: Counter = Counter() zero = 0 for g in generations: @@ -123,65 +144,143 @@ def emitted_usage(view: Dict[str, Any], agent: str) -> Dict[str, Any]: 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(server_view(fake_langfuse)) + 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) - view = server_view(fake_langfuse) + generations = generations_by_agent(hook_module, fake_langfuse.observations) for agent in AGENTS: expected = transcript_usage(tmp_path, agent) - got = emitted_usage(view, 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_is_replaced_not_duplicated(hook_module, fake_langfuse, tmp_path): - run_session(hook_module, fake_langfuse, tmp_path) - exported = [o for o in fake_langfuse.observations - if o.as_type == "span" and o.name == "Subagent: Batch orchestrator"] - # Exported at the first Stop (interim) and again once it grew ... - assert len(exported) >= 2 - # ... always under one id, the last copy reaching the agent's real end. - assert len({o.id for o in exported}) == 1 - final = server_view(fake_langfuse)[exported[0].id] - assert final.end_time == hook_module.to_otel_nanoseconds(hook_module.parse_timestamp("2026-08-01T10:39:00.000Z")) - assert final.output == {"role": "assistant", "content": "Batch done."} - - -def test_late_agent_nests_under_the_agent_that_launched_it(hook_module, fake_langfuse, tmp_path): +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) - view = server_view(fake_langfuse) - spans = agent_spans(view) - child2 = view[spans["child2"][0]] - assert parent_id(child2) == spans["orch"][0] - assert child2.trace_id == view[spans["orch"][0]].trace_id + 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_re_emits_nothing(hook_module, fake_langfuse, tmp_path): +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. @@ -189,11 +288,8 @@ def test_registry_lives_in_its_own_session_file(hook_module, fake_langfuse, tmp_ 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) - view = server_view(fake_langfuse) - spans = agent_spans(view) + spans = agent_spans(fake_langfuse.observations) assert "child2" not in spans, "an agent launched after the interim notification arrived anyway" - orch = emitted_usage(view, "orch") - assert orch["messages"] < transcript_usage(tmp_path, "orch")["messages"] def test_control_without_echo_filter_zero_usage_generations_appear(hook_module, fake_langfuse, tmp_path, monkeypatch): @@ -210,15 +306,32 @@ def old_role(row): monkeypatch.setattr(hook_module, "get_user_or_assistant_role_from_row", old_role) run_session(hook_module, fake_langfuse, tmp_path) - view = server_view(fake_langfuse) - assert sum(emitted_usage(view, a)["zero"] for a in AGENTS) > 0 + 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_deterministic_ids_a_resumed_agent_duplicates(hook_module, fake_langfuse, tmp_path, monkeypatch): +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(server_view(fake_langfuse)) - assert len(spans["orch"]) > 1 + 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): @@ -226,21 +339,34 @@ def test_control_without_map_passthrough_workflow_children_are_lost(hook_module, def without_maps(*args, **kwargs): kwargs["workflow_agent_transcripts_by_run_id"] = None - if kwargs.get("span_name", "") and str(kwargs.get("span_name")).startswith("Workflow agent"): + 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(server_view(fake_langfuse)) + 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): - from conftest import FakeLangfuse - apply_phase("phase1", tmp_path) apply_phase("phase2", tmp_path) transcript = tmp_path / "transcript.jsonl" @@ -250,17 +376,15 @@ def test_backfill_is_idempotent_and_complete(hook_module, tmp_path, monkeypatch) first, second = FakeLangfuse(), FakeLangfuse() hook_module.backfill_session(first, config, SESSION, transcript) hook_module.backfill_session(second, config, SESSION, transcript) - first_view, second_view = server_view(first), server_view(second) - assert set(first_view) == set(second_view), "a re-run must hit the same observation ids" - assert {o.trace_id for o in first_view.values()} == {o.trace_id for o in second_view.values()} + 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_view).get(agent, [])) == 1, agent - assert emitted_usage(first_view, agent)["messages"] == transcript_usage(tmp_path, agent)["messages"], agent + 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): - from conftest import FakeLangfuse - 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") @@ -270,3 +394,36 @@ def test_backfill_traces_never_share_ids_with_live_traces(hook_module, fake_lang 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_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 index 6d5343c..2f30080 100644 --- a/tests/unit/test_deterministic_span_ids.py +++ b/tests/unit/test_deterministic_span_ids.py @@ -59,3 +59,33 @@ def test_corrupt_registry_starts_empty(hook_module, tmp_path): 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() From d69808c7d3bdfc00ddd11a02ef7749ecd2ccc201 Mon Sep 17 00:00:00 2001 From: Miguel Pereira Date: Sat, 17 Oct 2026 13:40:06 +0100 Subject: [PATCH 4/5] Stop losing agent work: meta notifications, half-written messages, failed uploads Second review found the once-only export trades duplication for loss: - A subagent receives a notification as an isMeta user row ("[SYSTEM NOTIFICATION ...]", origin kind task-notification). The injected-context branch ran first and ate it, so those launches never resolved and the agent never settled before SessionEnd. Notifications are now matched before the isMeta check. - An agent's last message is written as several rows; the earlier ones carry partial usage and stop_reason null. It counted as finished, so a generation could ship with partial usage and the agent settle early. The last message of an agent is now held until its last row has a stop_reason (a later message also proves it complete). - A launch that never notifies held its turn (or agent) until SessionEnd: a successful TaskStop result now resolves the stopped task, a waiting main turn ships after CC_LANGFUSE_MAX_DEFER_HOURS (default 12), an agent idle that long settles, and one killed mid-message settles after 30 min idle. - Backfill: flush() never raises on a rejected batch, so the upload is now read back (trace list with observation ids, retried up to 10 min) and nothing is deleted unless every uploaded observation is visible; exit 4 otherwise. The live-session guard now takes the newest mtime under the session directory. - Tests for each, and a mutation harness: 26 guard mutations, all fail. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01Ga4FKjMftJRxoPaQaiPLHy --- README.md | 14 +- hooks/langfuse_hook.py | 267 +++++++++++++++++++-- tests/integration/test_agent_completion.py | 242 +++++++++++++++++++ tests/integration/test_backfill_guards.py | 71 +++++- 4 files changed, 567 insertions(+), 27 deletions(-) create mode 100644 tests/integration/test_agent_completion.py diff --git a/README.md b/README.md index b658cfe..c613d49 100644 --- a/README.md +++ b/README.md @@ -90,11 +90,15 @@ the hook are read from the environment. `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. -- `--replace-session-traces` deletes, after the upload has been flushed, 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, and a transcript modified in +- 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. +- `--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 diff --git a/hooks/langfuse_hook.py b/hooks/langfuse_hook.py index a87b46d..0c7a156 100644 --- a/hooks/langfuse_hook.py +++ b/hooks/langfuse_hook.py @@ -1153,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"]) @@ -1311,17 +1313,112 @@ 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 and shells, agentId for agents).""" + 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") + 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 @@ -1530,14 +1627,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): @@ -1689,6 +1790,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: @@ -2573,10 +2680,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) @@ -3275,6 +3387,31 @@ def force_finalize(enabled: bool) -> Any: _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 @@ -3295,6 +3432,18 @@ def agent_is_settled(turns: List[Turn]) -> bool: 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) for turn in turns): + return False return True @@ -3409,10 +3558,27 @@ def emit_subagent_observations(langfuse: Langfuse, parent_otel_span: Any, 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) - settled = force or known_finished or agent_is_settled(turns) + 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 @@ -4050,6 +4216,7 @@ def emit_session_firing( 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, @@ -4321,16 +4488,22 @@ def get_backfill_trace_ids(langfuse: Any, session_id: str, transcript_path: Path return trace_ids -def list_session_traces(langfuse: Any, session_id: str) -> List[Tuple[str, Optional[str]]]: - """(id, name) of every trace Langfuse holds for the session (read-only).""" - traces_out: List[Tuple[str, Optional[str]]] = [] +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="core") + 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 trace_id: + 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: @@ -4346,7 +4519,8 @@ def plan_trace_replacement( 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 trace_id, name in traces: + 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: @@ -4356,6 +4530,48 @@ def plan_trace_replacement( 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]) @@ -4383,12 +4599,22 @@ def check_backfill_target(transcript_path: Path, session_id: str, *, force: bool return f"no row of {transcript_path.name} belongs to session {session_id!r}" if not force: try: - idle_minutes = (time.time() - transcript_path.stat().st_mtime) / 60 + 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 (a live hook would add turns beside the backfill). Wait " + 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 @@ -4499,9 +4725,18 @@ def run_backfill(argv: List[str]) -> int: return 2 try: # 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"backfilled {turns} turn(s) of session {session_id} (namespace {TRACE_SEED_NAMESPACE})") + print(f"uploaded {turns} turn(s) of session {session_id} (namespace {TRACE_SEED_NAMESPACE}); " + f"verifying {sum(len(v) for v in expected.values())} observation(s) in {len(expected)} trace(s)") + 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; the upload failed or is still being ingested. " + f"Nothing was deleted.", 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"]) diff --git a/tests/integration/test_agent_completion.py b/tests/integration/test_agent_completion.py new file mode 100644 index 0000000..765a398 --- /dev/null +++ b/tests/integration/test_agent_completion.py @@ -0,0 +1,242 @@ +"""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 diff --git a/tests/integration/test_backfill_guards.py b/tests/integration/test_backfill_guards.py index e8366a8..74eb4ff 100644 --- a/tests/integration/test_backfill_guards.py +++ b/tests/integration/test_backfill_guards.py @@ -32,14 +32,20 @@ def write_transcript(directory: Path, session_id: str = SESSION, *, age_minutes: 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") - return SimpleNamespace(data=list(self.traces), meta=SimpleNamespace(total_pages=1)) + 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") @@ -47,13 +53,18 @@ def delete_multiple(self, *, trace_ids: List[str]) -> None: class RecordingClient(FakeLangfuse): - def __init__(self, traces: List[Any]) -> None: + 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 @@ -65,8 +76,11 @@ def trace(trace_id: str, name: Any) -> Any: @pytest.fixture def client(hook_module, monkeypatch): - def make(traces: List[Any]) -> RecordingClient: - instance = RecordingClient(traces) + 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) @@ -132,8 +146,6 @@ def test_second_run_in_the_same_namespace_is_refused(hook_module, client, tmp_pa transcript = write_transcript(tmp_path) c = client([]) assert hook_module.run_backfill(["--backfill", str(transcript)]) == 0 - uploaded = {o.trace_id for o in c.observations} - c.api.trace.traces = [trace(t, hook_module.TRACE_NAME) for t in uploaded] before = len(c.observations) assert hook_module.run_backfill(["--backfill", str(transcript)]) == 3 assert len(c.observations) == before @@ -148,3 +160,50 @@ def test_dry_run_lists_the_delete_plan_and_deletes_nothing(hook_module, client, 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 == [] From 375077db338726ad6f89e9b1d573fb79c59c8bba Mon Sep 17 00:00:00 2001 From: Miguel Pereira Date: Sat, 17 Oct 2026 14:21:22 +0100 Subject: [PATCH 5/5] Revisit unsettled agents between Stops; background shells; backfill recovery Round 3 held with residuals: - A registered agent was skipped whenever its size had not changed and its span had shipped, so a woken agent's final message written with stop_reason null was never exported, and the idle bounds never fired for an agent first seen fresh. The registry now records whether an agent is at rest and which message it holds back; such agents are re-read once their idle bound is due, and always at SessionEnd. - A background shell (backgroundTaskId) keeps its agent awake until the shell notifies; task-id-only shell notifications resolve through the agent's own launch results. Main turns keep their gate (documented). - Backfill: --verify-only re-reads an earlier upload without uploading (ids are deterministic) and can finish the replacement; --verify-minutes sets the read-back window; the exit-4 message and README name the recovery path; an empty expectation never counts as verified. - Tests for every case the review listed; the mutation harness grows to 38 mutations, all failing the suite. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01Ga4FKjMftJRxoPaQaiPLHy --- README.md | 9 +- hooks/langfuse_hook.py | 129 +++++++++++++---- tests/conftest.py | 15 ++ tests/integration/test_agent_completion.py | 154 +++++++++++++++++++++ tests/integration/test_backfill_guards.py | 52 +++++++ 5 files changed, 332 insertions(+), 27 deletions(-) diff --git a/README.md b/README.md index c613d49..6c37580 100644 --- a/README.md +++ b/README.md @@ -93,7 +93,14 @@ the hook are read from the environment. - 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. + 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. diff --git a/hooks/langfuse_hook.py b/hooks/langfuse_hook.py index 0c7a156..11f3013 100644 --- a/hooks/langfuse_hook.py +++ b/hooks/langfuse_hook.py @@ -1332,13 +1332,18 @@ def get_stopped_task_id(row: Dict[str, Any]) -> Optional[str]: 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 and shells, agentId for agents).""" + (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") + 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)): @@ -1476,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 @@ -3364,6 +3374,13 @@ def active_agent_registry(registry: Optional[AgentRegistry]) -> Any: _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 @@ -3422,7 +3439,7 @@ def agent_is_settled(turns: List[Turn]) -> bool: if not turns: return False for turn in turns: - if turn_has_unresolved_async_activity(turn): + 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: @@ -3442,11 +3459,44 @@ def agent_is_settled_but_for_streaming(turns: List[Turn]) -> bool: 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) for turn in turns): + 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], @@ -3485,12 +3535,7 @@ def emit_subagent_observations(langfuse: Langfuse, parent_otel_span: Any, 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 entry.get("size") == size - and (entry.get("span_exported") or not force) - ): + 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 @@ -3498,8 +3543,12 @@ def emit_subagent_observations(langfuse: Langfuse, parent_otel_span: Any, if rows is None: return start_timestamp - # Notifications inside the agent's transcript may carry only a task id. - turns = build_turns(rows, get_task_id_to_tool_use_id(subagent_transcripts_by_tool_use_id)) + # 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 @@ -3630,6 +3679,12 @@ def emit_subagent_observations(langfuse: Langfuse, parent_otel_span: Any, "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), @@ -3665,9 +3720,7 @@ def refresh_grown_agents( for agent_id, entry in list(registry.entries.items()): path = Path(str(entry.get("path") or "")) size = _get_file_size(path) - if size is None: - continue - if size == entry.get("size") and (entry.get("span_exported") or not force): + 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: @@ -4658,12 +4711,19 @@ def run_backfill(argv: List[str]) -> int: 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 + 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) @@ -4687,8 +4747,8 @@ def run_backfill(argv: List[str]) -> int: # 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 = [trace_id for trace_id, _ in existing if trace_id in keep] - if already: + 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) @@ -4724,17 +4784,34 @@ def run_backfill(argv: List[str]) -> int: print("Langfuse keys missing (LANGFUSE_PUBLIC_KEY / LANGFUSE_SECRET_KEY)", file=sys.stderr) return 2 try: - # 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}); " - f"verifying {sum(len(v) for v in expected.values())} observation(s) in {len(expected)} trace(s)") + 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; the upload failed or is still being ingested. " - f"Nothing was deleted.", file=sys.stderr) + 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: diff --git a/tests/conftest.py b/tests/conftest.py index 7a0d259..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 diff --git a/tests/integration/test_agent_completion.py b/tests/integration/test_agent_completion.py index 765a398..c38f005 100644 --- a/tests/integration/test_agent_completion.py +++ b/tests/integration/test_agent_completion.py @@ -240,3 +240,157 @@ def test_agent_killed_mid_message_settles_after_the_idle_bound(hook_module, fake _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 index 74eb4ff..121f8a4 100644 --- a/tests/integration/test_backfill_guards.py +++ b/tests/integration/test_backfill_guards.py @@ -207,3 +207,55 @@ def test_a_recently_written_agent_transcript_counts_as_live(hook_module, client, 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 == []