From d61b5919ae1eb5ac16be6fb8adc924c867afdc86 Mon Sep 17 00:00:00 2001 From: Nigel Jones Date: Tue, 18 Aug 2026 12:15:10 +0100 Subject: [PATCH 01/12] feat(telemetry): add ADAPTER_FUNCTION_*_START hooks and fire them Progresses #1466. The ADAPTER_FUNCTION_INVOCATION_COMPLETE and ADAPTER_FUNCTION_PHASE_COMPLETE hooks had no start-side sibling, so no plugin could open a span for the adapter-function lifecycle -- this is the structural root cause #1454 worked around by opening spans inline in mellea/backends/. Adds ADAPTER_FUNCTION_INVOCATION_START and ADAPTER_FUNCTION_PHASE_START, each carrying a new invocation_id correlation field (also added to the existing COMPLETE payloads) so a tracing plugin can key spans safely under concurrent invocations. Fires the new hooks from AdapterMixin. adapter_scope() (activate/deactivate) and from LocalFileBinding. prepare(), which now opens its own single-phase invocation since it runs outside adapter_scope -- this also guarantees invocation-complete always fires (even if prepare() raises), which the phase-complete hook's success-only contract cannot, so a later span registry can drain to zero. Reconciles the phase Literal: "release" now appears in it (per #1466's acceptance criteria) with a documented reason it has no firing site -- WeightsBinding.release() runs outside any invocation, unlike prepare/activate/deactivate. No spans yet -- that's the next commit, from a plugin in mellea/telemetry/tracing_plugins.py per #1464/#1466. Assisted-by: Claude Code Signed-off-by: Nigel Jones --- mellea/backends/adapters/_core.py | 245 +++++++++++++++--- mellea/backends/adapters/adapter.py | 138 +++++++++- mellea/plugins/hooks/__init__.py | 4 + mellea/plugins/hooks/adapter_function.py | 77 +++++- mellea/plugins/types.py | 12 + test/backends/test_adapters/_hook_capture.py | 51 +++- .../test_adapters/test_adapter_scope.py | 17 +- .../test_adapters/test_local_file_binding.py | 16 +- .../test_local_file_integration.py | 25 +- test/telemetry/test_metrics_plugins.py | 5 +- 10 files changed, 511 insertions(+), 79 deletions(-) diff --git a/mellea/backends/adapters/_core.py b/mellea/backends/adapters/_core.py index 5351d12f60..4803121fa8 100644 --- a/mellea/backends/adapters/_core.py +++ b/mellea/backends/adapters/_core.py @@ -26,6 +26,7 @@ import json import threading import time +import uuid import warnings from dataclasses import dataclass from typing import TYPE_CHECKING, ClassVar, Literal @@ -401,6 +402,16 @@ def prepare(self) -> None: wall-clock cost of preparing), but worth stating, since a phase added later may not want the same boundary. + Unlike `activate`/`deactivate` (owned by `AdapterMixin.adapter_scope`), + `prepare()` runs outside any wrapping invocation, so it opens its own + single-phase `adapter_function_invocation_start`/`_complete` pair around + the `adapter_function_phase_start`/`_complete` pair — this is what lets a + `AdapterFunctionTracingPlugin` (`mellea/telemetry/tracing_plugins.py`) + emit `adapter_function.prepare` as a child of its own `adapter_function` + parent span, and guarantees the in-flight span registry drains even if + `prepare()` raises (the invocation-complete hook always fires, in a + `finally`, unlike the phase-complete hook, which only fires on success). + Raises: RuntimeError: `bind_backend()` was not called first, `name` is empty, the binding was already `release()`d, or the backend refused @@ -416,44 +427,63 @@ def prepare(self) -> None: ) if self.backend is not None and self._loaded: return - if self.backend is None: - if self._staged_backend is None: - raise RuntimeError( - "LocalFileBinding.prepare() requires bind_backend() to be called first." - ) - if not self.name: - raise RuntimeError( - "LocalFileBinding.prepare() requires a non-empty name. A " - "default-constructed LocalFileBinding() is an unconfigured " - "placeholder — build one with LocalFileBinding.from_catalog(name) " - "instead." - ) - self._staged_backend.add_adapter(self) - # `add_adapter` signals success by setting `.backend`; it has early-return - # paths (notably: a different object already registered under this - # `qualified_name`) that log a warning and leave it unset. Without this - # check `prepare()` would go on to load the *other* adapter's weights and - # leave `.backend` None, so a later `activate()` would raise "requires - # prepare() to be called first" despite `prepare()` having run. Fail here - # instead, where the cause is still visible. + invocation_id = str(uuid.uuid4()) + revision: str | None + try: + revision = self.resolved_revision() + except Exception: + revision = self.revision + self._fire_invocation_start(invocation_id, revision) + self._fire_phase_start(invocation_id, "prepare", revision) + + error: BaseException | None = None + try: if self.backend is None: - raise RuntimeError( - f"Backend refused to register adapter {self.qualified_name!r}; see the " - "backend's warning log. Either another adapter is already registered " - "under this qualified name, or this binding was previously released — " - "`release()` is terminal and does not free the name for re-use " - "(see #1528)." - ) - # `load_peft_adapter` mutates the backend's underlying PEFT model, the - # same shared state `activate_peft_adapter`/`deactivate_peft_adapter` - # document "must be called while holding `_generation_lock`" for. - # `prepare()`/`release()` aren't driven through `adapter_scope`, so - # nothing else takes this lock on their behalf. - with self.backend._adapter_activation_lock(): - self.backend.load_peft_adapter(self.qualified_name) - self._loaded = True - self._fire_phase_complete("prepare", time.monotonic() - started_at) + if self._staged_backend is None: + raise RuntimeError( + "LocalFileBinding.prepare() requires bind_backend() to be called first." + ) + if not self.name: + raise RuntimeError( + "LocalFileBinding.prepare() requires a non-empty name. A " + "default-constructed LocalFileBinding() is an unconfigured " + "placeholder — build one with LocalFileBinding.from_catalog(name) " + "instead." + ) + + self._staged_backend.add_adapter(self) + # `add_adapter` signals success by setting `.backend`; it has early-return + # paths (notably: a different object already registered under this + # `qualified_name`) that log a warning and leave it unset. Without this + # check `prepare()` would go on to load the *other* adapter's weights and + # leave `.backend` None, so a later `activate()` would raise "requires + # prepare() to be called first" despite `prepare()` having run. Fail here + # instead, where the cause is still visible. + if self.backend is None: + raise RuntimeError( + f"Backend refused to register adapter {self.qualified_name!r}; see the " + "backend's warning log. Either another adapter is already registered " + "under this qualified name, or this binding was previously released — " + "`release()` is terminal and does not free the name for re-use " + "(see #1528)." + ) + # `load_peft_adapter` mutates the backend's underlying PEFT model, the + # same shared state `activate_peft_adapter`/`deactivate_peft_adapter` + # document "must be called while holding `_generation_lock`" for. + # `prepare()`/`release()` aren't driven through `adapter_scope`, so + # nothing else takes this lock on their behalf. + with self.backend._adapter_activation_lock(): + self.backend.load_peft_adapter(self.qualified_name) + self._loaded = True + except BaseException as exc: + error = exc + raise + finally: + self._fire_invocation_complete(invocation_id, revision, error) + self._fire_phase_complete( + "prepare", time.monotonic() - started_at, invocation_id + ) def activate(self) -> None: """Selects already-loaded adapter weights for generation. @@ -544,18 +574,148 @@ def release(self) -> None: self._active = False self._released = True - def _fire_phase_complete(self, phase: str, duration_s: float) -> None: + def _fire_invocation_start(self, invocation_id: str, revision: str | None) -> None: + """Fires `adapter_function_invocation_start` for the prepare-only invocation this call owns. + + `prepare()` does not run inside `AdapterMixin.adapter_scope`, so it opens + its own single-phase invocation (start here, complete in + `_fire_invocation_complete`) rather than relying on one supplied by a + caller — this is what lets a tracing plugin open a real `adapter_function` + parent span for `adapter_function.prepare` to nest under, and guarantees + the invocation-complete hook always fires (even if `prepare()` raises), + which `_fire_phase_complete`'s success-only firing cannot. + + Args: + invocation_id: Correlation id shared with the matching + `_fire_invocation_complete` call. + revision: Catalog revision of the adapter, or `None` if unpinned. + """ + if not has_plugins(HookType.ADAPTER_FUNCTION_INVOCATION_START): + return + + from ...plugins.hooks.adapter_function import ( + AdapterFunctionInvocationStartPayload, + ) + + try: + payload = AdapterFunctionInvocationStartPayload( + invocation_id=invocation_id, + name=self.name, + revision=revision, + binding_type=self.binding_type, + adapter_type=self.adapter_type.value, + ) + hook_coro = invoke_hook(HookType.ADAPTER_FUNCTION_INVOCATION_START, payload) + _run_async_in_thread(hook_coro) + except Exception: + MelleaLogger.get_logger().warning( + f"adapter_function_invocation_start hook dispatch failed for " + f"{self.name!r}; ignoring so it does not block prepare().", + exc_info=True, + ) + + def _fire_invocation_complete( + self, invocation_id: str, revision: str | None, error: BaseException | None + ) -> None: + """Fires `adapter_function_invocation_complete` for the prepare-only invocation this call owns. + + Always fires, in `prepare()`'s `finally`, regardless of success or + failure — unlike `_fire_phase_complete`, whose contract fires only on + success. This is what lets a tracing plugin close the `adapter_function` + parent span (and defensively close any dangling `adapter_function.prepare` + child span) even when `prepare()` itself raised, so the in-flight span + registry still drains to zero. + + `prepare()` never parses adapter output, so its outcome is always + `"success"` or `"error"` — `"schema_error"` is reserved for + `AdapterMixin.adapter_scope`. + + Args: + invocation_id: Correlation id shared with the matching + `_fire_invocation_start` call. + revision: Catalog revision of the adapter, or `None` if unpinned. + error: The exception raised during `prepare()`, or `None` on success. + """ + if not has_plugins(HookType.ADAPTER_FUNCTION_INVOCATION_COMPLETE): + return + + from ...plugins.hooks.adapter_function import ( + AdapterFunctionInvocationCompletePayload, + ) + + try: + payload = AdapterFunctionInvocationCompletePayload( + invocation_id=invocation_id, + name=self.name, + revision=revision, + binding_type=self.binding_type, + adapter_type=self.adapter_type.value, + outcome="error" if error is not None else "success", + error=error, + ) + hook_coro = invoke_hook( + HookType.ADAPTER_FUNCTION_INVOCATION_COMPLETE, payload + ) + _run_async_in_thread(hook_coro) + except Exception: + MelleaLogger.get_logger().warning( + f"adapter_function_invocation_complete hook dispatch failed for " + f"{self.name!r}; ignoring so it doesn't mask the real outcome.", + exc_info=True, + ) + + def _fire_phase_start( + self, invocation_id: str, phase: str, revision: str | None + ) -> None: + """Fires `adapter_function_phase_start` for a phase this binding is about to run. + + Only `"prepare"` is fired from here — see `_fire_phase_complete`. + + Args: + invocation_id: Correlation id of the enclosing (prepare-only) invocation. + phase: Lifecycle phase name; must be a valid + `AdapterFunctionPhaseStartPayload.phase` value. + revision: Catalog revision of the adapter, or `None` if unpinned. + """ + if not has_plugins(HookType.ADAPTER_FUNCTION_PHASE_START): + return + + from ...plugins.hooks.adapter_function import AdapterFunctionPhaseStartPayload + + try: + payload = AdapterFunctionPhaseStartPayload( + invocation_id=invocation_id, + name=self.name, + phase=phase, + revision=revision, + ) + hook_coro = invoke_hook(HookType.ADAPTER_FUNCTION_PHASE_START, payload) + _run_async_in_thread(hook_coro) + except Exception: + MelleaLogger.get_logger().warning( + f"adapter_function_phase_start hook dispatch failed for {self.name!r} " + f"during {phase!r}; ignoring so it does not block the phase from " + "running.", + exc_info=True, + ) + + def _fire_phase_complete( + self, phase: str, duration_s: float, invocation_id: str + ) -> None: """Fires `adapter_function_phase_complete` for a phase this binding owns. Only `"prepare"` is fired from here: `"activate"`/`"deactivate"` are - owned by `AdapterMixin.adapter_scope`, and `"release"` has no phase - metric in the `AdapterFunctionPhaseCompletePayload` contract (Epic #929 - Phase 1, issue #1140). + owned by `AdapterMixin.adapter_scope`, and `"release"` has no firing site + at all — it has a `Literal` value (Epic #929 Phase 1, issue #1140 first + gave it a phase-metric contract with no metric; issue #1466 keeps that + deliberately unfired, since `release()` runs outside any invocation) but + is otherwise unobserved. Args: phase: Lifecycle phase name; must be a valid `AdapterFunctionPhaseCompletePayload.phase` value. duration_s: Wall-clock duration of the phase, in seconds. + invocation_id: Correlation id of the enclosing (prepare-only) invocation. """ if not has_plugins(HookType.ADAPTER_FUNCTION_PHASE_COMPLETE): return @@ -566,7 +726,10 @@ def _fire_phase_complete(self, phase: str, duration_s: float) -> None: try: payload = AdapterFunctionPhaseCompletePayload( - name=self.name, phase=phase, duration_ms=duration_s * 1000.0 + invocation_id=invocation_id, + name=self.name, + phase=phase, + duration_ms=duration_s * 1000.0, ) hook_coro = invoke_hook(HookType.ADAPTER_FUNCTION_PHASE_COMPLETE, payload) _run_async_in_thread(hook_coro) diff --git a/mellea/backends/adapters/adapter.py b/mellea/backends/adapters/adapter.py index 0e5bb2e3f5..ad5bbeb2c3 100644 --- a/mellea/backends/adapters/adapter.py +++ b/mellea/backends/adapters/adapter.py @@ -19,6 +19,7 @@ import pathlib import re import time +import uuid import warnings from collections.abc import Callable from typing import Literal, TypeAlias, TypeVar, cast @@ -336,7 +337,43 @@ def get_adapter_for_intrinsic( return adapter -def _fire_phase_complete_hook(name: str, phase: str, duration_ms: float) -> None: +def _fire_phase_start_hook( + invocation_id: str, name: str, phase: str, revision: str | None +) -> None: + """Fire the `adapter_function_phase_start` hook for a phase about to run. + + A hook-dispatch failure is logged and ignored: observability must not block + a phase from running. + + Args: + invocation_id: Correlation id of the enclosing invocation. + name: Adapter function name, used as the metric's `name` field. + phase: Lifecycle phase name; must be a valid + `AdapterFunctionPhaseStartPayload.phase` value. + revision: Catalog revision of the adapter, or `None` if unpinned. + """ + if not has_plugins(HookType.ADAPTER_FUNCTION_PHASE_START): + return + from ...plugins.hooks.adapter_function import AdapterFunctionPhaseStartPayload + + payload = AdapterFunctionPhaseStartPayload( + invocation_id=invocation_id, name=name, phase=phase, revision=revision + ) + try: + hook_coro = invoke_hook(HookType.ADAPTER_FUNCTION_PHASE_START, payload) + _run_async_in_thread(hook_coro) + except Exception: + MelleaLogger.get_logger().warning( + f"adapter_function_phase_start hook dispatch failed for {name!r} " + f"during {phase!r}; ignoring so it does not block the phase from " + "running.", + exc_info=True, + ) + + +def _fire_phase_complete_hook( + invocation_id: str, name: str, phase: str, duration_ms: float +) -> None: """Fire the `adapter_function_phase_complete` metric hook for a phase that already ran. Split out of `_run_adapter_phase` so a caller that must guarantee cleanup @@ -347,6 +384,7 @@ def _fire_phase_complete_hook(name: str, phase: str, duration_ms: float) -> None lifecycle phase into an operation failure. Args: + invocation_id: Correlation id of the enclosing invocation. name: Adapter function name, used as the metric's `name` field. phase: Lifecycle phase name; must be a valid `AdapterFunctionPhaseCompletePayload.phase` value. @@ -357,7 +395,7 @@ def _fire_phase_complete_hook(name: str, phase: str, duration_ms: float) -> None from ...plugins.hooks.adapter_function import AdapterFunctionPhaseCompletePayload payload = AdapterFunctionPhaseCompletePayload( - name=name, phase=phase, duration_ms=duration_ms + invocation_id=invocation_id, name=name, phase=phase, duration_ms=duration_ms ) try: hook_coro = invoke_hook(HookType.ADAPTER_FUNCTION_PHASE_COMPLETE, payload) @@ -371,32 +409,78 @@ def _fire_phase_complete_hook(name: str, phase: str, duration_ms: float) -> None ) -def _run_adapter_phase(name: str, phase: str, phase_fn: Callable[[], None]) -> None: - """Run one lifecycle phase and fire its phase-complete metric hook. +def _run_adapter_phase( + invocation_id: str, + name: str, + phase: str, + revision: str | None, + phase_fn: Callable[[], None], +) -> None: + """Run one lifecycle phase, firing its phase-start and phase-complete hooks. - Fires the hook only; it does not open a span. Span production belongs to a + Fires hooks only; it does not open a span. Span production belongs to a plugin (#1464, #1466), not to code under `mellea/backends/`. - The hook fires **only when the phase succeeds**, matching the name of - `ADAPTER_FUNCTION_PHASE_COMPLETE`: a phase that raised did not complete. If - `phase_fn` raises, the exception propagates and no phase event is emitted, so - a consumer reconciling phase counts against invocation counts will see the - failure only at invocation level, where `outcome` and `error` carry it. + The complete hook fires **only when the phase succeeds**, matching the name + of `ADAPTER_FUNCTION_PHASE_COMPLETE`: a phase that raised did not complete. + If `phase_fn` raises, the exception propagates and no phase-complete event is + emitted (the phase-start event already fired), so a consumer reconciling + phase counts against invocation counts will see the failure only at + invocation level, where `outcome` and `error` carry it. Args: + invocation_id: Correlation id of the enclosing invocation. name: Adapter function name, used as the metric's `name` field. phase: Lifecycle phase name; must be a valid `AdapterFunctionPhaseCompletePayload.phase` value. + revision: Catalog revision of the adapter, or `None` if unpinned. phase_fn: The zero-argument callable implementing the phase (e.g. `adapter.weights.activate`). """ + _fire_phase_start_hook(invocation_id, name, phase, revision) started_at = time.monotonic() phase_fn() - _fire_phase_complete_hook(name, phase, (time.monotonic() - started_at) * 1000.0) + _fire_phase_complete_hook( + invocation_id, name, phase, (time.monotonic() - started_at) * 1000.0 + ) + + +def _fire_invocation_start_hook( + invocation_id: str, + *, + name: str, + revision: str | None, + binding_type: str, + adapter_type: str, +) -> None: + """Fire the `adapter_function_invocation_start` hook. + + Args: + invocation_id: Correlation id shared with the matching + `_fire_invocation_complete` call. + name: Adapter function name. + revision: Catalog revision of the adapter, or `None` if unpinned. + binding_type: Weight-binding reality the adapter will run under. + adapter_type: Adapter mechanism (e.g. `"lora"`, `"alora"`). + """ + if not has_plugins(HookType.ADAPTER_FUNCTION_INVOCATION_START): + return + from ...plugins.hooks.adapter_function import AdapterFunctionInvocationStartPayload + + payload = AdapterFunctionInvocationStartPayload( + invocation_id=invocation_id, + name=name, + revision=revision, + binding_type=binding_type, + adapter_type=adapter_type, + ) + hook_coro = invoke_hook(HookType.ADAPTER_FUNCTION_INVOCATION_START, payload) + _run_async_in_thread(hook_coro) def _fire_invocation_complete( *, + invocation_id: str, name: str, revision: str | None, binding_type: str, @@ -407,6 +491,8 @@ def _fire_invocation_complete( """Fire the `adapter_function_invocation_complete` metric hook. Args: + invocation_id: Correlation id shared with the matching + `_fire_invocation_start_hook` call. name: Adapter function name. revision: Catalog revision of the adapter, or `None` if unpinned. binding_type: Weight-binding reality the adapter ran under. @@ -421,6 +507,7 @@ def _fire_invocation_complete( ) payload = AdapterFunctionInvocationCompletePayload( + invocation_id=invocation_id, name=name, revision=revision, binding_type=binding_type, @@ -789,6 +876,22 @@ def adapter_scope(self, adapter: "_AdapterCore | None"): # type: ignore[type-ar revision = cast(str | None, getattr(adapter.weights, "revision", None)) binding_type = adapter.weights.binding_type adapter_type = adapter.identity.adapter_type + invocation_id = str(uuid.uuid4()) + + try: + _fire_invocation_start_hook( + invocation_id, + name=name, + revision=revision, + binding_type=binding_type, + adapter_type=adapter_type, + ) + except Exception: + MelleaLogger.get_logger().warning( + f"adapter_function_invocation_start hook dispatch failed for " + f"{name!r}; ignoring so it does not block activation.", + exc_info=True, + ) outcome: Literal["success", "schema_error", "error"] = "success" exception: BaseException | None = None @@ -796,11 +899,15 @@ def adapter_scope(self, adapter: "_AdapterCore | None"): # type: ignore[type-ar body_exception: BaseException | None = None try: started_at = time.monotonic() + _fire_phase_start_hook(invocation_id, name, "activate", revision) try: adapter.weights.activate() activated = True _fire_phase_complete_hook( - name, "activate", (time.monotonic() - started_at) * 1000.0 + invocation_id, + name, + "activate", + (time.monotonic() - started_at) * 1000.0, ) try: yield @@ -811,7 +918,11 @@ def adapter_scope(self, adapter: "_AdapterCore | None"): # type: ignore[type-ar if activated: try: _run_adapter_phase( - name, "deactivate", adapter.weights.deactivate + invocation_id, + name, + "deactivate", + revision, + adapter.weights.deactivate, ) except BaseException as deactivate_exc: if body_exception is None: @@ -841,6 +952,7 @@ def adapter_scope(self, adapter: "_AdapterCore | None"): # type: ignore[type-ar # telemetry-plumbing one. Log and swallow instead. try: _fire_invocation_complete( + invocation_id=invocation_id, name=name, revision=revision, binding_type=binding_type, diff --git a/mellea/plugins/hooks/__init__.py b/mellea/plugins/hooks/__init__.py index 3095fc2cfe..5cccf50311 100644 --- a/mellea/plugins/hooks/__init__.py +++ b/mellea/plugins/hooks/__init__.py @@ -5,7 +5,9 @@ from .adapter_function import ( AdapterFunctionInvocationCompletePayload, + AdapterFunctionInvocationStartPayload, AdapterFunctionPhaseCompletePayload, + AdapterFunctionPhaseStartPayload, ) from .component import ( ComponentPostErrorPayload, @@ -31,7 +33,9 @@ __all__ = [ # Adapter Function "AdapterFunctionInvocationCompletePayload", + "AdapterFunctionInvocationStartPayload", "AdapterFunctionPhaseCompletePayload", + "AdapterFunctionPhaseStartPayload", # Component "ComponentPostErrorPayload", "ComponentPostSuccessPayload", diff --git a/mellea/plugins/hooks/adapter_function.py b/mellea/plugins/hooks/adapter_function.py index 924015275b..bae10a40d6 100644 --- a/mellea/plugins/hooks/adapter_function.py +++ b/mellea/plugins/hooks/adapter_function.py @@ -9,11 +9,53 @@ from mellea.plugins.base import MelleaBasePayload +# Every lifecycle phase that fires (or is expected to fire in a future issue) +# ADAPTER_FUNCTION_PHASE_START / ADAPTER_FUNCTION_PHASE_COMPLETE. Firing sites, +# issue #1466: +# prepare -- LocalFileBinding.prepare() +# activate -- AdapterMixin.adapter_scope() +# deactivate -- AdapterMixin.adapter_scope() +# generate -- none yet; blocked on #1465 wiring generation through adapter_scope +# parse -- none yet; blocked on #1465 wiring parsing through adapter_scope +# release -- none yet, deliberately: WeightsBinding.release() runs outside +# adapter_scope and is not wrapped in an invocation, unlike +# prepare/activate/deactivate (see LocalFileBinding.release() and +# the pre-existing note this carries forward from Epic #929 Phase 1 +# that "release" has no phase-duration metric in this contract). +# It keeps a Literal value so downstream consumers can name it, but +# has no firing site — tracked as remaining work, not silently +# dropped. +AdapterFunctionPhase = Literal[ + "prepare", "activate", "generate", "parse", "deactivate", "release" +] + + +class AdapterFunctionInvocationStartPayload(MelleaBasePayload): + """Payload for `adapter_function_invocation_start` — before an adapter function invocation begins. + + Attributes: + invocation_id: Correlation id shared with the matching + `adapter_function_invocation_complete` event. + name: Adapter function name (e.g. `"answerability"`). + revision: Catalog revision of the adapter, or `None` if unpinned. + binding_type: Weight-binding reality the adapter will run under (e.g. + `"local_file"`, `"embedded"`, `"server_mediated"`). + adapter_type: Adapter mechanism (e.g. `"lora"`, `"alora"`). + """ + + invocation_id: str + name: str + revision: str | None = None + binding_type: str = "unknown" + adapter_type: str = "unknown" + class AdapterFunctionInvocationCompletePayload(MelleaBasePayload): """Payload for `adapter_function_invocation_complete` — after an adapter function invocation finishes. Attributes: + invocation_id: Correlation id shared with the `adapter_function_invocation_start` + event that opened this invocation. name: Adapter function name (e.g. `"answerability"`). revision: Catalog revision of the adapter, or `None` if unpinned. binding_type: Weight-binding reality the adapter ran under (e.g. @@ -23,6 +65,7 @@ class AdapterFunctionInvocationCompletePayload(MelleaBasePayload): error: The exception raised during invocation, or `None` on success. """ + invocation_id: str name: str revision: str | None = None binding_type: str = "unknown" @@ -37,20 +80,48 @@ class AdapterFunctionInvocationCompletePayload(MelleaBasePayload): error: Any = None +class AdapterFunctionPhaseStartPayload(MelleaBasePayload): + """Payload for `adapter_function_phase_start` — before one lifecycle phase begins. + + Attributes: + invocation_id: Correlation id of the enclosing invocation (shared with the + `adapter_function_invocation_start`/`_complete` events). + name: Adapter function name (e.g. `"answerability"`). + phase: Lifecycle phase about to run. See `AdapterFunctionPhase` for which + values currently have a firing site. + revision: Catalog revision of the adapter, or `None` if unpinned. Recorded + here (rather than only on the invocation) so a phase's own span can + carry it directly — e.g. `adapter_function.prepare` records the + resolved Hugging Face SHA. + """ + + invocation_id: str + name: str + phase: AdapterFunctionPhase + revision: str | None = None + + class AdapterFunctionPhaseCompletePayload(MelleaBasePayload): """Payload for `adapter_function_phase_complete` — after one lifecycle phase finishes. + Only fires when the phase itself succeeded — a phase that raised did not + complete, and its failure is reported once, at invocation level, via + `adapter_function_invocation_complete`'s `outcome`/`error`. + Attributes: + invocation_id: Correlation id of the enclosing invocation (shared with the + `adapter_function_invocation_start`/`_complete` events). name: Adapter function name (e.g. `"answerability"`). - phase: Lifecycle phase (`"prepare"`, `"activate"`, `"generate"`, - `"parse"`, or `"deactivate"`). + phase: Lifecycle phase that completed. See `AdapterFunctionPhase` for + which values currently have a firing site. duration_ms: Wall-clock duration of the phase in milliseconds. """ + invocation_id: str name: str # Constrained to a Literal so a typo can't silently spawn a new metric-label # series (the phase becomes a metric dimension). Required, with no unset # sentinel: a phase-complete event always has a real phase. (The payload is a # pydantic model, so a required field after the base's defaulted ones is fine.) - phase: Literal["prepare", "activate", "generate", "parse", "deactivate"] + phase: AdapterFunctionPhase duration_ms: float diff --git a/mellea/plugins/types.py b/mellea/plugins/types.py index 343c8bdc81..425aac3d78 100644 --- a/mellea/plugins/types.py +++ b/mellea/plugins/types.py @@ -72,7 +72,9 @@ class HookType(StrEnum): TOOL_POST_INVOKE = "tool_post_invoke" # Adapter Function Lifecycle + ADAPTER_FUNCTION_INVOCATION_START = "adapter_function_invocation_start" ADAPTER_FUNCTION_INVOCATION_COMPLETE = "adapter_function_invocation_complete" + ADAPTER_FUNCTION_PHASE_START = "adapter_function_phase_start" ADAPTER_FUNCTION_PHASE_COMPLETE = "adapter_function_phase_complete" # Streaming Pipeline @@ -95,7 +97,9 @@ def _build_hook_registry() -> dict[str, tuple[type, type]]: """ from mellea.plugins.hooks.adapter_function import ( AdapterFunctionInvocationCompletePayload, + AdapterFunctionInvocationStartPayload, AdapterFunctionPhaseCompletePayload, + AdapterFunctionPhaseStartPayload, ) from mellea.plugins.hooks.component import ( ComponentPostErrorPayload, @@ -184,10 +188,18 @@ def _build_hook_registry() -> dict[str, tuple[type, type]]: HookType.TOOL_PRE_INVOKE.value: (ToolPreInvokePayload, PluginResult), HookType.TOOL_POST_INVOKE.value: (ToolPostInvokePayload, PluginResult), # Adapter Function Lifecycle + HookType.ADAPTER_FUNCTION_INVOCATION_START.value: ( + AdapterFunctionInvocationStartPayload, + PluginResult, + ), HookType.ADAPTER_FUNCTION_INVOCATION_COMPLETE.value: ( AdapterFunctionInvocationCompletePayload, PluginResult, ), + HookType.ADAPTER_FUNCTION_PHASE_START.value: ( + AdapterFunctionPhaseStartPayload, + PluginResult, + ), HookType.ADAPTER_FUNCTION_PHASE_COMPLETE.value: ( AdapterFunctionPhaseCompletePayload, PluginResult, diff --git a/test/backends/test_adapters/_hook_capture.py b/test/backends/test_adapters/_hook_capture.py index 67429030cf..2a9bd79bfa 100644 --- a/test/backends/test_adapters/_hook_capture.py +++ b/test/backends/test_adapters/_hook_capture.py @@ -16,6 +16,13 @@ from collections.abc import Iterator from unittest.mock import MagicMock, patch +from mellea.plugins.hooks.adapter_function import ( + AdapterFunctionInvocationCompletePayload, + AdapterFunctionInvocationStartPayload, + AdapterFunctionPhaseCompletePayload, + AdapterFunctionPhaseStartPayload, +) + _TARGET = "mellea.backends.adapters.adapter" @@ -66,6 +73,22 @@ def hook_payloads(mock_invoke: MagicMock) -> list: return [call.args[1] for call in mock_invoke.call_args_list] +def phase_start_payloads(mock_invoke: MagicMock) -> list: + """Returns only the phase-start payloads. + + Args: + mock_invoke: The mock yielded by `capture_adapter_hooks`. + + Returns: + The recorded `AdapterFunctionPhaseStartPayload`s, ordered as fired. + """ + return [ + p + for p in hook_payloads(mock_invoke) + if isinstance(p, AdapterFunctionPhaseStartPayload) + ] + + def phase_payloads(mock_invoke: MagicMock) -> list: """Returns only the phase-complete payloads. @@ -75,7 +98,27 @@ def phase_payloads(mock_invoke: MagicMock) -> list: Returns: The recorded `AdapterFunctionPhaseCompletePayload`s, ordered as fired. """ - return [p for p in hook_payloads(mock_invoke) if hasattr(p, "phase")] + return [ + p + for p in hook_payloads(mock_invoke) + if isinstance(p, AdapterFunctionPhaseCompletePayload) + ] + + +def invocation_start_payloads(mock_invoke: MagicMock) -> list: + """Returns only the invocation-start payloads. + + Args: + mock_invoke: The mock yielded by `capture_adapter_hooks`. + + Returns: + The recorded `AdapterFunctionInvocationStartPayload`s, ordered as fired. + """ + return [ + p + for p in hook_payloads(mock_invoke) + if isinstance(p, AdapterFunctionInvocationStartPayload) + ] def invocation_payloads(mock_invoke: MagicMock) -> list: @@ -87,4 +130,8 @@ def invocation_payloads(mock_invoke: MagicMock) -> list: Returns: The recorded `AdapterFunctionInvocationCompletePayload`s, ordered as fired. """ - return [p for p in hook_payloads(mock_invoke) if hasattr(p, "outcome")] + return [ + p + for p in hook_payloads(mock_invoke) + if isinstance(p, AdapterFunctionInvocationCompletePayload) + ] diff --git a/test/backends/test_adapters/test_adapter_scope.py b/test/backends/test_adapters/test_adapter_scope.py index 85e3af14fc..4c92856cf6 100644 --- a/test/backends/test_adapters/test_adapter_scope.py +++ b/test/backends/test_adapters/test_adapter_scope.py @@ -27,6 +27,8 @@ from test.backends.test_adapters._hook_capture import ( capture_adapter_hooks, invocation_payloads, + phase_payloads, + phase_start_payloads, ) @@ -201,12 +203,15 @@ def test_adapter_scope_reports_other_exceptions_as_error(): def test_phase_hook_not_fired_when_the_phase_itself_fails(): - """A phase that raised did not complete, so no phase event is emitted. + """A phase that raised opens (phase-start fires) but never completes. - `ADAPTER_FUNCTION_PHASE_COMPLETE` means the phase finished. The failure is - reported once, at invocation level, where `outcome`/`error` carry it — so a + `ADAPTER_FUNCTION_PHASE_COMPLETE` means the phase finished, so it does not + fire for a phase that raised. `ADAPTER_FUNCTION_PHASE_START` fires + regardless, since it only marks the phase as about to run. The failure is + reported at invocation level, where `outcome`/`error` carry it — so a consumer reconciling phase counts against invocation counts sees one - invocation error and no phase event, not both. + invocation error, one phase-start with no matching phase-complete, and no + phase-complete event. """ mock_backend = MagicMock(spec=AdapterMixin) adapter, weights = _make_adapter() @@ -217,8 +222,8 @@ def test_phase_hook_not_fired_when_the_phase_itself_fails(): with AdapterMixin.adapter_scope(mock_backend, adapter): pytest.fail("body must not run when activate() raises") - payloads = [c.args[1] for c in mock_invoke.call_args_list] - assert [p for p in payloads if hasattr(p, "phase")] == [] + assert [p.phase for p in phase_start_payloads(mock_invoke)] == ["activate"] + assert phase_payloads(mock_invoke) == [] invocations = invocation_payloads(mock_invoke) assert [p.outcome for p in invocations] == ["error"] diff --git a/test/backends/test_adapters/test_local_file_binding.py b/test/backends/test_adapters/test_local_file_binding.py index 37b10ebf70..669fda94fc 100644 --- a/test/backends/test_adapters/test_local_file_binding.py +++ b/test/backends/test_adapters/test_local_file_binding.py @@ -492,6 +492,13 @@ def test_release_is_idempotent(): def test_prepare_fires_phase_complete_metric_when_plugins_present(): + """`prepare()` fires its own invocation-start/complete pair around the phase-start/complete pair. + + Four hook dispatches total: invocation_start, phase_start, phase_complete, + invocation_complete — see `LocalFileBinding.prepare()`'s docstring for why + `prepare()` opens its own single-phase invocation rather than relying on one + supplied by a caller. + """ pytest.importorskip("cpex", reason="cpex not installed — install mellea[hooks]") backend = _fake_backend() binding = LocalFileBinding(name="answerability") @@ -503,10 +510,11 @@ def test_prepare_fires_phase_complete_metric_when_plugins_present(): ): binding.prepare() - mock_run.assert_called_once() - hook_coro = mock_run.call_args.args[0] - assert isinstance(hook_coro, Coroutine) - hook_coro.close() + assert mock_run.call_count == 4 + for call in mock_run.call_args_list: + hook_coro = call.args[0] + assert isinstance(hook_coro, Coroutine) + hook_coro.close() def test_release_does_not_fire_phase_complete_metric(): diff --git a/test/backends/test_adapters/test_local_file_integration.py b/test/backends/test_adapters/test_local_file_integration.py index a369ffad72..b8ec39779c 100644 --- a/test/backends/test_adapters/test_local_file_integration.py +++ b/test/backends/test_adapters/test_local_file_integration.py @@ -36,7 +36,10 @@ from mellea.core import Component from test.backends.test_adapters._hook_capture import ( capture_adapter_hooks, - hook_payloads, + invocation_payloads, + invocation_start_payloads, + phase_payloads, + phase_start_payloads, ) pytestmark = pytest.mark.integration @@ -117,16 +120,22 @@ def test_prepare_activate_deactivate_release_full_lifecycle(): backend._model.delete_adapter.assert_called_once_with(binding.qualified_name) # type: ignore[union-attr] assert binding.backend is None - recorded = hook_payloads(mock_invoke) - phases = [p.phase for p in recorded if hasattr(p, "phase")] - assert phases == ["activate", "deactivate"] + assert [p.phase for p in phase_start_payloads(mock_invoke)] == [ + "activate", + "deactivate", + ] + assert [p.phase for p in phase_payloads(mock_invoke)] == ["activate", "deactivate"] - invocations = [p for p in recorded if hasattr(p, "outcome")] + invocation_starts = invocation_start_payloads(mock_invoke) + assert len(invocation_starts) == 1 + + invocations = invocation_payloads(mock_invoke) assert len(invocations) == 1 assert invocations[0].outcome == "success" assert invocations[0].name == "answerability" assert invocations[0].binding_type == "local_file" assert invocations[0].adapter_type == binding.adapter_type.value + assert invocations[0].invocation_id == invocation_starts[0].invocation_id def test_deactivate_runs_even_when_generation_body_raises(): @@ -151,11 +160,9 @@ def test_deactivate_runs_even_when_generation_body_raises(): # deactivate still ran, and the invocation is reported as an error carrying # the original exception — the behaviour the span status used to assert. - recorded = hook_payloads(mock_invoke) - phases = [p.phase for p in recorded if hasattr(p, "phase")] - assert "deactivate" in phases + assert "deactivate" in [p.phase for p in phase_payloads(mock_invoke)] - invocations = [p for p in recorded if hasattr(p, "outcome")] + invocations = invocation_payloads(mock_invoke) assert len(invocations) == 1 assert invocations[0].outcome == "error" assert isinstance(invocations[0].error, RuntimeError) diff --git a/test/telemetry/test_metrics_plugins.py b/test/telemetry/test_metrics_plugins.py index 3258dfe6d2..894ff89d7b 100644 --- a/test/telemetry/test_metrics_plugins.py +++ b/test/telemetry/test_metrics_plugins.py @@ -1084,6 +1084,7 @@ def adapter_function_plugin(): async def test_record_adapter_function_invocation_success(adapter_function_plugin): """A successful invocation records the invocations counter, not parse_failures.""" payload = AdapterFunctionInvocationCompletePayload( + invocation_id="inv-1", name="answerability", revision="r1", binding_type="local_file", @@ -1117,6 +1118,7 @@ async def test_record_adapter_function_invocation_schema_error_also_records_pars ): """A schema_error outcome records both the invocations counter and parse_failures.""" payload = AdapterFunctionInvocationCompletePayload( + invocation_id="inv-2", name="answerability", revision="r1", binding_type="local_file", @@ -1154,6 +1156,7 @@ async def test_record_adapter_function_invocation_none_revision_passed_through( not in the plugin — so the plugin passes the raw payload.revision value. """ payload = AdapterFunctionInvocationCompletePayload( + invocation_id="inv-3", name="answerability", revision=None, binding_type="embedded", @@ -1179,7 +1182,7 @@ async def test_record_adapter_function_invocation_none_revision_passed_through( async def test_record_adapter_function_phase_duration(adapter_function_plugin): """Phase-complete events record the phase-duration histogram in seconds.""" payload = AdapterFunctionPhaseCompletePayload( - name="answerability", phase="prepare", duration_ms=12.5 + invocation_id="inv-4", name="answerability", phase="prepare", duration_ms=12.5 ) with patch( From 0d17643d44d8fc9a2f4e7b7dcd4996b68b179ac6 Mon Sep 17 00:00:00 2001 From: Nigel Jones Date: Tue, 18 Aug 2026 13:05:27 +0100 Subject: [PATCH 02/12] feat(telemetry): emit adapter_function spans from a tracing plugin Progresses #1466. Adds AdapterFunctionTracingPlugin to mellea/telemetry/tracing_plugins.py, which turns the ADAPTER_FUNCTION_* hooks added in the previous commit into an adapter_function parent span with one adapter_function. child per lifecycle phase (prepare/activate/deactivate; generate/parse are blocked on #1465). On the mellea.backend tracer -- adapter/model lifecycle work is a backend concern, not a user-facing operation. The child spans parent explicitly via trace.set_span_in_context, looked up by invocation_id, rather than via the ambient-attach convention every other span pair in this codebase uses. ADAPTER_FUNCTION_*_START/_COMPLETE fire from sync code (adapter_scope, LocalFileBinding.prepare) via _run_async_in_thread, which runs each hook as an independent task seeded from a fresh contextvars snapshot of the calling thread -- an ambient-context attach inside one hook's task is invisible to the next hook's snapshot, so ambient nesting can't work here regardless of Python version. Explicit parenting sidesteps that entirely and needs no _CONTEXT_ATTACH_SUPPORTED gating. adapter_function_invocation_complete defensively closes any phase child span still open (a phase that raised fires phase_start but never its own success-only phase_complete), so the in-flight span registry still drains to zero on a raised phase. adapter_function.prepare records the resolved Hugging Face SHA as mellea.adapter_function.revision, not "main" (moved from #1141). Content capture (MELLEA_TRACES_CONTENT) is not wired here: no phase in this scope carries adapter input/output content -- that applies to generate/parse, landing with #1465. Documents the span schema, the tracer choice and its rationale, and the explicit-parenting decision in docs/docs/observability/tracing.md -- the current home for this content now that docs/dev/adapter_observability.md (the location #1466 named) has been deleted and folded into published docs and code (see PR #1483/#1548). Assisted-by: Claude Code Signed-off-by: Nigel Jones --- docs/docs/observability/tracing.md | 55 ++ mellea/telemetry/tracing.py | 189 ++++++ mellea/telemetry/tracing_plugins.py | 93 +++ .../test_tracing_adapter_function.py | 543 ++++++++++++++++++ 4 files changed, 880 insertions(+) create mode 100644 test/telemetry/test_tracing_adapter_function.py diff --git a/docs/docs/observability/tracing.md b/docs/docs/observability/tracing.md index 0272173c32..0db8db4ed5 100644 --- a/docs/docs/observability/tracing.md +++ b/docs/docs/observability/tracing.md @@ -243,6 +243,61 @@ When `MELLEA_GENERATION_CHUNK_EVENTS=true`, backend spans also record a `chunk_p span event per streamed chunk, carrying its index and added text length. This is opt-in and off by default, since a long response produces one event per chunk. +#### `adapter_function` span and its phase children + +Covers the adapter-function lifecycle (Epic #929) — LoRA/aLoRA adapters used +for RAG, safety, and core capability checks (`answerability`, +`requirement_check`, etc.). On `mellea.backend`: adapter/model lifecycle work +is a backend concern, not a user-facing operation. + +**As of #1466, this covers `prepare`/`activate`/`deactivate` only.** +`generate`/`parse` fire no spans yet — that lands with #1465, which wires real +generation through `AdapterMixin.adapter_scope`. `release` fires no span at +all: `WeightsBinding.release()` runs outside any invocation and has no +hook-firing site (see below). + +One `adapter_function` parent span per invocation: + +| Attribute | Description | +| --------- | ----------- | +| `mellea.adapter_function.name` | Adapter function name (e.g. `answerability`) | +| `mellea.adapter_function.revision` | Catalog revision (Hugging Face SHA); omitted when unpinned | +| `mellea.adapter_function.binding_type` | Weight-binding reality (e.g. `local_file`) | +| `mellea.adapter_function.adapter_type` | Adapter mechanism (`lora` or `alora`) | +| `mellea.adapter_function.outcome` | `success`, `schema_error`, or `error` — set when the span closes | + +**Two distinct kinds of invocation exist in this architecture, not one:** +`LocalFileBinding.prepare()` typically runs once at setup and opens its own +single-phase invocation (a parent span with just an `adapter_function.prepare` +child); `AdapterMixin.adapter_scope()` opens a separate invocation per call, +wrapping `adapter_function.activate` and `adapter_function.deactivate` (and, +once #1465 lands, `generate`/`parse`). `prepare()` and a later `adapter_scope()` +call on the same adapter do **not** share a parent span. + +One `adapter_function.` child span per lifecycle phase that ran: + +| Attribute | Description | +| --------- | ----------- | +| `mellea.adapter_function.phase` | `prepare`, `activate`, `deactivate` (`generate`/`parse` once #1465 lands) | +| `mellea.adapter_function.revision` | Same revision as the parent, recorded directly on the phase span too | + +A phase that raises opens its child span but never fires its own completion +event (matching `mellea.adapter_function.phase_duration`'s metric semantics: +a phase that didn't finish contributes no duration sample) — the enclosing +invocation's own close defensively ends that child span with `ERROR` status +instead, so the in-flight span registry still drains to zero. + +**Nesting is unconditional, unlike every other span pair in this document.** +Every other family nests via ambient OTel context attach, which needs +Python 3.12+ (see the note at the end of this section) — `adapter_function` +children instead parent explicitly via `trace.set_span_in_context`, because +`ADAPTER_FUNCTION_*_START`/`_COMPLETE` fire from **synchronous** code +(`adapter_scope`, `prepare()`) through `_run_async_in_thread`, under which +ambient attach can't establish a parent/child edge at all (each dispatched +hook call gets an independent `contextvars` snapshot of the calling thread). +So `adapter_function.` nests under `adapter_function` the same way on +Python 3.11 and 3.12+. + ### Span hierarchy Backend spans nest inside application spans: diff --git a/mellea/telemetry/tracing.py b/mellea/telemetry/tracing.py index 934d25d7d6..ebfc9b3202 100644 --- a/mellea/telemetry/tracing.py +++ b/mellea/telemetry/tracing.py @@ -1086,6 +1086,195 @@ def finish_validation_span( _finish_application_span_error(validation_id, exception=exception) +# Child phase spans are stashed under a key derived from the invocation id so +# they can't collide with the parent's own `_in_flight_spans` entry (keyed by +# the bare invocation id) or with each other across phases of the same +# invocation. +_ADAPTER_FUNCTION_PHASE_KEY_INFIX = ":phase:" + + +def _adapter_function_phase_key(invocation_id: str, phase: str) -> str: + return f"{invocation_id}{_ADAPTER_FUNCTION_PHASE_KEY_INFIX}{phase}" + + +def start_adapter_function_span( + invocation_id: str, + *, + name: str, + revision: str | None, + binding_type: str, + adapter_type: str, + attach_context: bool = False, +) -> Span | None: + """Open the `adapter_function` parent span for one adapter-function invocation. + + On the `mellea.backend` tracer: adapter/model lifecycle work is a backend + concern, not a user-facing operation (see + `docs/docs/observability/tracing.md`). + + `attach_context` defaults to `False`, unlike every other `start_*_span` + helper. `ADAPTER_FUNCTION_INVOCATION_START`/`_PHASE_START` fire from sync + code (`AdapterMixin.adapter_scope`, `LocalFileBinding.prepare`) via + `_run_async_in_thread`, which runs each hook as an independent task on a + shared background event loop, seeded from a *fresh* `contextvars.copy_context()` + snapshot of the calling thread taken at that call — mutations inside one + hook's task (like an ambient-context attach) never leak back to the + calling thread and so are invisible to the *next* `_run_async_in_thread` + call's snapshot. Ambient attach/detach across two such calls therefore + can't establish a parent/child edge (and mismatched attach/detach tasks + trigger "Detaching an OTel context token across asyncio tasks" warnings) + — `start_adapter_function_phase_span` instead parents explicitly via + `trace.set_span_in_context` using the span object looked up by + `invocation_id`, which needs no ambient context at all. + + Args: + invocation_id: Correlation key for the matching `finish_adapter_function_span` call. + name: Adapter function name (e.g. `"answerability"`). + revision: Catalog revision of the adapter, or `None` if unpinned. + binding_type: Weight-binding reality the adapter is running under (e.g. + `"local_file"`, `"embedded"`, `"server_mediated"`). + adapter_type: Adapter mechanism (e.g. `"lora"`, `"alora"`). + attach_context: Whether to attach the span as the ambient OTel context. + Left `False` by every current caller — see above. + + Returns: + The span, or `None` if tracing is disabled. + """ + tracer = get_backend_tracer() + if tracer is None: + return None + + span = tracer.start_span("adapter_function") + set_attribute_safe(span, "mellea.adapter_function.name", name) + set_attribute_safe(span, "mellea.adapter_function.revision", revision) + set_attribute_safe(span, "mellea.adapter_function.binding_type", binding_type) + set_attribute_safe(span, "mellea.adapter_function.adapter_type", adapter_type) + + token = _attach_span_context(span, attach=attach_context) + _in_flight_spans[invocation_id] = (span, token, _current_task()) + return span + + +def finish_adapter_function_span( + invocation_id: str, *, outcome: str, exception: BaseException | None +) -> None: + """End the `adapter_function` span, recording its outcome. + + Defensively closes any `adapter_function.` child span still open + under this invocation first — a phase that raised fires + `adapter_function_phase_start` but never its own + `adapter_function_phase_complete` (that hook's contract is success-only), + so without this the child span would never close and the in-flight + registry would never drain. The dangling child is marked ERROR with the + same exception as the invocation. + + Args: + invocation_id: Correlation key from the matching `start_adapter_function_span` call. + outcome: `"success"`, `"schema_error"`, or `"error"`. + exception: The exception raised during the invocation, or `None` on success. + """ + prefix = f"{invocation_id}{_ADAPTER_FUNCTION_PHASE_KEY_INFIX}" + for key in [k for k in _in_flight_spans if k.startswith(prefix)]: + entry = _in_flight_spans.pop(key, None) + if entry is None: + continue + phase_span, phase_token, phase_attach_task = entry + try: + if exception is not None: + phase_span.record_exception(exception) + phase_span.set_status( + trace.Status(trace.StatusCode.ERROR, str(exception)) + ) + finally: + _safe_detach(phase_token, phase_attach_task) + phase_span.end() + + entry = _in_flight_spans.pop(invocation_id, None) + if entry is None: + return + span, token, attach_task = entry + try: + set_attribute_safe(span, "mellea.adapter_function.outcome", outcome) + if exception is not None: + span.record_exception(exception) + span.set_status(trace.Status(trace.StatusCode.ERROR, str(exception))) + span.set_attribute("error.type", type(exception).__name__) + finally: + _safe_detach(token, attach_task) + span.end() + + +def start_adapter_function_phase_span( + invocation_id: str, + phase: str, + *, + revision: str | None = None, + attach_context: bool = False, +) -> Span | None: + """Open an `adapter_function.` child span, explicitly parented under the invocation span. + + Parents via `trace.set_span_in_context` on the `adapter_function` span + looked up by `invocation_id`, rather than via ambient context — see + `start_adapter_function_span`'s docstring for why ambient attach can't + establish this edge for hooks fired via `_run_async_in_thread`. Explicit + parenting works the same on every Python version; no `_CONTEXT_ATTACH_SUPPORTED` + gating applies here. A missing parent (invocation not in flight, or + tracing was enabled only after the invocation started) falls back to + whatever's ambient — the phase span still opens; it just can't nest. + + Args: + invocation_id: Correlation key of the enclosing `adapter_function` span. + phase: Lifecycle phase name (e.g. `"prepare"`, `"activate"`). + revision: Catalog revision of the adapter, or `None` if unpinned. Recorded + directly on this phase span — e.g. `adapter_function.prepare` records + the resolved Hugging Face SHA here, not just on the parent. + attach_context: Whether to attach the span as the ambient OTel context. + Left `False` by every current caller — see `start_adapter_function_span`. + + Returns: + The span, or `None` if tracing is disabled. + """ + tracer = get_backend_tracer() + if tracer is None: + return None + + parent_entry = _in_flight_spans.get(invocation_id) + parent_context = ( + trace.set_span_in_context(parent_entry[0]) if parent_entry is not None else None + ) + span = tracer.start_span(f"adapter_function.{phase}", context=parent_context) + set_attribute_safe(span, "mellea.adapter_function.phase", phase) + set_attribute_safe(span, "mellea.adapter_function.revision", revision) + + token = _attach_span_context(span, attach=attach_context) + _in_flight_spans[_adapter_function_phase_key(invocation_id, phase)] = ( + span, + token, + _current_task(), + ) + return span + + +def finish_adapter_function_phase_span(invocation_id: str, phase: str) -> None: + """End an `adapter_function.` child span successfully. + + A no-op if the phase span isn't in flight — e.g. it was already closed + defensively by `finish_adapter_function_span` because the phase raised. + + Args: + invocation_id: Correlation key of the enclosing `adapter_function` span. + phase: Lifecycle phase name. + """ + entry = _in_flight_spans.pop( + _adapter_function_phase_key(invocation_id, phase), None + ) + if entry is None: + return + span, token, attach_task = entry + _safe_detach(token, attach_task) + span.end() + + __all__ = [ "get_application_tracer", "get_backend_tracer", diff --git a/mellea/telemetry/tracing_plugins.py b/mellea/telemetry/tracing_plugins.py index 898f2566d4..b1998c1dba 100644 --- a/mellea/telemetry/tracing_plugins.py +++ b/mellea/telemetry/tracing_plugins.py @@ -17,6 +17,10 @@ - SamplingTracingPlugin: Emits a `sampling` span per sampling loop, with a span event per iteration and repair. - ValidationTracingPlugin: Emits a `validation` span per requirement-check batch. +- AdapterFunctionTracingPlugin: Emits the `adapter_function` span tree (one + parent span per invocation, one `adapter_function.` child per + lifecycle phase) for the adapter-function lifecycle. Covers + prepare/activate/deactivate only as of #1466; generate/parse land with #1465. """ from __future__ import annotations @@ -35,6 +39,12 @@ _CONTEXT_ATTACH_SUPPORTED: bool = sys.version_info >= (3, 12) if TYPE_CHECKING: + from mellea.plugins.hooks.adapter_function import ( + AdapterFunctionInvocationCompletePayload, + AdapterFunctionInvocationStartPayload, + AdapterFunctionPhaseCompletePayload, + AdapterFunctionPhaseStartPayload, + ) from mellea.plugins.hooks.component import ( ComponentPostErrorPayload, ComponentPostSuccessPayload, @@ -634,6 +644,88 @@ async def on_post_check( ) +class AdapterFunctionTracingPlugin( + Plugin, name="adapter_function_tracing", priority=1046 +): + """Emits the `adapter_function` span tree for the adapter-function lifecycle. + + `adapter_function_invocation_start` opens the `adapter_function` parent + span; `adapter_function_invocation_complete` closes it, recording the + outcome and defensively closing any `adapter_function.` child span + left open by a phase that raised (see `finish_adapter_function_span`). + `adapter_function_phase_start`/`adapter_function_phase_complete` open/close + one child span per lifecycle phase, correlated with the parent via + `invocation_id`. + + On the `mellea.backend` tracer (adapter/model lifecycle work, not a + user-facing operation — see `docs/docs/observability/tracing.md`). + + Covers `prepare`/`activate`/`deactivate` only as of #1466. `generate`/ + `parse` fire no hooks yet (blocked on #1465 wiring generation through + `AdapterMixin.adapter_scope`), so this plugin does not yet emit + `adapter_function.generate`/`adapter_function.parse` — it will, once those + hooks fire, with no changes needed here. `release` fires no hooks at all + (see `AdapterFunctionPhaseCompletePayload`'s `phase` field for why) and so + never gets a span either. Content capture (`MELLEA_TRACES_CONTENT`) is not + wired here: no phase in scope carries adapter input/output content — + `generate`/`parse` are where that will apply. + + Unlike every other plugin in this module, these hooks don't rely on + `_CONTEXT_ATTACH_SUPPORTED` ambient-context attach/detach at all — they + fire from sync code (`AdapterMixin.adapter_scope`, `LocalFileBinding.prepare`) + via `_run_async_in_thread`, under which ambient attach can't establish a + parent/child edge (see `start_adapter_function_span`'s docstring). + `start_adapter_function_phase_span` parents each child explicitly instead, + so nesting works identically on every Python version. + """ + + @hook("adapter_function_invocation_start") + async def on_invocation_start( + self, payload: AdapterFunctionInvocationStartPayload, context: dict[str, Any] + ) -> None: + """Open the `adapter_function` parent span for this invocation.""" + from mellea.telemetry.tracing import start_adapter_function_span + + start_adapter_function_span( + payload.invocation_id, + name=payload.name, + revision=payload.revision, + binding_type=payload.binding_type, + adapter_type=payload.adapter_type, + ) + + @hook("adapter_function_invocation_complete") + async def on_invocation_complete( + self, payload: AdapterFunctionInvocationCompletePayload, context: dict[str, Any] + ) -> None: + """Close the `adapter_function` span with its outcome.""" + from mellea.telemetry.tracing import finish_adapter_function_span + + finish_adapter_function_span( + payload.invocation_id, outcome=payload.outcome, exception=payload.error + ) + + @hook("adapter_function_phase_start") + async def on_phase_start( + self, payload: AdapterFunctionPhaseStartPayload, context: dict[str, Any] + ) -> None: + """Open the `adapter_function.` child span.""" + from mellea.telemetry.tracing import start_adapter_function_phase_span + + start_adapter_function_phase_span( + payload.invocation_id, payload.phase, revision=payload.revision + ) + + @hook("adapter_function_phase_complete") + async def on_phase_complete( + self, payload: AdapterFunctionPhaseCompletePayload, context: dict[str, Any] + ) -> None: + """Close the `adapter_function.` child span.""" + from mellea.telemetry.tracing import finish_adapter_function_phase_span + + finish_adapter_function_phase_span(payload.invocation_id, payload.phase) + + # All tracing plugins to auto-register when tracing is enabled. _TRACING_PLUGIN_CLASSES = ( BackendTracingPlugin, @@ -642,4 +734,5 @@ async def on_post_check( ToolTracingPlugin, SamplingTracingPlugin, ValidationTracingPlugin, + AdapterFunctionTracingPlugin, ) diff --git a/test/telemetry/test_tracing_adapter_function.py b/test/telemetry/test_tracing_adapter_function.py new file mode 100644 index 0000000000..89cd7e96bf --- /dev/null +++ b/test/telemetry/test_tracing_adapter_function.py @@ -0,0 +1,543 @@ +# Copyright IBM Corp. All Rights Reserved. +# SPDX-License-Identifier: Apache-2.0 + +"""Tests for adapter-function tracing — the `adapter_function` span tree (#1466). + +Covers prepare/activate/deactivate only, matching #1466's scope; generate/parse +have no firing hooks yet (blocked on #1465). + +Three layers, mirroring `test_tracing_application.py`: + +1. Helper-level unit tests (mock tracer): pin attribute shapes and key + derivation in `tracing.py`'s `start_adapter_function_span`/ + `finish_adapter_function_span`/`start_adapter_function_phase_span`/ + `finish_adapter_function_phase_span`. +2. Plugin unit tests (mock tracer): `AdapterFunctionTracingPlugin`'s hooks + translate payload fields into span opens/closes. +3. Integration tests (real OTel SDK, in-memory exporter, real + `AdapterMixin.adapter_scope`/`LocalFileBinding.prepare` call sites): verify + the full `adapter_function` > `adapter_function.` nesting, the + dangling-child-span cleanup on a raised phase, and that the in-flight span + registry drains to zero. +""" + +from types import SimpleNamespace +from unittest.mock import MagicMock, patch + +import pytest + +pytest.importorskip( + "opentelemetry", reason="opentelemetry not installed — install mellea[telemetry]" +) +pytest.importorskip("cpex", reason="cpex not installed — install mellea[hooks]") + +from opentelemetry.sdk.trace.export import SimpleSpanProcessor +from opentelemetry.sdk.trace.export.in_memory_span_exporter import InMemorySpanExporter + +from mellea.backends.adapters._core import ( + Adapter, + Identity, + IOContract, + LocalFileBinding, +) +from mellea.backends.adapters.adapter import AdapterMixin +from mellea.core import Component +from mellea.telemetry import tracing +from mellea.telemetry.tracing import ( + finish_adapter_function_phase_span, + finish_adapter_function_span, + start_adapter_function_phase_span, + start_adapter_function_span, +) +from mellea.telemetry.tracing_plugins import AdapterFunctionTracingPlugin +from test.telemetry.conftest import reset_tracing_state + +# --------------------------------------------------------------------------- +# Fixtures +# --------------------------------------------------------------------------- + + +@pytest.fixture +def enabled_tracing(monkeypatch): + monkeypatch.setenv("MELLEA_TRACES_ENABLED", "true") + reset_tracing_state() + yield + reset_tracing_state() + + +@pytest.fixture +def disabled_tracing(monkeypatch): + monkeypatch.delenv("MELLEA_TRACES_ENABLED", raising=False) + reset_tracing_state() + yield + reset_tracing_state() + + +@pytest.fixture +def span_exporter(enabled_tracing): + """Attach an in-memory span exporter to the active tracer provider.""" + if tracing._tracer_provider is None: + pytest.skip("Telemetry not initialized") + exporter = InMemorySpanExporter() + tracing._tracer_provider.add_span_processor(SimpleSpanProcessor(exporter)) + yield exporter + exporter.clear() + + +@pytest.fixture +def adapter_function_plugin(): + return AdapterFunctionTracingPlugin() + + +def _patch_backend_tracer() -> tuple[MagicMock, MagicMock]: + fake_span = MagicMock() + fake_tracer = MagicMock() + fake_tracer.start_span.return_value = fake_span + return fake_span, fake_tracer + + +def _attrs(span: MagicMock) -> dict: + return {c.args[0]: c.args[1] for c in span.set_attribute.call_args_list} + + +def _spans_by_name(exporter: InMemorySpanExporter) -> dict: + tracing._tracer_provider.force_flush() # type: ignore[union-attr] + return {s.name: s for s in exporter.get_finished_spans()} + + +# --------------------------------------------------------------------------- +# Helper-level unit tests (mock tracer) +# --------------------------------------------------------------------------- + + +def test_start_adapter_function_span_stamps_attrs_and_stashes_by_invocation_id( + enabled_tracing, +): + fake_span, fake_tracer = _patch_backend_tracer() + with patch("mellea.telemetry.tracing.get_backend_tracer", return_value=fake_tracer): + start_adapter_function_span( + "inv-1", + name="answerability", + revision="abc123", + binding_type="local_file", + adapter_type="lora", + ) + + fake_tracer.start_span.assert_called_once_with("adapter_function") + assert "inv-1" in tracing._in_flight_spans + attrs = _attrs(fake_span) + assert attrs["mellea.adapter_function.name"] == "answerability" + assert attrs["mellea.adapter_function.revision"] == "abc123" + assert attrs["mellea.adapter_function.binding_type"] == "local_file" + assert attrs["mellea.adapter_function.adapter_type"] == "lora" + + +def test_start_adapter_function_span_omits_none_revision(enabled_tracing): + fake_span, fake_tracer = _patch_backend_tracer() + with patch("mellea.telemetry.tracing.get_backend_tracer", return_value=fake_tracer): + start_adapter_function_span( + "inv-unpinned", + name="answerability", + revision=None, + binding_type="local_file", + adapter_type="lora", + ) + + assert "mellea.adapter_function.revision" not in _attrs(fake_span) + + +def test_finish_adapter_function_span_success_records_outcome(enabled_tracing): + fake_span, fake_tracer = _patch_backend_tracer() + with patch("mellea.telemetry.tracing.get_backend_tracer", return_value=fake_tracer): + start_adapter_function_span( + "inv-2", + name="answerability", + revision="r1", + binding_type="local_file", + adapter_type="lora", + ) + finish_adapter_function_span("inv-2", outcome="success", exception=None) + + fake_span.end.assert_called_once() + assert _attrs(fake_span)["mellea.adapter_function.outcome"] == "success" + fake_span.record_exception.assert_not_called() + assert "inv-2" not in tracing._in_flight_spans + + +def test_finish_adapter_function_span_error_records_exception(enabled_tracing): + fake_span, fake_tracer = _patch_backend_tracer() + err = RuntimeError("boom") + with patch("mellea.telemetry.tracing.get_backend_tracer", return_value=fake_tracer): + start_adapter_function_span( + "inv-err", + name="answerability", + revision="r1", + binding_type="local_file", + adapter_type="lora", + ) + finish_adapter_function_span("inv-err", outcome="error", exception=err) + + fake_span.record_exception.assert_called_once_with(err) + fake_span.set_status.assert_called_once() + attrs = _attrs(fake_span) + assert attrs["mellea.adapter_function.outcome"] == "error" + assert attrs["error.type"] == "RuntimeError" + + +def test_finish_adapter_function_span_no_op_when_not_in_flight(enabled_tracing): + finish_adapter_function_span("never-opened", outcome="success", exception=None) + assert "never-opened" not in tracing._in_flight_spans + + +def test_start_adapter_function_phase_span_stamps_phase_and_revision(enabled_tracing): + fake_span, fake_tracer = _patch_backend_tracer() + with patch("mellea.telemetry.tracing.get_backend_tracer", return_value=fake_tracer): + start_adapter_function_phase_span("inv-3", "prepare", revision="sha123") + + # No invocation "inv-3" in flight, so no explicit parent context is passed. + fake_tracer.start_span.assert_called_once_with( + "adapter_function.prepare", context=None + ) + attrs = _attrs(fake_span) + assert attrs["mellea.adapter_function.phase"] == "prepare" + assert attrs["mellea.adapter_function.revision"] == "sha123" + # Keyed distinctly from the parent's own `_in_flight_spans` entry. + assert "inv-3" not in tracing._in_flight_spans + assert "inv-3:phase:prepare" in tracing._in_flight_spans + + +def test_phase_span_key_does_not_collide_with_parent_or_other_phases(enabled_tracing): + fake_tracer = MagicMock() + fake_tracer.start_span.side_effect = lambda name, context=None: MagicMock(name=name) + with patch("mellea.telemetry.tracing.get_backend_tracer", return_value=fake_tracer): + start_adapter_function_span( + "inv-4", + name="answerability", + revision=None, + binding_type="local_file", + adapter_type="lora", + ) + start_adapter_function_phase_span("inv-4", "activate") + start_adapter_function_phase_span("inv-4", "deactivate") + + assert set(tracing._in_flight_spans) == { + "inv-4", + "inv-4:phase:activate", + "inv-4:phase:deactivate", + } + + +def test_finish_adapter_function_phase_span_closes_and_removes(enabled_tracing): + fake_span, fake_tracer = _patch_backend_tracer() + with patch("mellea.telemetry.tracing.get_backend_tracer", return_value=fake_tracer): + start_adapter_function_phase_span("inv-5", "prepare") + finish_adapter_function_phase_span("inv-5", "prepare") + + fake_span.end.assert_called_once() + assert "inv-5:phase:prepare" not in tracing._in_flight_spans + + +def test_finish_adapter_function_phase_span_no_op_when_not_in_flight(enabled_tracing): + # Contract: a phase never opened (or already closed) is a silent no-op — + # this is what lets finish_adapter_function_span's defensive cleanup run + # unconditionally without double-closing a phase that completed normally. + finish_adapter_function_phase_span("inv-6", "prepare") + + +def test_finish_adapter_function_span_closes_dangling_phase_span(enabled_tracing): + """A phase that raised (start fired, complete never did) is closed by the invocation's own finish.""" + fake_tracer = MagicMock() + fake_parent_span = MagicMock() + fake_phase_span = MagicMock() + fake_tracer.start_span.side_effect = [fake_parent_span, fake_phase_span] + err = RuntimeError("activation failed") + + with patch("mellea.telemetry.tracing.get_backend_tracer", return_value=fake_tracer): + start_adapter_function_span( + "inv-7", + name="answerability", + revision="r1", + binding_type="local_file", + adapter_type="lora", + ) + start_adapter_function_phase_span("inv-7", "activate") + # No matching finish_adapter_function_phase_span("inv-7", "activate") — + # the phase itself raised. + finish_adapter_function_span("inv-7", outcome="error", exception=err) + + fake_phase_span.record_exception.assert_called_once_with(err) + fake_phase_span.set_status.assert_called_once() + fake_phase_span.end.assert_called_once() + fake_parent_span.end.assert_called_once() + assert "inv-7" not in tracing._in_flight_spans + assert "inv-7:phase:activate" not in tracing._in_flight_spans + + +def test_helpers_are_silent_when_tracing_disabled(disabled_tracing): + assert ( + start_adapter_function_span( + "inv-d", + name="x", + revision=None, + binding_type="local_file", + adapter_type="lora", + ) + is None + ) + assert start_adapter_function_phase_span("inv-d", "prepare") is None + finish_adapter_function_span("inv-d", outcome="success", exception=None) + finish_adapter_function_phase_span("inv-d", "prepare") + assert tracing._in_flight_spans == {} + + +# --------------------------------------------------------------------------- +# Plugin unit tests (mock tracer) +# --------------------------------------------------------------------------- + + +@pytest.mark.asyncio +async def test_plugin_invocation_start_opens_parent_span( + adapter_function_plugin, enabled_tracing +): + from mellea.plugins.hooks.adapter_function import ( + AdapterFunctionInvocationStartPayload, + ) + + _fake_span, fake_tracer = _patch_backend_tracer() + payload = AdapterFunctionInvocationStartPayload( + invocation_id="p-inv-1", + name="answerability", + revision="r1", + binding_type="local_file", + adapter_type="lora", + ) + with patch("mellea.telemetry.tracing.get_backend_tracer", return_value=fake_tracer): + await adapter_function_plugin.on_invocation_start(payload, {}) + + fake_tracer.start_span.assert_called_once_with("adapter_function") + assert "p-inv-1" in tracing._in_flight_spans + + +@pytest.mark.asyncio +async def test_plugin_invocation_complete_closes_parent_span( + adapter_function_plugin, enabled_tracing +): + from mellea.plugins.hooks.adapter_function import ( + AdapterFunctionInvocationCompletePayload, + AdapterFunctionInvocationStartPayload, + ) + + fake_span, fake_tracer = _patch_backend_tracer() + start_payload = AdapterFunctionInvocationStartPayload( + invocation_id="p-inv-2", + name="answerability", + revision="r1", + binding_type="local_file", + adapter_type="lora", + ) + complete_payload = AdapterFunctionInvocationCompletePayload( + invocation_id="p-inv-2", + name="answerability", + revision="r1", + binding_type="local_file", + adapter_type="lora", + outcome="success", + ) + with patch("mellea.telemetry.tracing.get_backend_tracer", return_value=fake_tracer): + await adapter_function_plugin.on_invocation_start(start_payload, {}) + await adapter_function_plugin.on_invocation_complete(complete_payload, {}) + + fake_span.end.assert_called_once() + assert "p-inv-2" not in tracing._in_flight_spans + + +@pytest.mark.asyncio +async def test_plugin_phase_start_and_complete_open_and_close_child_span( + adapter_function_plugin, enabled_tracing +): + from mellea.plugins.hooks.adapter_function import ( + AdapterFunctionPhaseCompletePayload, + AdapterFunctionPhaseStartPayload, + ) + + fake_span, fake_tracer = _patch_backend_tracer() + start_payload = AdapterFunctionPhaseStartPayload( + invocation_id="p-inv-3", name="answerability", phase="prepare", revision="sha1" + ) + complete_payload = AdapterFunctionPhaseCompletePayload( + invocation_id="p-inv-3", name="answerability", phase="prepare", duration_ms=5.0 + ) + with patch("mellea.telemetry.tracing.get_backend_tracer", return_value=fake_tracer): + await adapter_function_plugin.on_phase_start(start_payload, {}) + await adapter_function_plugin.on_phase_complete(complete_payload, {}) + + # No invocation "p-inv-3" in flight, so no explicit parent context is passed. + fake_tracer.start_span.assert_called_once_with( + "adapter_function.prepare", context=None + ) + fake_span.end.assert_called_once() + assert "p-inv-3:phase:prepare" not in tracing._in_flight_spans + + +# --------------------------------------------------------------------------- +# Integration: real call sites + real OTel SDK + real adapter lifecycle +# --------------------------------------------------------------------------- + + +class _Contract(IOContract): + def build_prompt(self, **kwargs: object) -> Component: + raise NotImplementedError + + def parse(self, raw: str) -> dict[str, object]: + return {} + + +def _make_scope_adapter(): + weights = MagicMock(spec=LocalFileBinding) + weights.binding_type = "local_file" + weights.revision = "abc123" + weights.resolved_revision.return_value = "abc123" + identity = Identity(name="answerability", adapter_type="lora") + return Adapter(identity=identity, io_contract=_Contract(), weights=weights) + + +@pytest.mark.integration +def test_activate_deactivate_emits_nested_span_tree(span_exporter): + """`adapter_scope` emits `adapter_function` > `adapter_function.{activate,deactivate}`. + + Nesting here is via explicit `trace.set_span_in_context` parenting (see + `start_adapter_function_phase_span`), not ambient-context attach, so unlike + every other span family in this codebase it holds on Python 3.11 too — no + `_CONTEXT_ATTACH_SUPPORTED` gating needed. + """ + adapter = _make_scope_adapter() + mock_backend = MagicMock(spec=AdapterMixin) + + with AdapterMixin.adapter_scope(mock_backend, adapter): + pass + + by_name = _spans_by_name(span_exporter) + assert "adapter_function" in by_name + assert "adapter_function.activate" in by_name + assert "adapter_function.deactivate" in by_name + + parent = by_name["adapter_function"] + activate_span = by_name["adapter_function.activate"] + deactivate_span = by_name["adapter_function.deactivate"] + + assert parent.parent is None + assert parent.attributes is not None + assert parent.attributes.get("mellea.adapter_function.name") == "answerability" + assert parent.attributes.get("mellea.adapter_function.outcome") == "success" + + assert activate_span.parent is not None + assert activate_span.parent.span_id == parent.context.span_id + assert deactivate_span.parent is not None + assert deactivate_span.parent.span_id == parent.context.span_id + + assert tracing._in_flight_spans == {} + + +@pytest.mark.integration +def test_activate_raising_still_drains_registry_and_marks_error(span_exporter): + """A phase that raises still gets its span closed via the invocation's own finish.""" + adapter = _make_scope_adapter() + mock_backend = MagicMock(spec=AdapterMixin) + adapter.weights.activate.side_effect = RuntimeError("activation failed") # type: ignore[union-attr] + + with pytest.raises(RuntimeError, match="activation failed"): + with AdapterMixin.adapter_scope(mock_backend, adapter): + pytest.fail("body must not run when activate() raises") + + by_name = _spans_by_name(span_exporter) + assert "adapter_function" in by_name + assert "adapter_function.activate" in by_name + # activate() raised before deactivate ever ran. + assert "adapter_function.deactivate" not in by_name + + from opentelemetry.trace import StatusCode + + assert by_name["adapter_function"].status.status_code == StatusCode.ERROR + assert by_name["adapter_function.activate"].status.status_code == StatusCode.ERROR + + # The registry drains to zero even though the phase never fired its own + # completion hook — finish_adapter_function_span's defensive cleanup closed it. + assert tracing._in_flight_spans == {} + + +@pytest.mark.integration +def test_prepare_emits_its_own_invocation_and_records_resolved_revision(span_exporter): + """`LocalFileBinding.prepare()` opens its own `adapter_function` invocation. + + `adapter_function.prepare` records the resolved catalogue revision, not the + unresolved `None` a lazily-pinned binding starts with — regression coverage + for the moved-from-#1141 acceptance criterion ("not 'main'"). + """ + backend = MagicMock() + backend.add_adapter.side_effect = lambda binding: setattr( + binding, "backend", backend + ) + binding = LocalFileBinding(name="answerability") # revision=None, lazily resolved + binding.bind_backend(backend) + assert binding.revision is None + + binding.prepare() + + by_name = _spans_by_name(span_exporter) + assert "adapter_function" in by_name + assert "adapter_function.prepare" in by_name + + parent = by_name["adapter_function"] + prepare_span = by_name["adapter_function.prepare"] + + resolved = binding.resolved_revision() + assert resolved != "main" + assert parent.attributes is not None + assert parent.attributes.get("mellea.adapter_function.revision") == resolved + assert prepare_span.attributes is not None + assert prepare_span.attributes.get("mellea.adapter_function.revision") == resolved + assert prepare_span.attributes.get("mellea.adapter_function.phase") == "prepare" + + assert prepare_span.parent is not None + assert prepare_span.parent.span_id == parent.context.span_id + + assert tracing._in_flight_spans == {} + + +@pytest.mark.integration +def test_prepare_and_activate_open_independent_invocations(span_exporter): + """`prepare()` and the later `adapter_scope()` call are separate invocations, not nested. + + `prepare()` typically runs once at setup, well before any `adapter_scope` + call — they don't share a parent `adapter_function` span in this + architecture; each gets its own. + """ + backend = MagicMock() + backend.add_adapter.side_effect = lambda binding: setattr( + binding, "backend", backend + ) + binding = LocalFileBinding(name="answerability") + binding.bind_backend(backend) + binding.prepare() + + from mellea.backends.adapters._core import ( + Adapter as _AdapterCore, + Identity as _Identity, + ) + + adapter = _AdapterCore( + identity=_Identity(name="answerability", adapter_type="lora"), + io_contract=_Contract(), + weights=binding, + ) + mock_backend = MagicMock(spec=AdapterMixin) + with AdapterMixin.adapter_scope(mock_backend, adapter): + pass + + tracing._tracer_provider.force_flush() # type: ignore[union-attr] + parents = [ + s for s in span_exporter.get_finished_spans() if s.name == "adapter_function" + ] + assert len(parents) == 2 + assert parents[0].context.span_id != parents[1].context.span_id + assert tracing._in_flight_spans == {} From 2640c351c448653bbe30fe49a40ea58d63c78b1e Mon Sep 17 00:00:00 2001 From: Nigel Jones Date: Tue, 18 Aug 2026 13:11:00 +0100 Subject: [PATCH 03/12] docs(telemetry): document that adapter_function spans have no exemplar linkage MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Progresses #1466. AdapterFunctionTracingPlugin and the pre-existing AdapterFunctionMetricsPlugin are two separate plugins subscribed to the same hooks, so exemplar linkage (SKILL.md §3) isn't structurally guaranteed by "one plugin owns both". Checked and found genuinely unreachable here regardless of firing order: no span in this family is ever attached as ambient OTel context (a deliberate choice, since ambient attach can't establish anything across separate _run_async_in_thread-dispatched hook calls -- see the previous commit), so there is nothing for the metrics plugin to sample as an exemplar even if it ran while the span were still open. Documents this as a known, explained gap rather than leaving it to be found later. Assisted-by: Claude Code Signed-off-by: Nigel Jones --- docs/docs/observability/tracing.md | 8 ++++++++ mellea/telemetry/tracing_plugins.py | 12 ++++++++++++ 2 files changed, 20 insertions(+) diff --git a/docs/docs/observability/tracing.md b/docs/docs/observability/tracing.md index 0db8db4ed5..b002222fce 100644 --- a/docs/docs/observability/tracing.md +++ b/docs/docs/observability/tracing.md @@ -298,6 +298,14 @@ hook call gets an independent `contextvars` snapshot of the calling thread). So `adapter_function.` nests under `adapter_function` the same way on Python 3.11 and 3.12+. +**Known gap: no exemplar linkage to `mellea.adapter_function.phase_duration`.** +Because no span in this family is attached as ambient context (see above), the +`AdapterFunctionMetricsPlugin` histogram sample (a separate plugin subscribed +to the same hooks) has no ambiently-current span to sample as an exemplar, +regardless of the two plugins' firing order. Fixing this would mean recording +the metric from inside `AdapterFunctionTracingPlugin` itself, so it can pass +the span's context explicitly — a larger change left for a follow-up. + ### Span hierarchy Backend spans nest inside application spans: diff --git a/mellea/telemetry/tracing_plugins.py b/mellea/telemetry/tracing_plugins.py index b1998c1dba..1eac561f5f 100644 --- a/mellea/telemetry/tracing_plugins.py +++ b/mellea/telemetry/tracing_plugins.py @@ -677,6 +677,18 @@ class AdapterFunctionTracingPlugin( parent/child edge (see `start_adapter_function_span`'s docstring). `start_adapter_function_phase_span` parents each child explicitly instead, so nesting works identically on every Python version. + + Exemplar linkage (SKILL.md §3) is **not** established for these spans, and + can't be with the current architecture: an OTel histogram exemplar samples + whatever span is *ambiently* current at the moment the metric is recorded, + but no span in this family is ever attached as ambient context (see above) + — there is nothing for `AdapterFunctionMetricsPlugin` + (`mellea/telemetry/metrics_plugins.py`, a separate plugin subscribed to the + same hooks) to sample regardless of firing order between the two plugins. + This is a known, structural gap, not an oversight: fixing it would need the + metric recorded from inside this plugin (so it can pass the span's context + explicitly) rather than from a same-hook sibling plugin, which is a larger + change than adding spans and is left for a follow-up. """ @hook("adapter_function_invocation_start") From 48f40f57afeeaef4e82f14c7ff841ea590cf68a3 Mon Sep 17 00:00:00 2001 From: Nigel Jones Date: Tue, 18 Aug 2026 15:21:55 +0100 Subject: [PATCH 04/12] fix(telemetry): correct adapter-function hook ordering and payload guarding Progresses #1466. Fixes two real bugs found by independent review of the previous two commits, both confirmed by reproducing them against the pre-fix code and observing the failure: - LocalFileBinding.prepare() fired adapter_function_invocation_complete before adapter_function_phase_complete on the success path (the phase hook fired outside the with-block, after the invocation hook's finally). This silently made finish_adapter_function_span's defensive dangling-child-span cleanup -- documented as the failure-only path -- the only path that ever closed adapter_function.prepare's span, and inverted the order AdapterMixin.adapter_scope uses for the same pair. Fixed by firing phase-complete from an else: clause, before the finally. - adapter.py's _fire_phase_start_hook built its payload outside its own try, so a non-str .revision on a duck-typed (non-LocalFileBinding) WeightsBinding raised a pydantic ValidationError that escaped adapter_scope entirely, aborting before activate() ever ran -- exactly the failure the function's docstring says it prevents. _core.py's sibling _fire_phase_start already guarded this correctly; adapter.py's now matches it. Also fixes AdapterMixin.adapter_scope's docstring, which still claimed the ADAPTER_FUNCTION_* family "currently has no start hook" -- the exact gap the previous two commits closed -- and pointed at the deleted docs/dev/adapter_observability.md. Adds regression tests for both bugs, each verified against the pre-fix code (temporarily reverted, confirmed failing, restored) per the project's regression-guard verification standard, plus the two error-path tests review flagged as untested: a failing prepare() asserting both spans close ERROR and the registry drains, and a failing adapter_function_invocation_start hook dispatch not blocking activation (mirroring the existing invocation-complete coverage). Also, cleanup from the same review pass: - Drop the attach_context parameter from start_adapter_function_span/ start_adapter_function_phase_span -- no caller ever passed it, and passing True would misbehave (mismatched attach/detach tasks), so it was configurability that could not be used correctly. - Iterate list(_in_flight_spans) rather than the live dict in finish_adapter_function_span's dangling-child sweep, so a concurrent insert from another invocation's sync-dispatched hook can't raise "dictionary changed size during iteration". - Record error.type on a dangling phase child span too, matching the parent invocation span's existing convention. - Reword the "Nesting is unconditional"/exemplar-gap doc and docstring passages for precision (an enclosing application span can still be ambiently current; it's just not the adapter_function span the metric is about). - Fix a stale test comment, a redundant re-import in a test, and a doc cross-reference to a note that had moved sections. Assisted-by: Claude Code Signed-off-by: Nigel Jones --- docs/docs/observability/tracing.md | 13 ++-- mellea/backends/adapters/_core.py | 13 +++- mellea/backends/adapters/adapter.py | 27 +++---- mellea/telemetry/tracing.py | 78 ++++++++----------- mellea/telemetry/tracing_plugins.py | 22 +++--- .../test_adapters/test_adapter_scope.py | 70 +++++++++++++++++ .../test_adapters/test_local_file_binding.py | 51 +++++++++++- .../test_tracing_adapter_function.py | 40 ++++++++-- 8 files changed, 230 insertions(+), 84 deletions(-) diff --git a/docs/docs/observability/tracing.md b/docs/docs/observability/tracing.md index b002222fce..28cc7b5a3c 100644 --- a/docs/docs/observability/tracing.md +++ b/docs/docs/observability/tracing.md @@ -289,7 +289,7 @@ instead, so the in-flight span registry still drains to zero. **Nesting is unconditional, unlike every other span pair in this document.** Every other family nests via ambient OTel context attach, which needs -Python 3.12+ (see the note at the end of this section) — `adapter_function` +Python 3.12+ (see the note under "Span hierarchy" below) — `adapter_function` children instead parent explicitly via `trace.set_span_in_context`, because `ADAPTER_FUNCTION_*_START`/`_COMPLETE` fire from **synchronous** code (`adapter_scope`, `prepare()`) through `_run_async_in_thread`, under which @@ -301,10 +301,13 @@ Python 3.11 and 3.12+. **Known gap: no exemplar linkage to `mellea.adapter_function.phase_duration`.** Because no span in this family is attached as ambient context (see above), the `AdapterFunctionMetricsPlugin` histogram sample (a separate plugin subscribed -to the same hooks) has no ambiently-current span to sample as an exemplar, -regardless of the two plugins' firing order. Fixing this would mean recording -the metric from inside `AdapterFunctionTracingPlugin` itself, so it can pass -the span's context explicitly — a larger change left for a follow-up. +to the same hooks) never has the `adapter_function`/`adapter_function.` +span ambiently current when it records — at best it would sample whatever +*enclosing application span* happens to be ambient (e.g. `action`), not the +adapter-function span the metric is actually about — regardless of the two +plugins' firing order. Fixing this would mean recording the metric from inside +`AdapterFunctionTracingPlugin` itself, so it can pass the span's context +explicitly — a larger change left for a follow-up. ### Span hierarchy diff --git a/mellea/backends/adapters/_core.py b/mellea/backends/adapters/_core.py index 4803121fa8..41f4adc8d6 100644 --- a/mellea/backends/adapters/_core.py +++ b/mellea/backends/adapters/_core.py @@ -479,11 +479,18 @@ def prepare(self) -> None: except BaseException as exc: error = exc raise + else: + # Fires before `_fire_invocation_complete` below so hook order + # matches `AdapterMixin.adapter_scope`'s (phase-complete, then + # invocation-complete) — firing this after the `with` block + # instead put it after invocation-complete, which made the + # dangling-child cleanup in `finish_adapter_function_span` the + # only path that ever closed `adapter_function.prepare`'s span. + self._fire_phase_complete( + "prepare", time.monotonic() - started_at, invocation_id + ) finally: self._fire_invocation_complete(invocation_id, revision, error) - self._fire_phase_complete( - "prepare", time.monotonic() - started_at, invocation_id - ) def activate(self) -> None: """Selects already-loaded adapter weights for generation. diff --git a/mellea/backends/adapters/adapter.py b/mellea/backends/adapters/adapter.py index ad5bbeb2c3..a0020fb4cd 100644 --- a/mellea/backends/adapters/adapter.py +++ b/mellea/backends/adapters/adapter.py @@ -347,7 +347,7 @@ def _fire_phase_start_hook( Args: invocation_id: Correlation id of the enclosing invocation. - name: Adapter function name, used as the metric's `name` field. + name: Adapter function name, recorded as a span attribute. phase: Lifecycle phase name; must be a valid `AdapterFunctionPhaseStartPayload.phase` value. revision: Catalog revision of the adapter, or `None` if unpinned. @@ -356,10 +356,10 @@ def _fire_phase_start_hook( return from ...plugins.hooks.adapter_function import AdapterFunctionPhaseStartPayload - payload = AdapterFunctionPhaseStartPayload( - invocation_id=invocation_id, name=name, phase=phase, revision=revision - ) try: + payload = AdapterFunctionPhaseStartPayload( + invocation_id=invocation_id, name=name, phase=phase, revision=revision + ) hook_coro = invoke_hook(HookType.ADAPTER_FUNCTION_PHASE_START, payload) _run_async_in_thread(hook_coro) except Exception: @@ -815,15 +815,16 @@ def adapter_scope(self, adapter: "_AdapterCore | None"): # type: ignore[type-ar A no-op when `adapter` is `None`. Otherwise: activates `adapter.weights`, yields, then always deactivates — even if the `with` - body raises. Each phase fires `ADAPTER_FUNCTION_PHASE_COMPLETE`, and - `ADAPTER_FUNCTION_INVOCATION_COMPLETE` fires on the way out, carrying the - overall outcome. - - This method fires hooks only; it does not open spans. Span production is a - plugin's job (see #1464 for the rule and #1466 for the adapter-function - spans), and the `ADAPTER_FUNCTION_*` family currently has no start hook for - a plugin to open a span on. See `docs/dev/adapter_observability.md` for the - metric schema. + body raises. Fires `ADAPTER_FUNCTION_INVOCATION_START` on the way in; + each phase fires `ADAPTER_FUNCTION_PHASE_START` then + `ADAPTER_FUNCTION_PHASE_COMPLETE`; `ADAPTER_FUNCTION_INVOCATION_COMPLETE` + fires on the way out, carrying the overall outcome. + + This method fires hooks only; it does not open spans itself. Span + production is a plugin's job (see #1464 for the rule) — + `AdapterFunctionTracingPlugin` (`mellea/telemetry/tracing_plugins.py`) + turns these hooks into the `adapter_function` span tree. See + `docs/docs/observability/tracing.md` for the span schema. `deactivate()` is guarded on `activate()`'s own side effect having completed, not on the activate phase's hook dispatch also succeeding. diff --git a/mellea/telemetry/tracing.py b/mellea/telemetry/tracing.py index ebfc9b3202..1242324154 100644 --- a/mellea/telemetry/tracing.py +++ b/mellea/telemetry/tracing.py @@ -1104,7 +1104,6 @@ def start_adapter_function_span( revision: str | None, binding_type: str, adapter_type: str, - attach_context: bool = False, ) -> Span | None: """Open the `adapter_function` parent span for one adapter-function invocation. @@ -1112,9 +1111,10 @@ def start_adapter_function_span( concern, not a user-facing operation (see `docs/docs/observability/tracing.md`). - `attach_context` defaults to `False`, unlike every other `start_*_span` - helper. `ADAPTER_FUNCTION_INVOCATION_START`/`_PHASE_START` fire from sync - code (`AdapterMixin.adapter_scope`, `LocalFileBinding.prepare`) via + Never attached as the ambient OTel context, unlike every other + `start_*_span` helper — deliberately, not as an oversight. + `ADAPTER_FUNCTION_INVOCATION_START`/`_PHASE_START` fire from sync code + (`AdapterMixin.adapter_scope`, `LocalFileBinding.prepare`) via `_run_async_in_thread`, which runs each hook as an independent task on a shared background event loop, seeded from a *fresh* `contextvars.copy_context()` snapshot of the calling thread taken at that call — mutations inside one @@ -1122,10 +1122,12 @@ def start_adapter_function_span( calling thread and so are invisible to the *next* `_run_async_in_thread` call's snapshot. Ambient attach/detach across two such calls therefore can't establish a parent/child edge (and mismatched attach/detach tasks - trigger "Detaching an OTel context token across asyncio tasks" warnings) - — `start_adapter_function_phase_span` instead parents explicitly via - `trace.set_span_in_context` using the span object looked up by - `invocation_id`, which needs no ambient context at all. + would trigger "Detaching an OTel context token across asyncio tasks" + warnings) — `start_adapter_function_phase_span` instead parents explicitly + via `trace.set_span_in_context` using the span object looked up by + `invocation_id`, which needs no ambient context at all. Exposing an + `attach_context` parameter here (as the sibling helpers do) would only + offer a setting that breaks whenever used, so there isn't one. Args: invocation_id: Correlation key for the matching `finish_adapter_function_span` call. @@ -1134,8 +1136,6 @@ def start_adapter_function_span( binding_type: Weight-binding reality the adapter is running under (e.g. `"local_file"`, `"embedded"`, `"server_mediated"`). adapter_type: Adapter mechanism (e.g. `"lora"`, `"alora"`). - attach_context: Whether to attach the span as the ambient OTel context. - Left `False` by every current caller — see above. Returns: The span, or `None` if tracing is disabled. @@ -1150,8 +1150,7 @@ def start_adapter_function_span( set_attribute_safe(span, "mellea.adapter_function.binding_type", binding_type) set_attribute_safe(span, "mellea.adapter_function.adapter_type", adapter_type) - token = _attach_span_context(span, attach=attach_context) - _in_flight_spans[invocation_id] = (span, token, _current_task()) + _in_flight_spans[invocation_id] = (span, None, _current_task()) return span @@ -1173,43 +1172,38 @@ def finish_adapter_function_span( outcome: `"success"`, `"schema_error"`, or `"error"`. exception: The exception raised during the invocation, or `None` on success. """ + # `list(...)` snapshots the keys in one call before filtering, so a + # concurrent insert from another thread (e.g. a different invocation's + # sync-dispatched hook, on the shared `_run_async_in_thread` background + # loop) can't trigger a "dictionary changed size during iteration" error + # here — the first site in this module to iterate `_in_flight_spans` + # rather than do a keyed lookup. prefix = f"{invocation_id}{_ADAPTER_FUNCTION_PHASE_KEY_INFIX}" - for key in [k for k in _in_flight_spans if k.startswith(prefix)]: + for key in [k for k in list(_in_flight_spans) if k.startswith(prefix)]: entry = _in_flight_spans.pop(key, None) if entry is None: continue - phase_span, phase_token, phase_attach_task = entry - try: - if exception is not None: - phase_span.record_exception(exception) - phase_span.set_status( - trace.Status(trace.StatusCode.ERROR, str(exception)) - ) - finally: - _safe_detach(phase_token, phase_attach_task) - phase_span.end() + phase_span, _phase_token, _phase_attach_task = entry + if exception is not None: + phase_span.record_exception(exception) + phase_span.set_status(trace.Status(trace.StatusCode.ERROR, str(exception))) + phase_span.set_attribute("error.type", type(exception).__name__) + phase_span.end() entry = _in_flight_spans.pop(invocation_id, None) if entry is None: return - span, token, attach_task = entry - try: - set_attribute_safe(span, "mellea.adapter_function.outcome", outcome) - if exception is not None: - span.record_exception(exception) - span.set_status(trace.Status(trace.StatusCode.ERROR, str(exception))) - span.set_attribute("error.type", type(exception).__name__) - finally: - _safe_detach(token, attach_task) - span.end() + span, _token, _attach_task = entry + set_attribute_safe(span, "mellea.adapter_function.outcome", outcome) + if exception is not None: + span.record_exception(exception) + span.set_status(trace.Status(trace.StatusCode.ERROR, str(exception))) + span.set_attribute("error.type", type(exception).__name__) + span.end() def start_adapter_function_phase_span( - invocation_id: str, - phase: str, - *, - revision: str | None = None, - attach_context: bool = False, + invocation_id: str, phase: str, *, revision: str | None = None ) -> Span | None: """Open an `adapter_function.` child span, explicitly parented under the invocation span. @@ -1228,8 +1222,6 @@ def start_adapter_function_phase_span( revision: Catalog revision of the adapter, or `None` if unpinned. Recorded directly on this phase span — e.g. `adapter_function.prepare` records the resolved Hugging Face SHA here, not just on the parent. - attach_context: Whether to attach the span as the ambient OTel context. - Left `False` by every current caller — see `start_adapter_function_span`. Returns: The span, or `None` if tracing is disabled. @@ -1246,10 +1238,9 @@ def start_adapter_function_phase_span( set_attribute_safe(span, "mellea.adapter_function.phase", phase) set_attribute_safe(span, "mellea.adapter_function.revision", revision) - token = _attach_span_context(span, attach=attach_context) _in_flight_spans[_adapter_function_phase_key(invocation_id, phase)] = ( span, - token, + None, _current_task(), ) return span @@ -1270,8 +1261,7 @@ def finish_adapter_function_phase_span(invocation_id: str, phase: str) -> None: ) if entry is None: return - span, token, attach_task = entry - _safe_detach(token, attach_task) + span, _token, _attach_task = entry span.end() diff --git a/mellea/telemetry/tracing_plugins.py b/mellea/telemetry/tracing_plugins.py index 1eac561f5f..1c53e28b27 100644 --- a/mellea/telemetry/tracing_plugins.py +++ b/mellea/telemetry/tracing_plugins.py @@ -678,17 +678,19 @@ class AdapterFunctionTracingPlugin( `start_adapter_function_phase_span` parents each child explicitly instead, so nesting works identically on every Python version. - Exemplar linkage (SKILL.md §3) is **not** established for these spans, and - can't be with the current architecture: an OTel histogram exemplar samples - whatever span is *ambiently* current at the moment the metric is recorded, - but no span in this family is ever attached as ambient context (see above) - — there is nothing for `AdapterFunctionMetricsPlugin` + Exemplar linkage (see `docs/docs/observability/tracing.md`) is **not** + established for these spans, and can't be with the current architecture: + an OTel histogram exemplar samples whatever span is *ambiently* current at + the moment the metric is recorded, but no span in this family is ever + attached as ambient context (see above) — `AdapterFunctionMetricsPlugin` (`mellea/telemetry/metrics_plugins.py`, a separate plugin subscribed to the - same hooks) to sample regardless of firing order between the two plugins. - This is a known, structural gap, not an oversight: fixing it would need the - metric recorded from inside this plugin (so it can pass the span's context - explicitly) rather than from a same-hook sibling plugin, which is a larger - change than adding spans and is left for a follow-up. + same hooks) at best samples whatever enclosing application span happens to + be ambient, never the adapter-function span the metric is actually about, + regardless of firing order between the two plugins. This is a known, + structural gap, not an oversight: fixing it would need the metric recorded + from inside this plugin (so it can pass the span's context explicitly) + rather than from a same-hook sibling plugin, which is a larger change than + adding spans and is left for a follow-up. """ @hook("adapter_function_invocation_start") diff --git a/test/backends/test_adapters/test_adapter_scope.py b/test/backends/test_adapters/test_adapter_scope.py index 4c92856cf6..b2d8b63edd 100644 --- a/test/backends/test_adapters/test_adapter_scope.py +++ b/test/backends/test_adapters/test_adapter_scope.py @@ -20,6 +20,7 @@ Identity, IOContract, LocalFileBinding, + WeightsBinding, ) from mellea.backends.adapters.adapter import AdapterMixin from mellea.backends.adapters.catalog import AdapterType @@ -256,6 +257,75 @@ def test_adapter_scope_reports_resolved_revision_not_raw_none(): assert invocations[0].revision != "main" +class _IntRevisionBinding(WeightsBinding): + """Non-`LocalFileBinding` weights whose `.revision` is not a `str`. + + `adapter_scope` treats `WeightsBinding.revision` as unverified duck-typed + data for any binding that isn't a `LocalFileBinding` — it reads it via a + bare `getattr(...)` with no type check. This double stands in for any + third-party binding that sets a non-`str` revision. + """ + + binding_type = "custom" + revision = 7 + + def prepare(self) -> None: + pass + + def activate(self) -> None: + pass + + def deactivate(self) -> None: + pass + + def release(self) -> None: + pass + + +def test_adapter_scope_swallows_non_str_revision_on_phase_start(): + """A non-`str` `.revision` must not abort activation. + + Regression guard: `_fire_phase_start_hook` used to construct + `AdapterFunctionPhaseStartPayload` outside its own `try`, so a duck-typed + binding with a non-`str` `.revision` raised a pydantic `ValidationError` + that escaped `adapter_scope` entirely, aborting before `activate()` ever + ran — exactly the failure the function's docstring says it prevents. + """ + mock_backend = MagicMock(spec=AdapterMixin) + weights = _IntRevisionBinding() + identity = Identity(name="answerability", adapter_type="lora") + adapter = Adapter(identity=identity, io_contract=_Contract(), weights=weights) + + body_ran = False + with AdapterMixin.adapter_scope(mock_backend, adapter): + body_ran = True + + assert body_ran + + +def test_adapter_scope_swallows_invocation_start_hook_failure(): + """A failing invocation-start hook must not block activation. + + Regression guard: `_fire_invocation_start_hook` is called unguarded inside + `adapter_scope` itself, wrapped in its own try/except at the call site + (unlike `_fire_phase_start_hook`, which guards internally). Pin that the + call-site guard actually works — `_fire_invocation_complete` already has + two dedicated tests for this; `_fire_invocation_start_hook` had none. + """ + mock_backend = MagicMock(spec=AdapterMixin) + adapter, weights = _make_adapter() + + with patch( + "mellea.backends.adapters.adapter._fire_invocation_start_hook", + side_effect=RuntimeError("start hook dispatch blew up"), + ): + with AdapterMixin.adapter_scope(mock_backend, adapter): + pass # must not raise despite the start hook failing on entry + + weights.activate.assert_called_once() + weights.deactivate.assert_called_once() + + def test_adapter_scope_swallows_invocation_hook_failure_on_clean_run(): """A failing invocation-complete hook must not turn a clean run into an error. diff --git a/test/backends/test_adapters/test_local_file_binding.py b/test/backends/test_adapters/test_local_file_binding.py index 669fda94fc..5fb0b9d4d1 100644 --- a/test/backends/test_adapters/test_local_file_binding.py +++ b/test/backends/test_adapters/test_local_file_binding.py @@ -517,8 +517,57 @@ def test_prepare_fires_phase_complete_metric_when_plugins_present(): hook_coro.close() +def test_prepare_fires_hooks_in_start_then_complete_order(): + """Regression guard: phase-complete must fire before invocation-complete. + + Guards against an ordering inversion where `prepare()`'s phase-complete + hook fired *after* invocation-complete, silently making the defensive + dangling-child-span close in `finish_adapter_function_span` the only path + that ever closed `adapter_function.prepare`'s span on a *successful* + prepare() — contradicting `AdapterMixin.adapter_scope`'s own hook order + (phase-complete before invocation-complete for both activate and + deactivate) and this file's own + `test_prepare_fires_phase_complete_metric_when_plugins_present` docstring, + which asserted the correct order in prose without a test able to catch a + reversal. + """ + pytest.importorskip("cpex", reason="cpex not installed — install mellea[hooks]") + from mellea.backends.adapters._core import invoke_hook as _real_invoke_hook + from mellea.plugins.types import HookType + + backend = _fake_backend() + binding = LocalFileBinding(name="answerability") + binding.bind_backend(backend) + + fired_hook_types: list[HookType] = [] + + def _record_and_dispatch(hook_type, payload): + fired_hook_types.append(hook_type) + return _real_invoke_hook(hook_type, payload) + + with ( + patch("mellea.backends.adapters._core.has_plugins", return_value=True), + patch( + "mellea.backends.adapters._core.invoke_hook", + new_callable=MagicMock, + side_effect=_record_and_dispatch, + ), + patch("mellea.backends.adapters._core._run_async_in_thread") as mock_run, + ): + binding.prepare() + + assert fired_hook_types == [ + HookType.ADAPTER_FUNCTION_INVOCATION_START, + HookType.ADAPTER_FUNCTION_PHASE_START, + HookType.ADAPTER_FUNCTION_PHASE_COMPLETE, + HookType.ADAPTER_FUNCTION_INVOCATION_COMPLETE, + ] + for call in mock_run.call_args_list: + call.args[0].close() + + def test_release_does_not_fire_phase_complete_metric(): - # "release" is not a valid AdapterFunctionPhaseCompletePayload.phase value. + # release() fires no hooks at all — it runs outside any invocation. pytest.importorskip("cpex", reason="cpex not installed — install mellea[hooks]") backend = _fake_backend() binding = LocalFileBinding(name="answerability") diff --git a/test/telemetry/test_tracing_adapter_function.py b/test/telemetry/test_tracing_adapter_function.py index 89cd7e96bf..23a1e13821 100644 --- a/test/telemetry/test_tracing_adapter_function.py +++ b/test/telemetry/test_tracing_adapter_function.py @@ -21,7 +21,6 @@ registry drains to zero. """ -from types import SimpleNamespace from unittest.mock import MagicMock, patch import pytest @@ -465,6 +464,36 @@ def test_activate_raising_still_drains_registry_and_marks_error(span_exporter): assert tracing._in_flight_spans == {} +@pytest.mark.integration +def test_prepare_raising_drains_registry_and_marks_error(span_exporter): + """A failing `prepare()` still closes both spans and drains the registry. + + `prepare()`'s own invocation-start/complete pair (unlike `adapter_scope`'s) + has never been exercised at the span level before — only via mocked hook + counts in `test_local_file_binding.py`. This is the direct span-level + counterpart to `test_activate_raising_still_drains_registry_and_marks_error`. + """ + from opentelemetry.trace import StatusCode + + backend = MagicMock() + backend.add_adapter.side_effect = lambda binding: setattr( + binding, "backend", backend + ) + backend.load_peft_adapter.side_effect = RuntimeError("load boom") + binding = LocalFileBinding(name="answerability") + binding.bind_backend(backend) + + with pytest.raises(RuntimeError, match="load boom"): + binding.prepare() + + by_name = _spans_by_name(span_exporter) + assert "adapter_function" in by_name + assert "adapter_function.prepare" in by_name + assert by_name["adapter_function"].status.status_code == StatusCode.ERROR + assert by_name["adapter_function.prepare"].status.status_code == StatusCode.ERROR + assert tracing._in_flight_spans == {} + + @pytest.mark.integration def test_prepare_emits_its_own_invocation_and_records_resolved_revision(span_exporter): """`LocalFileBinding.prepare()` opens its own `adapter_function` invocation. @@ -520,13 +549,8 @@ def test_prepare_and_activate_open_independent_invocations(span_exporter): binding.bind_backend(backend) binding.prepare() - from mellea.backends.adapters._core import ( - Adapter as _AdapterCore, - Identity as _Identity, - ) - - adapter = _AdapterCore( - identity=_Identity(name="answerability", adapter_type="lora"), + adapter = Adapter( + identity=Identity(name="answerability", adapter_type="lora"), io_contract=_Contract(), weights=binding, ) From 94ab6148b7c08849039c25bda969c8bd8b9734df Mon Sep 17 00:00:00 2001 From: Nigel Jones Date: Tue, 18 Aug 2026 16:25:49 +0100 Subject: [PATCH 05/12] docs: record the docstring-quality-gate substring false-positive Per AGENTS.md section 13's own feedback-loop rule. Encountered while fixing a bug found in review of #1466: a code comment containing the literal text "raise " false-triggered tooling/docs-autogen/audit_coverage.py's "missing Raises section" check on a function with no actual raise statement, since that check is a substring match over the whole function source, not an AST check for real raise statements. Assisted-by: Claude Code Signed-off-by: Nigel Jones --- AGENTS.md | 1 + 1 file changed, 1 insertion(+) diff --git a/AGENTS.md b/AGENTS.md index fa606d778f..09c39c3ed3 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -124,6 +124,7 @@ Use the tool's common name (e.g., GitHub Copilot, Cursor, etc.). | Telemetry import errors | Run `uv sync` to install OpenTelemetry deps | | Silent empty strings from async backends | Check for `asyncio.gather(..., return_exceptions=True)` — exceptions become values silently; use `return_exceptions=False` unless callers explicitly handle `BaseException` values | | GitHub Actions workflow injection warning | Never use `${{ expression }}` directly inside `run:` shell commands — always route through `env:` (`env: MY_VAR: ${{ expr }}` then `"$MY_VAR"` in the script). This rule applies only to `run:` steps; `${{ }}` in `if:` conditions and `with:` action inputs is fine. | +| Docstring quality gate false-flags "missing Raises section" with no actual `raise` in the function | `tooling/docs-autogen/audit_coverage.py`'s check is `if "raise " in source` — a substring match over the whole function source, including comments and docstrings, not an AST check for real `raise` statements. A comment containing the literal text `raise ` (e.g. "can't raise X here") triggers it. Reword the comment to avoid the substring; don't add a fake `Raises:` section. | ## 10. Self-Review (before notifying user) 1. `uv run pytest test/ -m "not qualitative"` passes? From d144877bb73260bbe7768134243fe5d986aac96b Mon Sep 17 00:00:00 2001 From: Nigel Jones Date: Wed, 19 Aug 2026 18:34:48 +0100 Subject: [PATCH 06/12] fix(telemetry): fire prepare() adapter hooks outside the lifecycle lock Each adapter_function hook dispatch blocks the calling thread on the shared background event loop (_run_async_in_thread resolves the hook coroutine via run_coroutine_threadsafe(...).result()). Holding the non-reentrant _lifecycle_lock across all four of them let a plugin handler that re-enters this binding's lifecycle from the background loop deadlock: the handler waits on the lock while prepare() waits on the handler. Split prepare() into two short lock windows - the released/loaded check, then the registration/load work - and run the invocation/phase dispatches between them, preserving the pinned invocation_start -> phase_start -> phase_complete -> invocation_complete order. An already-loaded (or released) binding still opens no invocation and fires no hooks, and a release interleaving now surfaces as the backend's 'refused to register' error rather than racing the load. Assisted-by: opencode Signed-off-by: Nigel Jones --- mellea/backends/adapters/_core.py | 65 ++++++++++++++++++------------- 1 file changed, 39 insertions(+), 26 deletions(-) diff --git a/mellea/backends/adapters/_core.py b/mellea/backends/adapters/_core.py index 41f4adc8d6..53ab816b97 100644 --- a/mellea/backends/adapters/_core.py +++ b/mellea/backends/adapters/_core.py @@ -411,6 +411,9 @@ def prepare(self) -> None: parent span, and guarantees the in-flight span registry drains even if `prepare()` raises (the invocation-complete hook always fires, in a `finally`, unlike the phase-complete hook, which only fires on success). + The hook dispatches run outside the `_lifecycle_lock` (see the body + comment for the deadlock rationale); the released/loaded checks and the + registration/load work each run under it. Raises: RuntimeError: `bind_backend()` was not called first, `name` is empty, @@ -428,17 +431,27 @@ def prepare(self) -> None: if self.backend is not None and self._loaded: return - invocation_id = str(uuid.uuid4()) - revision: str | None - try: - revision = self.resolved_revision() - except Exception: - revision = self.revision - self._fire_invocation_start(invocation_id, revision) - self._fire_phase_start(invocation_id, "prepare", revision) - - error: BaseException | None = None - try: + # Every hook dispatch below blocks the caller on the shared background + # event loop (`_run_async_in_thread`), so they run outside + # `_lifecycle_lock` (a non-reentrant `threading.Lock`): a plugin handler + # that re-enters this binding's lifecycle from the background loop would + # otherwise deadlock against the lock this call still holds. The check + # above and the work below each run under the lock, so an already-loaded + # (or released) binding opens no invocation and fires no hooks, and a + # concurrent `release()` interleaving surfaces as the backend's + # "refused to register" error rather than as state corruption. + invocation_id = str(uuid.uuid4()) + revision: str | None + try: + revision = self.resolved_revision() + except Exception: + revision = self.revision + self._fire_invocation_start(invocation_id, revision) + self._fire_phase_start(invocation_id, "prepare", revision) + + error: BaseException | None = None + try: + with self._lifecycle_lock: if self.backend is None: if self._staged_backend is None: raise RuntimeError( @@ -476,21 +489,21 @@ def prepare(self) -> None: with self.backend._adapter_activation_lock(): self.backend.load_peft_adapter(self.qualified_name) self._loaded = True - except BaseException as exc: - error = exc - raise - else: - # Fires before `_fire_invocation_complete` below so hook order - # matches `AdapterMixin.adapter_scope`'s (phase-complete, then - # invocation-complete) — firing this after the `with` block - # instead put it after invocation-complete, which made the - # dangling-child cleanup in `finish_adapter_function_span` the - # only path that ever closed `adapter_function.prepare`'s span. - self._fire_phase_complete( - "prepare", time.monotonic() - started_at, invocation_id - ) - finally: - self._fire_invocation_complete(invocation_id, revision, error) + except BaseException as exc: + error = exc + raise + else: + # Fires before `_fire_invocation_complete` below so hook order + # matches `AdapterMixin.adapter_scope`'s (phase-complete, then + # invocation-complete) — firing this after the `with` block + # instead put it after invocation-complete, which made the + # dangling-child cleanup in `finish_adapter_function_span` the + # only path that ever closed `adapter_function.prepare`'s span. + self._fire_phase_complete( + "prepare", time.monotonic() - started_at, invocation_id + ) + finally: + self._fire_invocation_complete(invocation_id, revision, error) def activate(self) -> None: """Selects already-loaded adapter weights for generation. From a3402733b791bc0332b67f6f3d55b77b9ac19b76 Mon Sep 17 00:00:00 2001 From: Nigel Jones Date: Wed, 19 Aug 2026 18:41:37 +0100 Subject: [PATCH 07/12] fix(telemetry): align adapter-function phase-duration boundaries The three firing sites measured phase_duration on different clocks: activate started its timer before its blocking phase-start dispatch, deactivate after it, and prepare at method entry (covering the lock wait and both start dispatches). Samples from the three phases were therefore not clock-comparable. Take started_at after the phase-start dispatch at every site, so each phase_duration sample covers the phase's own work only. Also move the invocation_id parameter first in LocalFileBinding._fire_phase_complete to match the module-level twins in adapter.py. Assisted-by: opencode Signed-off-by: Nigel Jones --- mellea/backends/adapters/_core.py | 21 ++++++++++++--------- mellea/backends/adapters/adapter.py | 2 +- 2 files changed, 13 insertions(+), 10 deletions(-) diff --git a/mellea/backends/adapters/_core.py b/mellea/backends/adapters/_core.py index 53ab816b97..89874ad0fd 100644 --- a/mellea/backends/adapters/_core.py +++ b/mellea/backends/adapters/_core.py @@ -396,11 +396,14 @@ def prepare(self) -> None: guard. The `prepare` phase duration reported to - `ADAPTER_FUNCTION_PHASE_COMPLETE` spans the whole operation, **including - the Hugging Face download** — `add_adapter` calls `get_local_hf_path`, - which can take seconds on a cache miss. That is deliberate (it is the - wall-clock cost of preparing), but worth stating, since a phase added - later may not want the same boundary. + `ADAPTER_FUNCTION_PHASE_COMPLETE` spans the phase's own work under the + lifecycle lock — backend registration and the weights load, + **including the Hugging Face download** (`add_adapter` calls + `get_local_hf_path`, which can take seconds on a cache miss) — and + excludes hook-dispatch and lock-wait time, matching the + `activate`/`deactivate` boundaries in `AdapterMixin.adapter_scope`. + Worth stating, since a phase added later may not want the same + boundary. Unlike `activate`/`deactivate` (owned by `AdapterMixin.adapter_scope`), `prepare()` runs outside any wrapping invocation, so it opens its own @@ -420,7 +423,6 @@ def prepare(self) -> None: the binding was already `release()`d, or the backend refused the registration. """ - started_at = time.monotonic() with self._lifecycle_lock: if self._released: raise RuntimeError( @@ -452,6 +454,7 @@ def prepare(self) -> None: error: BaseException | None = None try: with self._lifecycle_lock: + started_at = time.monotonic() if self.backend is None: if self._staged_backend is None: raise RuntimeError( @@ -500,7 +503,7 @@ def prepare(self) -> None: # dangling-child cleanup in `finish_adapter_function_span` the # only path that ever closed `adapter_function.prepare`'s span. self._fire_phase_complete( - "prepare", time.monotonic() - started_at, invocation_id + invocation_id, "prepare", time.monotonic() - started_at ) finally: self._fire_invocation_complete(invocation_id, revision, error) @@ -720,7 +723,7 @@ def _fire_phase_start( ) def _fire_phase_complete( - self, phase: str, duration_s: float, invocation_id: str + self, invocation_id: str, phase: str, duration_s: float ) -> None: """Fires `adapter_function_phase_complete` for a phase this binding owns. @@ -732,10 +735,10 @@ def _fire_phase_complete( is otherwise unobserved. Args: + invocation_id: Correlation id of the enclosing (prepare-only) invocation. phase: Lifecycle phase name; must be a valid `AdapterFunctionPhaseCompletePayload.phase` value. duration_s: Wall-clock duration of the phase, in seconds. - invocation_id: Correlation id of the enclosing (prepare-only) invocation. """ if not has_plugins(HookType.ADAPTER_FUNCTION_PHASE_COMPLETE): return diff --git a/mellea/backends/adapters/adapter.py b/mellea/backends/adapters/adapter.py index a0020fb4cd..db048502d2 100644 --- a/mellea/backends/adapters/adapter.py +++ b/mellea/backends/adapters/adapter.py @@ -899,8 +899,8 @@ def adapter_scope(self, adapter: "_AdapterCore | None"): # type: ignore[type-ar activated = False body_exception: BaseException | None = None try: - started_at = time.monotonic() _fire_phase_start_hook(invocation_id, name, "activate", revision) + started_at = time.monotonic() try: adapter.weights.activate() activated = True From 4f9eaaa1d5684cfb0af56048afe5ed108f54b266 Mon Sep 17 00:00:00 2001 From: Nigel Jones Date: Wed, 19 Aug 2026 18:42:36 +0100 Subject: [PATCH 08/12] test(telemetry): pin idempotent-prepare hook silence and no-op registry hygiene An idempotent prepare() (already loaded) must fire zero adapter_function hooks; nothing pinned that - a refactor moving the _loaded check below the hook firings would silently open a duplicate invocation per re-entry. Extend the hook-count test with a second prepare() under capture, and give the phase-span no-op test a registry-untouched assertion so the no-op cannot pass while corrupting _in_flight_spans. Assisted-by: opencode Signed-off-by: Nigel Jones --- test/backends/test_adapters/test_local_file_binding.py | 5 ++++- test/telemetry/test_tracing_adapter_function.py | 3 +++ 2 files changed, 7 insertions(+), 1 deletion(-) diff --git a/test/backends/test_adapters/test_local_file_binding.py b/test/backends/test_adapters/test_local_file_binding.py index 5fb0b9d4d1..46c67f0b66 100644 --- a/test/backends/test_adapters/test_local_file_binding.py +++ b/test/backends/test_adapters/test_local_file_binding.py @@ -497,7 +497,9 @@ def test_prepare_fires_phase_complete_metric_when_plugins_present(): Four hook dispatches total: invocation_start, phase_start, phase_complete, invocation_complete — see `LocalFileBinding.prepare()`'s docstring for why `prepare()` opens its own single-phase invocation rather than relying on one - supplied by a caller. + supplied by a caller. A second, already-loaded `prepare()` adds no + dispatches: idempotent re-entry must not open a second invocation (the + check that gates on `_loaded` runs before any hook fires). """ pytest.importorskip("cpex", reason="cpex not installed — install mellea[hooks]") backend = _fake_backend() @@ -509,6 +511,7 @@ def test_prepare_fires_phase_complete_metric_when_plugins_present(): patch("mellea.backends.adapters._core._run_async_in_thread") as mock_run, ): binding.prepare() + binding.prepare() assert mock_run.call_count == 4 for call in mock_run.call_args_list: diff --git a/test/telemetry/test_tracing_adapter_function.py b/test/telemetry/test_tracing_adapter_function.py index 23a1e13821..d9976029eb 100644 --- a/test/telemetry/test_tracing_adapter_function.py +++ b/test/telemetry/test_tracing_adapter_function.py @@ -242,6 +242,9 @@ def test_finish_adapter_function_phase_span_no_op_when_not_in_flight(enabled_tra # unconditionally without double-closing a phase that completed normally. finish_adapter_function_phase_span("inv-6", "prepare") + # The no-op must leave the registry untouched, not merely avoid raising. + assert tracing._in_flight_spans == {} + def test_finish_adapter_function_span_closes_dangling_phase_span(enabled_tracing): """A phase that raised (start fired, complete never did) is closed by the invocation's own finish.""" From 6ab539ba7e0448f73c954b5c7b2d39327938b5fd Mon Sep 17 00:00:00 2001 From: Nigel Jones Date: Wed, 19 Aug 2026 18:44:04 +0100 Subject: [PATCH 09/12] docs(telemetry): state invocation-hook guard obligation and nesting edge The invocation hook builders in adapter.py construct payloads and dispatch unguarded by deliberate design - the call site in adapter_scope carries the try/except - but only the regression test explained why. State the obligation in both builders' docstrings so a future call site (e.g. #1465's generate/parse wiring) inherits the contract. Reword the tracing.md nesting claim: 'unconditional' overstates it - every firing site swallows dispatch failures, so a failed invocation-start dispatch leaves that invocation's phase spans unparented (ambient fallback). Document the edge. Assisted-by: opencode Signed-off-by: Nigel Jones --- docs/docs/observability/tracing.md | 9 +++++++-- mellea/backends/adapters/adapter.py | 10 ++++++++++ 2 files changed, 17 insertions(+), 2 deletions(-) diff --git a/docs/docs/observability/tracing.md b/docs/docs/observability/tracing.md index 28cc7b5a3c..ff0f9f67be 100644 --- a/docs/docs/observability/tracing.md +++ b/docs/docs/observability/tracing.md @@ -287,7 +287,8 @@ a phase that didn't finish contributes no duration sample) — the enclosing invocation's own close defensively ends that child span with `ERROR` status instead, so the in-flight span registry still drains to zero. -**Nesting is unconditional, unlike every other span pair in this document.** +**Nesting is unconditional across Python versions, unlike every other span +pair in this document, with one edge exception.** Every other family nests via ambient OTel context attach, which needs Python 3.12+ (see the note under "Span hierarchy" below) — `adapter_function` children instead parent explicitly via `trace.set_span_in_context`, because @@ -296,7 +297,11 @@ children instead parent explicitly via `trace.set_span_in_context`, because ambient attach can't establish a parent/child edge at all (each dispatched hook call gets an independent `contextvars` snapshot of the calling thread). So `adapter_function.` nests under `adapter_function` the same way on -Python 3.11 and 3.12+. +Python 3.11 and 3.12+. The edge exception is not version-related: every +firing site swallows a failed dispatch (an observability failure must never +block the operation it observes), so if an invocation's *start* dispatch +fails, its parent span never opens and that invocation's phase spans open +unparented, falling back to whatever ambient context exists. **Known gap: no exemplar linkage to `mellea.adapter_function.phase_duration`.** Because no span in this family is attached as ambient context (see above), the diff --git a/mellea/backends/adapters/adapter.py b/mellea/backends/adapters/adapter.py index db048502d2..ab0bf3039b 100644 --- a/mellea/backends/adapters/adapter.py +++ b/mellea/backends/adapters/adapter.py @@ -455,6 +455,11 @@ def _fire_invocation_start_hook( ) -> None: """Fire the `adapter_function_invocation_start` hook. + Unlike `_fire_phase_start_hook`, neither the payload construction nor the + dispatch is guarded here: a failure escapes to the call site, which must + wrap the call in `try`/`except` if the operation must not be blocked (see + `adapter_scope`). + Args: invocation_id: Correlation id shared with the matching `_fire_invocation_complete` call. @@ -490,6 +495,11 @@ def _fire_invocation_complete( ) -> None: """Fire the `adapter_function_invocation_complete` metric hook. + Payload construction is unguarded here, as in + `_fire_invocation_start_hook`: the call site carries the `try`/`except` — + a complete-hook failure must be logged and swallowed, never mask the real + outcome (see `adapter_scope`). + Args: invocation_id: Correlation id shared with the matching `_fire_invocation_start_hook` call. From 5e1ec7a0e8b9b4ca555fde4d41bc6423dc3df9a7 Mon Sep 17 00:00:00 2001 From: Nigel Jones Date: Wed, 19 Aug 2026 19:05:25 +0100 Subject: [PATCH 10/12] fix(telemetry): keep concurrent prepare() idempotent after the lock split The two-window check/work structure let a concurrent prepare() pass the pre-flight check while a winner held the work lock, then re-run load_peft_adapter and open a full second invocation (duplicate span and phase-duration sample) for work that was already done - the old single-window code made the loser a pure no-op. Re-check backend/_loaded as the first statement of the work window and return: the load never ran under the losing call, so no phase-complete fires (success-only contract) and the finally still closes the invocation it opened. Also correct the body comment: a release() completing between the windows clears _staged_backend, so the work window raises the bind-missing error, not the 'refused to register' one. Pinned by test_concurrent_prepare_loses_the_race_without_reloading (observed failing on the racy code: load_peft_adapter called twice). Assisted-by: opencode Signed-off-by: Nigel Jones --- mellea/backends/adapters/_core.py | 22 +++++++-- .../test_adapters/test_local_file_binding.py | 45 +++++++++++++++++++ 2 files changed, 63 insertions(+), 4 deletions(-) diff --git a/mellea/backends/adapters/_core.py b/mellea/backends/adapters/_core.py index 89874ad0fd..955cfc1d82 100644 --- a/mellea/backends/adapters/_core.py +++ b/mellea/backends/adapters/_core.py @@ -388,7 +388,11 @@ def bind_backend(self, backend: "AdapterMixin") -> None: def prepare(self) -> None: """Downloads the adapter weights and loads them into the staged backend. - Idempotent: a no-op once already prepared. Retryable: if a previous + Idempotent: a no-op once already prepared, including a concurrent + caller that passes the pre-flight check while a winner is still + loading — such a caller re-checks under the lifecycle lock and returns + without re-running the load or firing a phase-complete for work it + never did. Retryable: if a previous call registered with the backend but failed during the weights load (e.g. a transient download/load failure), the next call retries only the load rather than re-registering — registration already succeeded @@ -439,9 +443,12 @@ def prepare(self) -> None: # that re-enters this binding's lifecycle from the background loop would # otherwise deadlock against the lock this call still holds. The check # above and the work below each run under the lock, so an already-loaded - # (or released) binding opens no invocation and fires no hooks, and a - # concurrent `release()` interleaving surfaces as the backend's - # "refused to register" error rather than as state corruption. + # (or released) binding opens no invocation and fires no hooks. A + # caller that passes the check while a winner is still loading re-checks + # under the work lock and returns without re-running the load or firing + # a phase-complete; a `release()` completing between the two windows + # clears `_staged_backend`, so the work window raises the bind-missing + # error — a clean termination, not state corruption. invocation_id = str(uuid.uuid4()) revision: str | None try: @@ -454,6 +461,13 @@ def prepare(self) -> None: error: BaseException | None = None try: with self._lifecycle_lock: + if self.backend is not None and self._loaded: + # Lost the race: a concurrent prepare() completed between + # the check window above and the work lock. The load did + # not run under this call, so no phase-complete fires + # (success-only contract) — the `finally` below still + # closes the invocation this call opened. + return started_at = time.monotonic() if self.backend is None: if self._staged_backend is None: diff --git a/test/backends/test_adapters/test_local_file_binding.py b/test/backends/test_adapters/test_local_file_binding.py index 46c67f0b66..d39a1a2db0 100644 --- a/test/backends/test_adapters/test_local_file_binding.py +++ b/test/backends/test_adapters/test_local_file_binding.py @@ -166,6 +166,51 @@ def release(binding: LocalFileBinding) -> None: assert not binding._loaded +def test_concurrent_prepare_loses_the_race_without_reloading(): + """A prepare() that loses the race to a winner must not re-run the load. + + Regression guard: the hook dispatches run between two short lifecycle-lock + windows (see `prepare()`'s body comment), so a concurrent caller can pass + the pre-flight check while the winner still holds the work lock. On + entering the work window it must re-check and return instead of re-running + `load_peft_adapter` and firing a second phase-complete for work it never + did. + """ + backend = _fake_backend() + registration_started = threading.Event() + allow_registration = threading.Event() + errors: list[BaseException] = [] + + def register(binding: LocalFileBinding) -> None: + registration_started.set() + allow_registration.wait(timeout=1) + binding.backend = backend + + def prepare() -> None: + try: + binding.prepare() + except BaseException as exc: + errors.append(exc) + + backend.add_adapter.side_effect = register + binding = LocalFileBinding(name="answerability") + binding.bind_backend(backend) + + threads = [threading.Thread(target=prepare) for _ in range(2)] + for thread in threads: + thread.start() + assert registration_started.wait(timeout=1) + allow_registration.set() + for thread in threads: + thread.join(timeout=1) + + assert not any(thread.is_alive() for thread in threads) + assert not errors + backend.add_adapter.assert_called_once() + backend.load_peft_adapter.assert_called_once_with(binding.qualified_name) + assert binding._loaded + + def test_bind_backend_rejects_a_different_backend_after_registration(): backend = _fake_backend() other_backend = _fake_backend() From 6a4c9de56c7887ab40f699df1f80997249cd55d1 Mon Sep 17 00:00:00 2001 From: Nigel Jones Date: Thu, 20 Aug 2026 07:52:43 +0100 Subject: [PATCH 11/12] fix(telemetry): guard phase-complete payload construction in adapter.py _fire_phase_complete_hook built its pydantic payload outside its guard, contradicting its own docstring promise. Identity is a plain frozen dataclass with no runtime coercion, so an adapter with a non-str Identity.name raised a pydantic ValidationError from the activate phase-complete site after activate() had succeeded - the body never ran and a healthy invocation was reported as an error. Move the construction under the same guard as the dispatch. The invocation hooks stay unguarded by design (call-site guards, documented in their docstrings). Pinned by test_adapter_scope_swallows_non_str_identity_name_on_phase_ complete (observed failing on the unguarded code with the exact ValidationError). Assisted-by: opencode Signed-off-by: Nigel Jones --- mellea/backends/adapters/adapter.py | 12 +++++----- .../test_adapters/test_adapter_scope.py | 23 +++++++++++++++++++ 2 files changed, 29 insertions(+), 6 deletions(-) diff --git a/mellea/backends/adapters/adapter.py b/mellea/backends/adapters/adapter.py index ab0bf3039b..40d1eaa1e3 100644 --- a/mellea/backends/adapters/adapter.py +++ b/mellea/backends/adapters/adapter.py @@ -379,9 +379,9 @@ def _fire_phase_complete_hook( Split out of `_run_adapter_phase` so a caller that must guarantee cleanup after a phase's side effect — e.g. `adapter_scope` guaranteeing `deactivate()` runs once `activate()` has succeeded — can run the side - effect and this hook fire under separate exception handling. A hook-dispatch - failure is logged and ignored: observability must not turn a completed - lifecycle phase into an operation failure. + effect and this hook fire under separate exception handling. A + construction or dispatch failure is logged and ignored: observability + must not turn a completed lifecycle phase into an operation failure. Args: invocation_id: Correlation id of the enclosing invocation. @@ -394,10 +394,10 @@ def _fire_phase_complete_hook( return from ...plugins.hooks.adapter_function import AdapterFunctionPhaseCompletePayload - payload = AdapterFunctionPhaseCompletePayload( - invocation_id=invocation_id, name=name, phase=phase, duration_ms=duration_ms - ) try: + payload = AdapterFunctionPhaseCompletePayload( + invocation_id=invocation_id, name=name, phase=phase, duration_ms=duration_ms + ) hook_coro = invoke_hook(HookType.ADAPTER_FUNCTION_PHASE_COMPLETE, payload) _run_async_in_thread(hook_coro) except Exception: diff --git a/test/backends/test_adapters/test_adapter_scope.py b/test/backends/test_adapters/test_adapter_scope.py index b2d8b63edd..d0e7025f46 100644 --- a/test/backends/test_adapters/test_adapter_scope.py +++ b/test/backends/test_adapters/test_adapter_scope.py @@ -326,6 +326,29 @@ def test_adapter_scope_swallows_invocation_start_hook_failure(): weights.deactivate.assert_called_once() +def test_adapter_scope_swallows_non_str_identity_name_on_phase_complete(): + """A non-`str` adapter identity name must not abort activation. + + Regression guard: `_fire_phase_complete_hook` constructed its payload + outside its guard, so an adapter whose `Identity.name` was not a + `str` (`Identity` is a plain frozen dataclass and performs no runtime + type coercion) raised a pydantic `ValidationError` from the activate + phase-complete site after `activate()` had already succeeded — the + body never ran and a healthy invocation was reported as an error. + Construction now sits under the same guard as the dispatch. + """ + mock_backend = MagicMock(spec=AdapterMixin) + weights = _IntRevisionBinding() + identity = Identity(name=7, adapter_type="lora") # type: ignore[arg-type] + adapter = Adapter(identity=identity, io_contract=_Contract(), weights=weights) + + body_ran = False + with AdapterMixin.adapter_scope(mock_backend, adapter): + body_ran = True + + assert body_ran + + def test_adapter_scope_swallows_invocation_hook_failure_on_clean_run(): """A failing invocation-complete hook must not turn a clean run into an error. From 0abe496b384d3bfc7a66cc2e7449efe75fad6813 Mon Sep 17 00:00:00 2001 From: Nigel Jones Date: Thu, 20 Aug 2026 16:44:30 +0100 Subject: [PATCH 12/12] refactor: rename adapter function payload invocation id to family form Rename the public hook payload field 'invocation_id' to 'adapter_function_invocation_id', consistent with the other families' 'tool_invocation_id', closing the review round-1 deferred-rename item. None of the four payloads is released, so no migration is needed. The id travels through the private tracing helpers as a short local parameter and as the in-memory _in_flight_spans registry key; no span attribute carries it, so nothing to preserve on the wire. Assisted-by: opencode Signed-off-by: Nigel Jones --- mellea/backends/adapters/_core.py | 8 ++++---- mellea/backends/adapters/adapter.py | 14 ++++++++++---- mellea/plugins/hooks/adapter_function.py | 16 ++++++++-------- mellea/telemetry/tracing_plugins.py | 16 +++++++++++----- .../test_adapters/test_local_file_integration.py | 5 ++++- test/telemetry/test_metrics_plugins.py | 11 +++++++---- test/telemetry/test_tracing_adapter_function.py | 16 +++++++++++----- 7 files changed, 55 insertions(+), 31 deletions(-) diff --git a/mellea/backends/adapters/_core.py b/mellea/backends/adapters/_core.py index 955cfc1d82..e7e247edec 100644 --- a/mellea/backends/adapters/_core.py +++ b/mellea/backends/adapters/_core.py @@ -636,7 +636,7 @@ def _fire_invocation_start(self, invocation_id: str, revision: str | None) -> No try: payload = AdapterFunctionInvocationStartPayload( - invocation_id=invocation_id, + adapter_function_invocation_id=invocation_id, name=self.name, revision=revision, binding_type=self.binding_type, @@ -682,7 +682,7 @@ def _fire_invocation_complete( try: payload = AdapterFunctionInvocationCompletePayload( - invocation_id=invocation_id, + adapter_function_invocation_id=invocation_id, name=self.name, revision=revision, binding_type=self.binding_type, @@ -721,7 +721,7 @@ def _fire_phase_start( try: payload = AdapterFunctionPhaseStartPayload( - invocation_id=invocation_id, + adapter_function_invocation_id=invocation_id, name=self.name, phase=phase, revision=revision, @@ -763,7 +763,7 @@ def _fire_phase_complete( try: payload = AdapterFunctionPhaseCompletePayload( - invocation_id=invocation_id, + adapter_function_invocation_id=invocation_id, name=self.name, phase=phase, duration_ms=duration_s * 1000.0, diff --git a/mellea/backends/adapters/adapter.py b/mellea/backends/adapters/adapter.py index 40d1eaa1e3..84a16723be 100644 --- a/mellea/backends/adapters/adapter.py +++ b/mellea/backends/adapters/adapter.py @@ -358,7 +358,10 @@ def _fire_phase_start_hook( try: payload = AdapterFunctionPhaseStartPayload( - invocation_id=invocation_id, name=name, phase=phase, revision=revision + adapter_function_invocation_id=invocation_id, + name=name, + phase=phase, + revision=revision, ) hook_coro = invoke_hook(HookType.ADAPTER_FUNCTION_PHASE_START, payload) _run_async_in_thread(hook_coro) @@ -396,7 +399,10 @@ def _fire_phase_complete_hook( try: payload = AdapterFunctionPhaseCompletePayload( - invocation_id=invocation_id, name=name, phase=phase, duration_ms=duration_ms + adapter_function_invocation_id=invocation_id, + name=name, + phase=phase, + duration_ms=duration_ms, ) hook_coro = invoke_hook(HookType.ADAPTER_FUNCTION_PHASE_COMPLETE, payload) _run_async_in_thread(hook_coro) @@ -473,7 +479,7 @@ def _fire_invocation_start_hook( from ...plugins.hooks.adapter_function import AdapterFunctionInvocationStartPayload payload = AdapterFunctionInvocationStartPayload( - invocation_id=invocation_id, + adapter_function_invocation_id=invocation_id, name=name, revision=revision, binding_type=binding_type, @@ -517,7 +523,7 @@ def _fire_invocation_complete( ) payload = AdapterFunctionInvocationCompletePayload( - invocation_id=invocation_id, + adapter_function_invocation_id=invocation_id, name=name, revision=revision, binding_type=binding_type, diff --git a/mellea/plugins/hooks/adapter_function.py b/mellea/plugins/hooks/adapter_function.py index bae10a40d6..f26bb15f22 100644 --- a/mellea/plugins/hooks/adapter_function.py +++ b/mellea/plugins/hooks/adapter_function.py @@ -34,7 +34,7 @@ class AdapterFunctionInvocationStartPayload(MelleaBasePayload): """Payload for `adapter_function_invocation_start` — before an adapter function invocation begins. Attributes: - invocation_id: Correlation id shared with the matching + adapter_function_invocation_id: Correlation id shared with the matching `adapter_function_invocation_complete` event. name: Adapter function name (e.g. `"answerability"`). revision: Catalog revision of the adapter, or `None` if unpinned. @@ -43,7 +43,7 @@ class AdapterFunctionInvocationStartPayload(MelleaBasePayload): adapter_type: Adapter mechanism (e.g. `"lora"`, `"alora"`). """ - invocation_id: str + adapter_function_invocation_id: str name: str revision: str | None = None binding_type: str = "unknown" @@ -54,7 +54,7 @@ class AdapterFunctionInvocationCompletePayload(MelleaBasePayload): """Payload for `adapter_function_invocation_complete` — after an adapter function invocation finishes. Attributes: - invocation_id: Correlation id shared with the `adapter_function_invocation_start` + adapter_function_invocation_id: Correlation id shared with the `adapter_function_invocation_start` event that opened this invocation. name: Adapter function name (e.g. `"answerability"`). revision: Catalog revision of the adapter, or `None` if unpinned. @@ -65,7 +65,7 @@ class AdapterFunctionInvocationCompletePayload(MelleaBasePayload): error: The exception raised during invocation, or `None` on success. """ - invocation_id: str + adapter_function_invocation_id: str name: str revision: str | None = None binding_type: str = "unknown" @@ -84,7 +84,7 @@ class AdapterFunctionPhaseStartPayload(MelleaBasePayload): """Payload for `adapter_function_phase_start` — before one lifecycle phase begins. Attributes: - invocation_id: Correlation id of the enclosing invocation (shared with the + adapter_function_invocation_id: Correlation id of the enclosing invocation (shared with the `adapter_function_invocation_start`/`_complete` events). name: Adapter function name (e.g. `"answerability"`). phase: Lifecycle phase about to run. See `AdapterFunctionPhase` for which @@ -95,7 +95,7 @@ class AdapterFunctionPhaseStartPayload(MelleaBasePayload): resolved Hugging Face SHA. """ - invocation_id: str + adapter_function_invocation_id: str name: str phase: AdapterFunctionPhase revision: str | None = None @@ -109,7 +109,7 @@ class AdapterFunctionPhaseCompletePayload(MelleaBasePayload): `adapter_function_invocation_complete`'s `outcome`/`error`. Attributes: - invocation_id: Correlation id of the enclosing invocation (shared with the + adapter_function_invocation_id: Correlation id of the enclosing invocation (shared with the `adapter_function_invocation_start`/`_complete` events). name: Adapter function name (e.g. `"answerability"`). phase: Lifecycle phase that completed. See `AdapterFunctionPhase` for @@ -117,7 +117,7 @@ class AdapterFunctionPhaseCompletePayload(MelleaBasePayload): duration_ms: Wall-clock duration of the phase in milliseconds. """ - invocation_id: str + adapter_function_invocation_id: str name: str # Constrained to a Literal so a typo can't silently spawn a new metric-label # series (the phase becomes a metric dimension). Required, with no unset diff --git a/mellea/telemetry/tracing_plugins.py b/mellea/telemetry/tracing_plugins.py index 1c53e28b27..49d9541de0 100644 --- a/mellea/telemetry/tracing_plugins.py +++ b/mellea/telemetry/tracing_plugins.py @@ -655,7 +655,7 @@ class AdapterFunctionTracingPlugin( left open by a phase that raised (see `finish_adapter_function_span`). `adapter_function_phase_start`/`adapter_function_phase_complete` open/close one child span per lifecycle phase, correlated with the parent via - `invocation_id`. + `adapter_function_invocation_id`. On the `mellea.backend` tracer (adapter/model lifecycle work, not a user-facing operation — see `docs/docs/observability/tracing.md`). @@ -701,7 +701,7 @@ async def on_invocation_start( from mellea.telemetry.tracing import start_adapter_function_span start_adapter_function_span( - payload.invocation_id, + payload.adapter_function_invocation_id, name=payload.name, revision=payload.revision, binding_type=payload.binding_type, @@ -716,7 +716,9 @@ async def on_invocation_complete( from mellea.telemetry.tracing import finish_adapter_function_span finish_adapter_function_span( - payload.invocation_id, outcome=payload.outcome, exception=payload.error + payload.adapter_function_invocation_id, + outcome=payload.outcome, + exception=payload.error, ) @hook("adapter_function_phase_start") @@ -727,7 +729,9 @@ async def on_phase_start( from mellea.telemetry.tracing import start_adapter_function_phase_span start_adapter_function_phase_span( - payload.invocation_id, payload.phase, revision=payload.revision + payload.adapter_function_invocation_id, + payload.phase, + revision=payload.revision, ) @hook("adapter_function_phase_complete") @@ -737,7 +741,9 @@ async def on_phase_complete( """Close the `adapter_function.` child span.""" from mellea.telemetry.tracing import finish_adapter_function_phase_span - finish_adapter_function_phase_span(payload.invocation_id, payload.phase) + finish_adapter_function_phase_span( + payload.adapter_function_invocation_id, payload.phase + ) # All tracing plugins to auto-register when tracing is enabled. diff --git a/test/backends/test_adapters/test_local_file_integration.py b/test/backends/test_adapters/test_local_file_integration.py index b8ec39779c..ddfb3aa3c1 100644 --- a/test/backends/test_adapters/test_local_file_integration.py +++ b/test/backends/test_adapters/test_local_file_integration.py @@ -135,7 +135,10 @@ def test_prepare_activate_deactivate_release_full_lifecycle(): assert invocations[0].name == "answerability" assert invocations[0].binding_type == "local_file" assert invocations[0].adapter_type == binding.adapter_type.value - assert invocations[0].invocation_id == invocation_starts[0].invocation_id + assert ( + invocations[0].adapter_function_invocation_id + == invocation_starts[0].adapter_function_invocation_id + ) def test_deactivate_runs_even_when_generation_body_raises(): diff --git a/test/telemetry/test_metrics_plugins.py b/test/telemetry/test_metrics_plugins.py index 894ff89d7b..3c4a7272d1 100644 --- a/test/telemetry/test_metrics_plugins.py +++ b/test/telemetry/test_metrics_plugins.py @@ -1084,7 +1084,7 @@ def adapter_function_plugin(): async def test_record_adapter_function_invocation_success(adapter_function_plugin): """A successful invocation records the invocations counter, not parse_failures.""" payload = AdapterFunctionInvocationCompletePayload( - invocation_id="inv-1", + adapter_function_invocation_id="inv-1", name="answerability", revision="r1", binding_type="local_file", @@ -1118,7 +1118,7 @@ async def test_record_adapter_function_invocation_schema_error_also_records_pars ): """A schema_error outcome records both the invocations counter and parse_failures.""" payload = AdapterFunctionInvocationCompletePayload( - invocation_id="inv-2", + adapter_function_invocation_id="inv-2", name="answerability", revision="r1", binding_type="local_file", @@ -1156,7 +1156,7 @@ async def test_record_adapter_function_invocation_none_revision_passed_through( not in the plugin — so the plugin passes the raw payload.revision value. """ payload = AdapterFunctionInvocationCompletePayload( - invocation_id="inv-3", + adapter_function_invocation_id="inv-3", name="answerability", revision=None, binding_type="embedded", @@ -1182,7 +1182,10 @@ async def test_record_adapter_function_invocation_none_revision_passed_through( async def test_record_adapter_function_phase_duration(adapter_function_plugin): """Phase-complete events record the phase-duration histogram in seconds.""" payload = AdapterFunctionPhaseCompletePayload( - invocation_id="inv-4", name="answerability", phase="prepare", duration_ms=12.5 + adapter_function_invocation_id="inv-4", + name="answerability", + phase="prepare", + duration_ms=12.5, ) with patch( diff --git a/test/telemetry/test_tracing_adapter_function.py b/test/telemetry/test_tracing_adapter_function.py index d9976029eb..bd3f777678 100644 --- a/test/telemetry/test_tracing_adapter_function.py +++ b/test/telemetry/test_tracing_adapter_function.py @@ -307,7 +307,7 @@ async def test_plugin_invocation_start_opens_parent_span( _fake_span, fake_tracer = _patch_backend_tracer() payload = AdapterFunctionInvocationStartPayload( - invocation_id="p-inv-1", + adapter_function_invocation_id="p-inv-1", name="answerability", revision="r1", binding_type="local_file", @@ -331,14 +331,14 @@ async def test_plugin_invocation_complete_closes_parent_span( fake_span, fake_tracer = _patch_backend_tracer() start_payload = AdapterFunctionInvocationStartPayload( - invocation_id="p-inv-2", + adapter_function_invocation_id="p-inv-2", name="answerability", revision="r1", binding_type="local_file", adapter_type="lora", ) complete_payload = AdapterFunctionInvocationCompletePayload( - invocation_id="p-inv-2", + adapter_function_invocation_id="p-inv-2", name="answerability", revision="r1", binding_type="local_file", @@ -364,10 +364,16 @@ async def test_plugin_phase_start_and_complete_open_and_close_child_span( fake_span, fake_tracer = _patch_backend_tracer() start_payload = AdapterFunctionPhaseStartPayload( - invocation_id="p-inv-3", name="answerability", phase="prepare", revision="sha1" + adapter_function_invocation_id="p-inv-3", + name="answerability", + phase="prepare", + revision="sha1", ) complete_payload = AdapterFunctionPhaseCompletePayload( - invocation_id="p-inv-3", name="answerability", phase="prepare", duration_ms=5.0 + adapter_function_invocation_id="p-inv-3", + name="answerability", + phase="prepare", + duration_ms=5.0, ) with patch("mellea.telemetry.tracing.get_backend_tracer", return_value=fake_tracer): await adapter_function_plugin.on_phase_start(start_payload, {})