diff --git a/CHANGELOG.md b/CHANGELOG.md index b876464..04bb5a4 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,6 +12,8 @@ The format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/). The - **The structured-output path, on the typed LLM events and the LLM span** (graph-engine §6, observability §5.5, proposal 0126). `LlmCompletionEvent` and `LlmFailedEvent` carry `structured_output_path`, and the `openarmature.llm.complete` span carries `openarmature.llm.structured_output.path`, naming the way a call with a `response_schema` asked for structured output: `"native"` when the request went out with `strict: true`, `"native_unenforced"` when it went out with `strict: false`, and `"prompt_augmentation"` on the schema-directive fallback. The field is `None`, and the attribute absent, when no schema was supplied or no request was sent. Neither is gated by `disable_provider_payload`. The field defaults to `None`, so a custom provider that builds these events keeps working unchanged. +- **A warning when a provider did not honor the schema** (observability §5.5.7 and §7, proposal 0126). When a `strict: true` structured-output attempt finishes with `finish_reason` `"stop"`, no stop sequence set, and content that is not a JSON object, the OpenAI provider logs one `WARNING` with the event name `openarmature.structured_output.schema_not_honored`. Constrained decoding cannot produce that content, so it is evidence the schema did not reach or did not bind the model, as with an endpoint that accepts `response_format` and ignores it. A JSON object that fails validation does not trigger it, since a provider that applied the schema can still return one. The record carries `openarmature.llm.provider`, `openarmature.llm.model` (the bound model), `openarmature.llm.call_id`, which joins it to the call's typed event, and `openarmature.llm.attempt_index`. It is logged once per attempt, so a reask that recovers still leaves the failed attempt's record, and it does not depend on any observer being attached. It is advisory: the call fails with `StructuredOutputInvalid` as before, and nothing is retried or switched to the fallback because of it. The name is importable as `STRUCTURED_OUTPUT_SCHEMA_NOT_HONORED` from `openarmature.observability`. + ### Changed - **A structured-output failure's `error_message` describes every violation** (llm-provider §5 and §7, proposal 0126, spec v0.119.0). It used to name one, the one jsonschema's best match picked, at a `$.`-style path. It now lists every assertion the content fails, each at its location as a JSON Pointer in URI-fragment form (`#/site/lat`, `#/first%20name`) with the constraint that failed, and a `type` violation names the expected type: `2 violations: #/site/delta: expected type number, got string; #/site/echo: required property is missing`. A missing required property, a property that `additionalProperties: false` excludes or whose name `propertyNames` rejects, and an array element the schema disallows each sit at their own location rather than at the object or array containing them. `unevaluatedProperties: false` and `unevaluatedItems: false` are placed that way only in a draft 2020-12 schema without a nested `$id` or a `$dynamicRef`; elsewhere, and when either keyword holds a schema, they are still reported once, at the object or array. In an `anyOf` or `oneOf` that no member satisfies, only the members whose own `type` admits the content are reported, or, when none does, one violation at the composite naming the members' types. A failure that only a Pydantic `response_schema` class's own validation catches is reported at the failing field, one violation for each error Pydantic reports. jsonschema's own wording in each description is cut to 200 characters, so a long enum or array is not repeated whole in every violation. A `response_schema` that declares no `$schema` is now read as JSON Schema draft 2020-12 explicitly, rather than as whatever draft the installed jsonschema treats as newest; a declared draft is still honored when jsonschema recognizes its URI, and any other `$schema`, such as the `https` form of the draft-07 URI, is read as 2020-12 as well. Content that cannot be parsed stays a single violation: `NaN` and `Infinity`, which Python's parser accepted, now count as malformed, and a number too large for a float, such as `1e400`, is reported the same way. Fixture 082 runs. diff --git a/conformance.toml b/conformance.toml index 857f2ec..2fdab71 100644 --- a/conformance.toml +++ b/conformance.toml @@ -1204,4 +1204,4 @@ note = "Conformance coverage only, no normative spec change: fixture 160 gains a [proposals."0126"] status = "partial" since = "0.18.0" -note = "Structured-output failure reports, partly implemented. Done: a structured_output_invalid error_message describes every violation, each located by a URI-fragment JSON Pointer with the constraint that failed and the expected type for a type violation; the violations jsonschema reports at the enclosing object or array (missing required and dependentRequired properties, properties that additionalProperties: false excludes or whose name propertyNames rejects, disallowed array elements) are moved to their own location in every draft, and an anyOf or oneOf no member satisfies reports only the members whose own type admits the content. A response_schema that declares no $schema is read as JSON Schema draft 2020-12. An OpenAI refusal maps to finish_reason content_filter, with its text as the message's content. LlmCompletionEvent and LlmFailedEvent carry structured_output_path and the LLM span carries openarmature.llm.structured_output.path; each attempt's span and the call's typed event describe the request that attempt sent, with any per-attempt override merged and the reask turns and the fallback's schema directive included, and a request rejected before sending is described with a null path: the caller's own when nothing was sent, and on a retry the request it was building. Missing: unevaluatedProperties and unevaluatedItems located per property or element when either holds a schema, in draft 2019-09, or in a schema with a nested $id or a $dynamicRef (each is reported once at the object or array); and the openarmature.structured_output.schema_not_honored diagnostic. Fixtures 082 and 083 run, 083 without its two streamed cases; 161, which also asserts the path and the request descriptions, is deferred: our runner lacks the harness support it needs, log-record assertions among them. The streamed half of the refusal mapping waits for streaming (proposal 0062)." +note = "Structured-output failure reports, partly implemented. Done: a structured_output_invalid error_message describes every violation, each located by a URI-fragment JSON Pointer with the constraint that failed and the expected type for a type violation; the violations jsonschema reports at the enclosing object or array (missing required and dependentRequired properties, properties that additionalProperties: false excludes or whose name propertyNames rejects, disallowed array elements) are moved to their own location in every draft, and an anyOf or oneOf no member satisfies reports only the members whose own type admits the content. A response_schema that declares no $schema is read as JSON Schema draft 2020-12. An OpenAI refusal maps to finish_reason content_filter, with its text as the message's content. LlmCompletionEvent and LlmFailedEvent carry structured_output_path and the LLM span carries openarmature.llm.structured_output.path; each attempt's span and the call's typed event describe the request that attempt sent, with any per-attempt override merged and the reask turns and the fallback's schema directive included, and a request rejected before sending is described with a null path: the caller's own when nothing was sent, and on a retry the request it was building. A request whose connection never opened also reports a null path. A native-path attempt that finishes on stop, with no stop sequence, and returns content that is not a JSON object logs the openarmature.structured_output.schema_not_honored WARNING, once per attempt and whether or not an observer is attached, with its four attributes. Missing: unevaluatedProperties and unevaluatedItems located per property or element when either holds a schema, in draft 2019-09, or in a schema with a nested $id or a $dynamicRef (each is reported once at the object or array). Fixtures 082 and 083 run, 083 without its two streamed cases; 161 is deferred: our runner lacks the harness support it needs, log-record assertions among them, so unit tests cover the diagnostic, the path and the request descriptions meanwhile. The streamed half of the refusal mapping waits for streaming (proposal 0062)." diff --git a/docs/concepts/llms.md b/docs/concepts/llms.md index 6b0b425..c197a4a 100644 --- a/docs/concepts/llms.md +++ b/docs/concepts/llms.md @@ -453,6 +453,17 @@ with `strict: true` reports the `"native"` path, and one sent with `strict: false` reports `"native_unenforced"`, since OpenAI documents constrained decoding only for strict mode. +Strict mode cannot produce content that is not a JSON object. So when +a `strict: true` attempt finishes with `finish_reason` `"stop"`, no +stop sequence set, and content that is prose, a bare array or anything +else that is not a JSON object, the provider logs one `WARNING` with +the event name `openarmature.structured_output.schema_not_honored`. It +names the model, the call's `call_id` and the attempt's index. One +cause is an endpoint that accepts `response_format` and ignores it. A +JSON object that fails validation does not trigger the warning. The +warning is advisory: the call still raises `StructuredOutputInvalid`, +and nothing is retried or switched to the fallback because of it. + `strict_mode_supported(schema)` (exported from `openarmature.llm`) performs the deep recursive check. The heuristic is conservative: anything not on the list below trips to `strict: false`: diff --git a/docs/concepts/observability.md b/docs/concepts/observability.md index adb90c8..58e550e 100644 --- a/docs/concepts/observability.md +++ b/docs/concepts/observability.md @@ -639,6 +639,7 @@ correlation: | `openarmature.langfuse.payload_suppressed` | `WARNING` | OA cannot establish the Langfuse client's provider binding and suppresses every harvested-payload channel | | `openarmature.langfuse.shared_provider_accepted` | `WARNING` | You accepted a shared provider and OA proceeded onto it | | `openarmature.langfuse.shared_provider_no_payload` | `INFO` | OA's client is on a provider it did not isolate, but no payload channel is live, so nothing is exported to it | +| `openarmature.structured_output.schema_not_honored` | `WARNING` | A `strict: true` structured-output attempt finished normally with content that is not a JSON object, so the schema did not bind ([details](llms.md#strict-mode)) | | `openarmature.token_budget.exceeded` | `WARNING` | An active prompt's token budget was exceeded | The no-payload one is `INFO` because nothing is leaking on that arm: it diff --git a/src/openarmature/llm/providers/openai.py b/src/openarmature/llm/providers/openai.py index e6261d9..81fe988 100644 --- a/src/openarmature/llm/providers/openai.py +++ b/src/openarmature/llm/providers/openai.py @@ -84,6 +84,7 @@ current_invocation_id, current_namespace_prefix, ) +from openarmature.observability.diagnostics import STRUCTURED_OUTPUT_SCHEMA_NOT_HONORED, diagnostic from openarmature.observability.metadata import AttributeValue, current_invocation_metadata from .._event_fields import _event_request, _EventRequest @@ -522,6 +523,7 @@ async def complete( path = _structured_output_path( schema_dict, fallback=self._force_prompt_augmentation_fallback, strict=strict ) + stop_sent = False def build_body( attempt: int, @@ -566,7 +568,7 @@ def hint(key: str) -> str | None: "an extras key; remove one" ) - nonlocal reported + nonlocal reported, stop_sent # graph-engine §6: a retry rejected before sending reports the # request it was building, with no path since none went out. A # first attempt rejected here leaves the caller's own in place. @@ -584,6 +586,7 @@ def hint(key: str) -> str | None: collision_hint=hint, ) reported = replace(request, structured_output_path=path) + stop_sent = _carries_stop_sequence(body.get("stop")) return body # Per-attempt LLM span surface (observability §5.5 under @@ -591,8 +594,8 @@ def hint(key: str) -> str | None: # LlmRetryAttemptEvent per attempt so the observer can render # one openarmature.llm.complete span per attempt. Each describes # its attempt's own request, which build_body recorded before the - # request went out. No-op outside an invocation (``dispatch`` is - # None). + # request went out. Outside an invocation (``dispatch`` is None) + # nothing is dispatched. def emit_attempt( idx: int, attempt_latency_ms: float, @@ -600,6 +603,12 @@ def emit_attempt( attempt_exc: LlmProviderError | None, retry_reason: str | None = None, ) -> None: + request = _as_sent(reported, attempt_exc) + # observability §5.5.7: one record per wire attempt however many + # observers are attached, none included, so it precedes the + # dispatch check. + if _schema_not_honored(request, attempt_exc, stop_sent=stop_sent): + self._warn_schema_not_honored(call_id, idx) if dispatch is None: return dispatch( @@ -607,7 +616,7 @@ def emit_attempt( llm_attempt_index=idx, latency_ms=attempt_latency_ms, call_id=call_id, - request=_as_sent(reported, attempt_exc), + request=request, active_prompt=active_prompt, active_prompt_group=active_prompt_group, token_budget=(active_prompt.token_budget if active_prompt is not None else None), @@ -1169,6 +1178,24 @@ def _build_llm_retry_attempt_event( **response_fields, ) + def _warn_schema_not_honored(self, call_id: str, attempt_index: int) -> None: + _log.warning( + "%s returned content that is not a JSON object on the native structured-output " + "path (call %s, attempt %d): the schema constraint did not reach or bind the model", + self.model, + call_id, + attempt_index, + extra={ + **diagnostic(STRUCTURED_OUTPUT_SCHEMA_NOT_HONORED), + "openarmature.llm.provider": self._genai_system, + # observability §5.5.7: the bound model, as the span's + # openarmature.llm.model, not the one the response reports. + "openarmature.llm.model": self.model, + "openarmature.llm.call_id": call_id, + "openarmature.llm.attempt_index": attempt_index, + }, + ) + async def _do_complete( self, body: dict[str, Any], @@ -1572,6 +1599,41 @@ def _as_sent(request: _EventRequest, exc: LlmProviderError | None) -> _EventRequ return request +# observability §5.5.7: an attempt on the native path that finished normally, +# with no stop sequence to end it early, returned content that is not a JSON +# object. A constraint that bound cannot produce that, since llm-provider §5 +# requires an object at the schema's top level. +def _schema_not_honored(request: _EventRequest, exc: LlmProviderError | None, *, stop_sent: bool) -> bool: + return ( + isinstance(exc, StructuredOutputInvalid) + and request.structured_output_path == "native" + and exc.finish_reason == "stop" + and not stop_sent + and not _is_json_object(exc.output_content) + ) + + +# A matched stop sequence also reports "stop", so §5.5.7 skips an attempt whose +# request carried one. Read from the body as sent, after the extras' `stop` has +# been merged into the declared list or dropped as malformed. OpenAI's `stop` is +# a string or a list, and only an empty list carries none. +def _carries_stop_sequence(stop: Any) -> bool: + return isinstance(stop, str) or (isinstance(stop, list) and len(cast("list[Any]", stop)) > 0) + + +# Read as the validation reads it, so NaN, a number past a float's range or +# nesting too deep to parse is malformed here too. +def _is_json_object(content: str) -> bool: + try: + return isinstance(_load_json(content), dict) + except (ValueError, RecursionError): + return False + + +def _load_json(content: str) -> Any: + return json.loads(content, parse_constant=_reject_non_json_constant, parse_float=_finite_float) + + # Parse the model's content string as JSON, then validate it against the # schema. The dict-schema path returns the dict; the BaseModel-class path then # runs the class's own validation, which produces the instance. @@ -1581,7 +1643,7 @@ def _parse_and_validate( schema_class: type[BaseModel] | None, ) -> ParsedValue: try: - loaded = json.loads(content, parse_constant=_reject_non_json_constant, parse_float=_finite_float) + loaded = _load_json(content) except (ValueError, RecursionError) as exc: raise StructuredOutputInvalid( "response content is not valid JSON", diff --git a/src/openarmature/observability/__init__.py b/src/openarmature/observability/__init__.py index d85376c..1499280 100644 --- a/src/openarmature/observability/__init__.py +++ b/src/openarmature/observability/__init__.py @@ -39,6 +39,7 @@ LANGFUSE_PAYLOAD_SUPPRESSED, LANGFUSE_SHARED_PROVIDER_ACCEPTED, LANGFUSE_SHARED_PROVIDER_NO_PAYLOAD, + STRUCTURED_OUTPUT_SCHEMA_NOT_HONORED, TOKEN_BUDGET_EXCEEDED, event_name_of, ) @@ -67,6 +68,7 @@ "LANGFUSE_PAYLOAD_SUPPRESSED", "LANGFUSE_SHARED_PROVIDER_ACCEPTED", "LANGFUSE_SHARED_PROVIDER_NO_PAYLOAD", + "STRUCTURED_OUTPUT_SCHEMA_NOT_HONORED", "TOKEN_BUDGET_EXCEEDED", "ToolCallScope", "current_active_observers", diff --git a/src/openarmature/observability/diagnostics.py b/src/openarmature/observability/diagnostics.py index b98f06c..42cc3ce 100644 --- a/src/openarmature/observability/diagnostics.py +++ b/src/openarmature/observability/diagnostics.py @@ -24,6 +24,7 @@ LANGFUSE_SHARED_PROVIDER_ACCEPTED = "openarmature.langfuse.shared_provider_accepted" LANGFUSE_PAYLOAD_SUPPRESSED = "openarmature.langfuse.payload_suppressed" LANGFUSE_SHARED_PROVIDER_NO_PAYLOAD = "openarmature.langfuse.shared_provider_no_payload" +STRUCTURED_OUTPUT_SCHEMA_NOT_HONORED = "openarmature.structured_output.schema_not_honored" TOKEN_BUDGET_EXCEEDED = "openarmature.token_budget.exceeded" # The stdlib LogRecord attribute the name rides on. `install_log_bridge` lifts @@ -58,6 +59,7 @@ def event_name_of(record: logging.LogRecord) -> str | None: "LANGFUSE_PAYLOAD_SUPPRESSED", "LANGFUSE_SHARED_PROVIDER_ACCEPTED", "LANGFUSE_SHARED_PROVIDER_NO_PAYLOAD", + "STRUCTURED_OUTPUT_SCHEMA_NOT_HONORED", "TOKEN_BUDGET_EXCEEDED", "diagnostic", "event_name_of", diff --git a/tests/unit/test_llm_provider.py b/tests/unit/test_llm_provider.py index 22d4574..46e1106 100644 --- a/tests/unit/test_llm_provider.py +++ b/tests/unit/test_llm_provider.py @@ -66,6 +66,7 @@ _set_invocation_id, _set_namespace_prefix, ) +from openarmature.observability.diagnostics import STRUCTURED_OUTPUT_SCHEMA_NOT_HONORED, event_name_of from openarmature.observability.metadata import set_invocation_metadata _DispatchToken = Token[Callable[[ObserverEvent], None] | None] @@ -2642,6 +2643,332 @@ def handler(_req: httpx.Request) -> httpx.Response: assert completion.structured_output_path == "native" +# --------------------------------------------------------------------------- +# A schema the provider did not honor (observability §5.5.7, proposal 0126) +# --------------------------------------------------------------------------- + +_PROSE = "Alice is thirty" +_REASK = "Return only the JSON object." + + +def _replies(*replies: tuple[str, str]) -> Callable[[httpx.Request], httpx.Response]: + # Each wire attempt takes the next (content, finish_reason). The response + # names a dated model, which the record must not report. + calls = [0] + + def handler(_req: httpx.Request) -> httpx.Response: + content, finish_reason = replies[calls[0]] + calls[0] += 1 + return httpx.Response( + 200, + json={ + "id": f"cc-{calls[0]}", + "object": "chat.completion", + "model": "gpt-test-2026-01-01", + "choices": [ + { + "index": 0, + "message": {"role": "assistant", "content": content}, + "finish_reason": finish_reason, + } + ], + "usage": {"prompt_tokens": 5, "completion_tokens": 1, "total_tokens": 6}, + }, + ) + + return handler + + +def _not_honored(caplog: pytest.LogCaptureFixture) -> list[logging.LogRecord]: + # Every record carrying the name, at any level, so a second record at + # another level fails a count. + return [r for r in caplog.records if event_name_of(r) == STRUCTURED_OUTPUT_SCHEMA_NOT_HONORED] + + +@pytest.mark.parametrize( + ("content", "finish_reason", "schema", "config", "fallback", "emitted"), + [ + pytest.param(_PROSE, "stop", _PERSON_SCHEMA, None, False, True, id="prose"), + pytest.param("[1, 2]", "stop", _PERSON_SCHEMA, None, False, True, id="array"), + pytest.param('{"name": NaN}', "stop", _PERSON_SCHEMA, None, False, True, id="nan-is-malformed"), + pytest.param( + '{"name": "Alice"}', "stop", _PERSON_SCHEMA, None, False, False, id="object-failing-schema" + ), + pytest.param('{"name": "Ali', "length", _PERSON_SCHEMA, None, False, False, id="length"), + pytest.param(_PROSE, "content_filter", _PERSON_SCHEMA, None, False, False, id="content-filter"), + pytest.param( + _PROSE, + "stop", + _PERSON_SCHEMA, + RuntimeConfig(stop_sequences=["END"]), + False, + False, + id="declared-stop", + ), + pytest.param( + _PROSE, + "stop", + _PERSON_SCHEMA, + RuntimeConfig(extras={"stop": ["END"]}), + False, + False, + id="extras-stop", + ), + pytest.param( + _PROSE, + "stop", + _PERSON_SCHEMA, + RuntimeConfig(extras={"stop": "END"}), + False, + False, + id="extras-stop-string", + ), + pytest.param( + _PROSE, + "stop", + _PERSON_SCHEMA, + RuntimeConfig(stop_sequences=[]), + False, + True, + id="empty-declared-stop", + ), + pytest.param( + _PROSE, + "stop", + _PERSON_SCHEMA, + RuntimeConfig(extras={"stop": []}), + False, + True, + id="empty-extras-stop", + ), + pytest.param( + _PROSE, + "stop", + _PERSON_SCHEMA, + RuntimeConfig(stop_sequences=[], extras={"stop": [123]}), + False, + True, + id="malformed-extras-stop-dropped", + ), + pytest.param( + _PROSE, + "stop", + _PERSON_SCHEMA, + RuntimeConfig(extras={"stop": ""}), + False, + False, + id="empty-string-extras-stop", + ), + pytest.param( + _PROSE, + "stop", + _PERSON_SCHEMA, + RuntimeConfig(stop_sequences=[], extras={"stop": ""}), + False, + False, + id="empty-string-merged-into-empty-list", + ), + pytest.param(_PROSE, "stop", _LOOSE_SCHEMA, None, False, False, id="native-unenforced"), + pytest.param(_PROSE, "stop", _PERSON_SCHEMA, None, True, False, id="prompt-augmentation"), + ], +) +async def test_the_record_fires_only_for_malformed_content_on_a_normal_native_finish( + caplog: pytest.LogCaptureFixture, + content: str, + finish_reason: str, + schema: dict[str, Any], + config: RuntimeConfig | None, + fallback: bool, + emitted: bool, +) -> None: + # observability §5.5.7, as fixture 161 cases 1 to 8, 15 and 18 exercise it. + # No invocation is active, so the cases that emit also show the record does + # not wait for an observer (case 14): moving the check after the dispatch + # check fails every one of them. NaN is malformed because the check reads + # content the way the validation does. The stop cases read the body as + # sent: a malformed extra beside a declared list is dropped, so none goes + # out, and any string is a sequence, since only an empty list carries none. + caplog.set_level(logging.DEBUG) + provider = OpenAIProvider( + base_url="http://test", + model="m", + api_key="k", + transport=httpx.MockTransport(_replies((content, finish_reason))), + force_prompt_augmentation_fallback=fallback, + ) + try: + with pytest.raises(StructuredOutputInvalid): + await provider.complete([UserMessage(content="go")], config=config, response_schema=schema) + finally: + await provider.aclose() + + assert len(_not_honored(caplog)) == (1 if emitted else 0) + + +async def test_the_record_names_the_call_its_attempt_and_the_bound_model( + caplog: pytest.LogCaptureFixture, +) -> None: + # observability §5.5.7: one WARNING record carrying the provider, the bound + # model rather than the dated one the response reports, the call id that + # joins it to the call's typed event, and the attempt's index. The provider + # is not the default, so a hardcoded "openai" fails. + caplog.set_level(logging.DEBUG) + events, token = _collecting_dispatch() + provider = OpenAIProvider( + base_url="http://test", + model="m", + api_key="k", + transport=httpx.MockTransport(_replies((_PROSE, "stop"))), + genai_system="vllm", + ) + try: + with pytest.raises(StructuredOutputInvalid): + await provider.complete([UserMessage(content="go")], response_schema=_PERSON_SCHEMA) + finally: + await provider.aclose() + _release_dispatch(token) + + failed = next(e for e in events if isinstance(e, LlmFailedEvent)) + [record] = _not_honored(caplog) + assert record.levelno == logging.WARNING + assert getattr(record, "openarmature.llm.provider") == "vllm" + assert getattr(record, "openarmature.llm.model") == "m" + assert getattr(record, "openarmature.llm.call_id") == failed.call_id + assert getattr(record, "openarmature.llm.attempt_index") == 0 + + +async def test_a_refusal_openai_reports_as_stop_emits_no_record(caplog: pytest.LogCaptureFixture) -> None: + # Fixture 161 case 16: OpenAI reports a refusal with finish_reason "stop", + # and the mapping reports it as "content_filter" (llm-provider §8.1.6). The + # check reads the mapped value, so the refusal text, which is not JSON, + # emits nothing. + def handler(_req: httpx.Request) -> httpx.Response: + return httpx.Response( + 200, + json={ + "id": "cc-refusal", + "object": "chat.completion", + "model": "gpt-test", + "choices": [ + { + "index": 0, + "message": { + "role": "assistant", + "content": None, + "refusal": "I can't help with that.", + }, + "finish_reason": "stop", + } + ], + "usage": {"prompt_tokens": 5, "completion_tokens": 1, "total_tokens": 6}, + }, + ) + + caplog.set_level(logging.DEBUG) + provider = OpenAIProvider( + base_url="http://test", model="m", api_key="k", transport=httpx.MockTransport(handler) + ) + try: + with pytest.raises(StructuredOutputInvalid) as raised: + await provider.complete([UserMessage(content="go")], response_schema=_PERSON_SCHEMA) + finally: + await provider.aclose() + + assert raised.value.finish_reason == "content_filter" + assert _not_honored(caplog) == [] + + +async def test_a_reask_that_recovers_still_records_the_failed_attempt( + caplog: pytest.LogCaptureFixture, +) -> None: + # Fixture 161 case 12: the check runs per attempt, so attempt 1's valid + # answer does not hide attempt 0's prose, and the valid attempt itself + # emits nothing. + from openarmature.llm import LlmRetryConfig + + caplog.set_level(logging.DEBUG) + provider = OpenAIProvider( + base_url="http://test", + model="m", + api_key="k", + transport=httpx.MockTransport(_replies((_PROSE, "stop"), ('{"name": "Alice", "age": 30}', "stop"))), + ) + try: + response = await provider.complete( + [UserMessage(content="go")], + response_schema=_PERSON_SCHEMA, + retry=LlmRetryConfig(max_attempts=2, backoff=deterministic_backoff(0), reask=lambda _e: _REASK), + ) + finally: + await provider.aclose() + + assert response.parsed == {"name": "Alice", "age": 30} + assert [getattr(r, "openarmature.llm.attempt_index") for r in _not_honored(caplog)] == [0] + + +async def test_each_attempt_that_qualifies_gets_its_own_record(caplog: pytest.LogCaptureFixture) -> None: + # Fixture 161 case 19: two attempts return prose, so there are two records, + # each with its own attempt's index and both with the call's id. + from openarmature.llm import LlmRetryConfig + + caplog.set_level(logging.DEBUG) + provider = OpenAIProvider( + base_url="http://test", + model="m", + api_key="k", + transport=httpx.MockTransport(_replies((_PROSE, "stop"), (_PROSE, "stop"))), + ) + try: + with pytest.raises(StructuredOutputInvalid): + await provider.complete( + [UserMessage(content="go")], + response_schema=_PERSON_SCHEMA, + retry=LlmRetryConfig( + max_attempts=2, backoff=deterministic_backoff(0), reask=lambda _e: _REASK + ), + ) + finally: + await provider.aclose() + + records = _not_honored(caplog) + assert [getattr(r, "openarmature.llm.attempt_index") for r in records] == [0, 1] + assert len({getattr(r, "openarmature.llm.call_id") for r in records}) == 1 + + +async def test_a_stop_sequence_on_one_attempt_suppresses_only_its_record( + caplog: pytest.LogCaptureFixture, +) -> None: + # Fixture 161 case 13: the override adds a stop sequence to attempt 1 only. + # Both attempts return prose, and only attempt 0 is recorded, since the + # check reads each attempt's own request. Reading the base config instead + # adds a record for attempt 1, and only this test catches that. + from openarmature.llm import LlmRetryConfig + + caplog.set_level(logging.DEBUG) + provider = OpenAIProvider( + base_url="http://test", + model="m", + api_key="k", + transport=httpx.MockTransport(_replies((_PROSE, "stop"), (_PROSE, "stop"))), + ) + try: + with pytest.raises(StructuredOutputInvalid): + await provider.complete( + [UserMessage(content="go")], + response_schema=_PERSON_SCHEMA, + retry=LlmRetryConfig( + max_attempts=2, + backoff=deterministic_backoff(0), + reask=lambda _e: _REASK, + per_attempt_override=[RuntimeConfig(stop_sequences=["END"])], + ), + ) + finally: + await provider.aclose() + + assert [getattr(r, "openarmature.llm.attempt_index") for r in _not_honored(caplog)] == [0] + + # --------------------------------------------------------------------------- # Proposal 0058: per-category field-mapping + pre-send + mutual exclusion # --------------------------------------------------------------------------- diff --git a/tests/unit/test_observability_otel.py b/tests/unit/test_observability_otel.py index e72e387..6f2232e 100644 --- a/tests/unit/test_observability_otel.py +++ b/tests/unit/test_observability_otel.py @@ -6717,6 +6717,91 @@ def emit(self, record: logging.LogRecord) -> None: assert event_name_of(breaches[0]) == TOKEN_BUDGET_EXCEEDED +async def test_the_schema_not_honored_record_reaches_the_otel_log_with_its_fields() -> None: + # observability §5.5.7 and §7: the provider's record arrives through the + # bridge with its event name on the OTel field, the four attributes and the + # correlation id. Driven through the provider, so the emitter's own extra= + # is what is checked. + import httpx + from opentelemetry._logs import SeverityNumber + from opentelemetry.sdk._logs import LoggerProvider + from opentelemetry.sdk._logs.export import ( + InMemoryLogRecordExporter, + SimpleLogRecordProcessor, + ) + + from openarmature.llm.errors import StructuredOutputInvalid + from openarmature.llm.messages import UserMessage + from openarmature.llm.providers.openai import OpenAIProvider + from openarmature.observability.correlation import ( + _reset_correlation_id, + _set_correlation_id, + ) + from openarmature.observability.diagnostics import STRUCTURED_OUTPUT_SCHEMA_NOT_HONORED + + def handler(_req: httpx.Request) -> httpx.Response: + return httpx.Response( + 200, + json={ + "id": "cc-1", + "object": "chat.completion", + "model": "gpt-test", + "choices": [ + { + "index": 0, + "message": {"role": "assistant", "content": "Alice is thirty"}, + "finish_reason": "stop", + } + ], + "usage": {"prompt_tokens": 5, "completion_tokens": 1, "total_tokens": 6}, + }, + ) + + schema = { + "type": "object", + "properties": {"name": {"type": "string"}}, + "required": ["name"], + "additionalProperties": False, + } + root = logging.getLogger() + prior_handlers = list(root.handlers) + prior_level = root.level + prior_factory = logging.getLogRecordFactory() + exporter = InMemoryLogRecordExporter() + log_provider = LoggerProvider() + log_provider.add_log_record_processor(SimpleLogRecordProcessor(exporter)) + try: + install_log_bridge(log_provider) + root.setLevel(logging.INFO) + provider = OpenAIProvider( + base_url="http://test", model="gpt-test", api_key="k", transport=httpx.MockTransport(handler) + ) + token = _set_correlation_id("cid-not-honored") + try: + with pytest.raises(StructuredOutputInvalid): + await provider.complete([UserMessage(content="go")], response_schema=schema) + finally: + _reset_correlation_id(token) + await provider.aclose() + log_provider.force_flush() + + emitted = [d.log_record for d in exporter.get_finished_logs()] + records = [r for r in emitted if r.event_name == STRUCTURED_OUTPUT_SCHEMA_NOT_HONORED] + assert len(records) == 1, f"expected one record; got {[str(r.body) for r in emitted]}" + attrs = dict(records[0].attributes or {}) + assert records[0].severity_number == SeverityNumber.WARN + assert attrs["openarmature.llm.provider"] == "openai" + assert attrs["openarmature.llm.model"] == "gpt-test" + assert attrs["openarmature.llm.attempt_index"] == 0 + assert attrs["openarmature.llm.call_id"] + assert attrs["openarmature.correlation_id"] == "cid-not-honored" + finally: + root.handlers[:] = prior_handlers + root.setLevel(prior_level) + logging.setLogRecordFactory(prior_factory) + log_provider.shutdown() + + def test_event_name_bridge_degrades_when_the_upstream_seam_is_gone() -> None: # The lift subclasses the OTel handler's `_translate`, which is its private # surface. Once that method no longer exists, `super()._translate(...)`