Skip to content

Commit 6bf1b5b

Browse files
Route Langfuse timestamps through OTel tracer
The v4.7 Langfuse SDK exposes timestamp control only on its internal OTel tracer, not on the public start_observation() API that the adapter was calling. Two quirks the original Protocol widening got wrong, both surfaced by live-account verification: start_observation() rejects a start_time kwarg with TypeError. When start_time is supplied, the adapter now mirrors the SDK's own create_event precedent: open the OTel span directly via _otel_tracer.start_span(name=, start_time=int_ns) within a trace context and wrap the result in LangfuseGeneration. The existing no-start_time path still uses the public API. LangfuseSpan.end(end_time) is typed Optional[int] (nanoseconds), not datetime. The adapter now converts the Protocol's datetime surface to nanoseconds before forwarding. Without the conversion the OTel span_processor's formatter crashes with TypeError on end_time / 1e9 deep in the SDK. Strengthen the unit tests: spy on both _otel_tracer.start_span and start_observation so the back-dated path asserts the OTel route is taken and the public-API path asserts the OTel tracer is NOT touched. The previous monkeypatch test accepted **kwargs and would have passed even with the broken implementation. Widen the integration test's REST poll budget to 180s and use server-side name+type filters; add a diagnostic that lists observation names actually projected under the trace_id when the target Generation doesn't appear, so a future name-mismatch SDK change surfaces explicitly.
1 parent c448ce2 commit 6bf1b5b

3 files changed

Lines changed: 190 additions & 43 deletions

File tree

src/openarmature/observability/langfuse/adapter.py

Lines changed: 94 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -134,10 +134,14 @@ def end(self, *, end_time: datetime | None = None, **fields: Any) -> None:
134134
# Apply any field updates first (so they're set BEFORE the
135135
# observation closes), then call end(). v4's end() takes only
136136
# an optional ``end_time``; field mutation happens via update().
137+
# The SDK's end_time is typed Optional[int] nanoseconds —
138+
# convert from the Protocol's datetime surface before passing
139+
# through. Without the conversion the OTel span_processor's
140+
# formatter raises TypeError when it tries ``end_time / 1e9``.
137141
if fields:
138142
self.update(**fields)
139143
if end_time is not None:
140-
self._obs.end(end_time=end_time)
144+
self._obs.end(end_time=int(end_time.timestamp() * 1_000_000_000))
141145
else:
142146
self._obs.end()
143147

@@ -362,19 +366,97 @@ def generation(
362366
usage_details["total"] = usage.total
363367
extra_kwargs["usage_details"] = usage_details
364368
if start_time is not None:
365-
extra_kwargs["start_time"] = start_time
366-
obs = self._start_observation(
367-
as_type="generation",
368-
trace_id=trace_id,
369-
name=name,
370-
metadata=metadata,
371-
parent_observation_id=parent_observation_id,
372-
level=level,
373-
status_message=status_message,
374-
**{k: v for k, v in extra_kwargs.items() if v is not None},
375-
)
369+
# v4's public ``start_observation`` does NOT accept a
370+
# ``start_time`` kwarg — only the internal OTel tracer
371+
# does. Mirror the SDK's own ``create_event`` precedent
372+
# (langfuse/_client/client.py:1518-1551): open the OTel
373+
# span directly via the private ``_otel_tracer`` with the
374+
# back-dated timestamp, then wrap it in LangfuseGeneration.
375+
# This is the only path to a back-dated Generation in
376+
# v4.7; the live-account integration test catches a future
377+
# SDK break.
378+
obs = self._start_back_dated_generation(
379+
trace_id=trace_id,
380+
name=name,
381+
metadata=metadata,
382+
parent_observation_id=parent_observation_id,
383+
level=level,
384+
status_message=status_message,
385+
start_time=start_time,
386+
**{k: v for k, v in extra_kwargs.items() if v is not None},
387+
)
388+
else:
389+
obs = self._start_observation(
390+
as_type="generation",
391+
trace_id=trace_id,
392+
name=name,
393+
metadata=metadata,
394+
parent_observation_id=parent_observation_id,
395+
level=level,
396+
status_message=status_message,
397+
**{k: v for k, v in extra_kwargs.items() if v is not None},
398+
)
376399
return _SpanHandle(obs)
377400

401+
def _start_back_dated_generation(
402+
self,
403+
*,
404+
trace_id: str,
405+
name: str | None,
406+
metadata: dict[str, Any] | None,
407+
parent_observation_id: str | None,
408+
level: ObservationLevel,
409+
status_message: str | None,
410+
start_time: datetime,
411+
**extra: Any,
412+
) -> Any:
413+
"""Open a LangfuseGeneration at a back-dated timestamp by going
414+
through the private OTel tracer rather than the public
415+
``start_observation`` API (which doesn't accept ``start_time``
416+
in v4.7). Mirrors the SDK's ``create_event`` precedent."""
417+
from langfuse._client.span import LangfuseGeneration
418+
from opentelemetry import trace as otel_trace_api
419+
420+
trace_entry = self._trace_info.get(trace_id)
421+
trace_context: TraceContext = {"trace_id": _to_otel_trace_id(trace_id)}
422+
if parent_observation_id is not None:
423+
trace_context["parent_span_id"] = parent_observation_id
424+
425+
# OTel's ``start_span(start_time=...)`` takes int nanoseconds
426+
# since epoch. The SDK uses ``time_ns()`` for its instant
427+
# events; for back-dating, convert from the supplied datetime.
428+
start_time_ns = int(start_time.timestamp() * 1_000_000_000)
429+
430+
remote_parent_span = self._client._create_remote_parent_span( # pyright: ignore[reportPrivateUsage] # noqa: SLF001
431+
trace_id=trace_context["trace_id"],
432+
parent_span_id=trace_context.get("parent_span_id"),
433+
)
434+
435+
with ExitStack() as stack:
436+
if trace_entry is not None:
437+
stack.enter_context(
438+
propagate_attributes(
439+
trace_name=trace_entry["name"],
440+
metadata=_stringify_metadata(trace_entry["metadata"]),
441+
)
442+
)
443+
stack.enter_context(otel_trace_api.use_span(remote_parent_span))
444+
otel_span = self._client._otel_tracer.start_span( # pyright: ignore[reportPrivateUsage] # noqa: SLF001
445+
name=name or "observation",
446+
start_time=start_time_ns,
447+
)
448+
generation_kwargs: dict[str, Any] = {
449+
"otel_span": otel_span,
450+
"langfuse_client": self._client,
451+
"metadata": metadata,
452+
}
453+
if level != "DEFAULT":
454+
generation_kwargs["level"] = level
455+
if status_message is not None:
456+
generation_kwargs["status_message"] = status_message
457+
generation_kwargs.update(extra)
458+
return LangfuseGeneration(**generation_kwargs)
459+
378460
def force_flush(self, timeout_ms: int = 30_000) -> bool:
379461
"""Best-effort flush of the underlying Langfuse client.
380462

tests/integration/test_langfuse_sdk_adapter.py

Lines changed: 24 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -185,30 +185,39 @@ async def test_sdk_adapter_generation_timestamps_round_trip_through_langfuse() -
185185
hex_id = invocation_id.replace("-", "")
186186
try:
187187
_poll_trace_with_retry(client, hex_id)
188-
# Pull observations directly: the trace.observations list lags
189-
# the headline trace fields in the REST projection, so query
190-
# the observations endpoint with a retry budget similar to the
191-
# trace poll. Filter by name rather than indexing the first
192-
# entry so future synthetic observations (Langfuse adds
193-
# ``openarmature.trace_io`` carriers for trace input/output
194-
# under some flows) don't shadow the target Generation.
188+
# Pull observations via REST. The observations-list endpoint
189+
# lags the headline trace fields by an "indeterminate window"
190+
# per Langfuse's own caveat (mirrored in the trace_io test
191+
# above), so the retry budget here is wider (180s vs the
192+
# trace_io test's 60s). Filter server-side by name + type so
193+
# the response is small + scoped; track seen names across
194+
# polls so a name-mismatch failure surfaces with diagnostics
195+
# rather than a generic "not found".
195196
observation: Any = None
196197
last_exc: Exception | None = None
197-
for _ in range(12):
198+
seen_names: set[str] = set()
199+
for _ in range(36):
198200
try:
199-
response = client.api.observations.get_many(trace_id=hex_id)
200-
observation = next(
201-
(o for o in response.data if o.name == "openarmature.llm.complete"),
202-
None,
201+
response = client.api.observations.get_many(
202+
trace_id=hex_id,
203+
name="openarmature.llm.complete",
204+
type="GENERATION",
203205
)
204-
if observation is not None:
206+
if response.data:
207+
observation = response.data[0]
205208
break
209+
# Fall back to an unfiltered query so we know whether
210+
# ANY observations have projected — distinguishes "REST
211+
# lag" from "observation projected with unexpected name".
212+
fallback = client.api.observations.get_many(trace_id=hex_id)
213+
seen_names.update(o.name or "<unnamed>" for o in fallback.data)
206214
except Exception as exc: # noqa: BLE001
207215
last_exc = exc
208216
time.sleep(5)
209217
assert observation is not None, (
210-
f"openarmature.llm.complete observation for trace {hex_id} did not appear via REST "
211-
f"after retry budget; last error: {last_exc!r}"
218+
f"openarmature.llm.complete Generation for trace {hex_id} did not appear via REST "
219+
f"after 180s retry budget. Observations seen under trace (any name): {seen_names or 'none'}. "
220+
f"Last error: {last_exc!r}"
212221
)
213222

214223
# The REST projection's start/end timestamps MUST match the

tests/unit/test_observability_langfuse_adapter.py

Lines changed: 72 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -161,38 +161,93 @@ def test_adapter_force_flush_delegates_to_client() -> None:
161161
assert wrapped.flush.call_count == 2
162162

163163

164-
def test_adapter_generation_forwards_start_time_to_sdk(monkeypatch: pytest.MonkeyPatch) -> None:
165-
# The typed-event LLM path back-dates the Generation observation
166-
# using ``start_time = end_time - timedelta(milliseconds=
167-
# latency_ms)``. The adapter MUST flow ``start_time`` through to
168-
# the v4 SDK's ``start_observation(start_time=...)`` kwarg.
169-
# Without this passthrough, Langfuse would show the call-time
170-
# timestamp instead of the back-dated one — the verification gap
171-
# the InMemory client can't catch on its own.
164+
def test_adapter_generation_routes_back_dated_calls_via_otel_tracer(monkeypatch: pytest.MonkeyPatch) -> None:
165+
# v4.7's public ``Langfuse.start_observation`` does NOT accept
166+
# ``start_time`` — only the internal ``_otel_tracer.start_span``
167+
# does. The adapter MUST route back-dated generation() calls via
168+
# the OTel tracer path (mirroring the SDK's own ``create_event``
169+
# precedent). This test spies on BOTH paths: ``start_observation``
170+
# is patched to fail loudly if the back-dated path ever falls
171+
# through to it (the prior monkeypatch test's gap), and the OTel
172+
# tracer's ``start_span`` is spied to assert the back-dated
173+
# nanosecond timestamp lands on the right surface.
172174
from datetime import UTC, datetime
173175
from unittest.mock import MagicMock
174176

177+
client = _dummy_client()
178+
captured_otel_kwargs: dict[str, Any] = {}
179+
180+
def _otel_spy(**kwargs: Any) -> MagicMock:
181+
captured_otel_kwargs.update(kwargs)
182+
# The SDK calls get_span_context(), set_attribute(), etc. on
183+
# the returned span during LangfuseGeneration construction.
184+
# Plain MagicMock auto-creates most attrs, but trace_id /
185+
# span_id MUST be real ints because the SDK formats them as
186+
# 32 / 16-char hex internally.
187+
span = MagicMock()
188+
span.get_span_context.return_value = MagicMock(
189+
trace_id=int("a" * 32, 16),
190+
span_id=int("b" * 16, 16),
191+
)
192+
return span
193+
194+
def _start_observation_should_not_be_called(**_kwargs: Any) -> None:
195+
raise AssertionError(
196+
"start_observation MUST NOT be called on the back-dated path; "
197+
"v4 SDK rejects start_time= and the adapter should route via _otel_tracer"
198+
)
199+
200+
monkeypatch.setattr(client._otel_tracer, "start_span", _otel_spy) # noqa: SLF001
201+
monkeypatch.setattr(client, "start_observation", _start_observation_should_not_be_called)
202+
adapter = LangfuseSDKAdapter(client)
203+
adapter.trace(id="trace-ts", name="t")
204+
205+
start = datetime(2026, 6, 8, 12, 0, 0, tzinfo=UTC)
206+
adapter.generation(trace_id="trace-ts", name="g", model="m", start_time=start)
207+
208+
expected_ns = int(start.timestamp() * 1_000_000_000)
209+
assert captured_otel_kwargs.get("start_time") == expected_ns
210+
assert captured_otel_kwargs.get("name") == "g"
211+
212+
213+
def test_adapter_generation_without_start_time_uses_public_api(monkeypatch: pytest.MonkeyPatch) -> None:
214+
# Companion to the back-dated test: when ``start_time`` is NOT
215+
# supplied, the adapter falls back to the v4 SDK's public
216+
# ``start_observation`` API and does NOT touch the private OTel
217+
# tracer.
218+
from unittest.mock import MagicMock
219+
175220
client = _dummy_client()
176221
captured_kwargs: dict[str, Any] = {}
177222

178223
def _spy(**kwargs: Any) -> MagicMock:
179224
captured_kwargs.update(kwargs)
180225
return MagicMock(id="obs-spy", end=MagicMock())
181226

227+
def _otel_tracer_should_not_be_called(**_kwargs: Any) -> None:
228+
raise AssertionError(
229+
"_otel_tracer.start_span MUST NOT be called when start_time is None; "
230+
"the public start_observation API should handle this path"
231+
)
232+
182233
monkeypatch.setattr(client, "start_observation", _spy)
234+
monkeypatch.setattr(client._otel_tracer, "start_span", _otel_tracer_should_not_be_called) # noqa: SLF001
183235
adapter = LangfuseSDKAdapter(client)
184236
adapter.trace(id="trace-ts", name="t")
185237

186-
start = datetime(2026, 6, 8, 12, 0, 0, tzinfo=UTC)
187-
adapter.generation(trace_id="trace-ts", name="g", model="m", start_time=start)
238+
adapter.generation(trace_id="trace-ts", name="g", model="m")
188239

189-
assert captured_kwargs.get("start_time") == start
240+
assert captured_kwargs.get("name") == "g"
241+
assert "start_time" not in captured_kwargs
190242

191243

192-
def test_adapter_generation_handle_end_forwards_end_time_to_sdk() -> None:
193-
# Companion to the start_time test: the handle's end() MUST flow
194-
# ``end_time`` through to the underlying v4 obs's ``end(end_time
195-
# =...)`` call so the Langfuse UI shows the back-dated duration.
244+
def test_adapter_generation_handle_end_converts_end_time_to_nanoseconds() -> None:
245+
# Companion to the start_time test: the handle's end() MUST
246+
# convert the datetime to int nanoseconds before forwarding to
247+
# the underlying v4 obs's end(). LangfuseSpan.end is typed
248+
# ``Optional[int]`` (nanoseconds); passing a datetime through
249+
# crashes the OTel span_processor's formatter with TypeError on
250+
# ``end_time / 1e9`` deep in the SDK.
196251
from datetime import UTC, datetime
197252
from unittest.mock import MagicMock
198253

@@ -205,7 +260,8 @@ def test_adapter_generation_handle_end_forwards_end_time_to_sdk() -> None:
205260
end = datetime(2026, 6, 8, 12, 0, 1, tzinfo=UTC)
206261
handle.end(end_time=end)
207262

208-
sdk_obs.end.assert_called_once_with(end_time=end)
263+
expected_ns = int(end.timestamp() * 1_000_000_000)
264+
sdk_obs.end.assert_called_once_with(end_time=expected_ns)
209265

210266

211267
def test_adapter_generation_handle_end_omits_end_time_when_unspecified() -> None:

0 commit comments

Comments
 (0)