From 2e2885cf37e33cf22b420254f64af31f055c5e51 Mon Sep 17 00:00:00 2001 From: chris-colinsky Date: Sat, 7 Nov 2026 10:58:29 -0800 Subject: [PATCH 1/2] Warn when a provider does not honor the schema A strict structured-output attempt that finishes on stop, with no stop sequence, and returns content that is not a JSON object is something constrained decoding cannot produce. Observability section 5.5.7 requires one WARNING record for each such attempt, carrying the event name openarmature.structured_output.schema_not_honored, the provider, the bound model, the call id and the attempt index. The OpenAI provider runs the check per wire attempt, ahead of the attempt event's dispatch, so it logs with or without an invocation or observers, and a reask that recovers still leaves the failed attempt's record. It reads each attempt's own request for the path and the stop sequences, the mapped finish_reason, and the content through the same strict parser the validation uses. The record is advisory: nothing is retried or switched to the fallback because of it. --- CHANGELOG.md | 2 + conformance.toml | 2 +- docs/concepts/llms.md | 11 + docs/concepts/observability.md | 1 + src/openarmature/llm/providers/openai.py | 67 +++- src/openarmature/observability/__init__.py | 2 + src/openarmature/observability/diagnostics.py | 2 + tests/unit/test_llm_provider.py | 298 ++++++++++++++++++ tests/unit/test_observability_otel.py | 85 +++++ 9 files changed, 465 insertions(+), 5 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index b876464f..04bb5a46 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 857f2ec0..2fdab71b 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 6b0b4259..c197a4a9 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 adb90c8b..58e550ed 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 e6261d97..cc13a173 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 @@ -591,8 +592,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 +601,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): + self._warn_schema_not_honored(call_id, idx) if dispatch is None: return dispatch( @@ -607,7 +614,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 +1176,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 +1597,40 @@ 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) -> bool: + return ( + isinstance(exc, StructuredOutputInvalid) + and request.structured_output_path == "native" + and exc.finish_reason == "stop" + and not _carries_stop_sequence(request) + and not _is_json_object(exc.output_content) + ) + + +# A matched stop sequence also reports "stop", so §5.5.7 reads both places a +# request can carry one: the declared field and §8.1's `stop` in extras. An +# empty list carries none. +def _carries_stop_sequence(request: _EventRequest) -> bool: + return bool(request.request_params.get("stop_sequences")) or bool(request.request_extras.get("stop")) + + +# 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 +1640,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 d85376c1..14992808 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 b98f06c2..42cc3ced 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 22d4574e..3b7714ba 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,303 @@ 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", _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. + 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 e72e3874..6f2232e7 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(...)` From a462227d61c85afbee149e43fe1de311b3f775a9 Mon Sep 17 00:00:00 2001 From: chris-colinsky Date: Sat, 7 Nov 2026 11:44:21 -0800 Subject: [PATCH 2/2] Read the stop sequence from the body as sent The schema_not_honored check decided whether an attempt carried a stop sequence from the config: the declared stop_sequences and the extras' stop. The request builder reconciles the two, so the config can disagree with the wire. With stop_sequences=[] and a malformed extras stop such as [123], the builder drops the extra and sends stop: [], yet the check saw a stop sequence and stayed silent. An extras stop of "" went out as a string while the check treated it as absent. The check now reads stop from the body each attempt built, and counts any string or non-empty list as a stop sequence, since observability section 5.5.7 exempts only an empty list. --- src/openarmature/llm/providers/openai.py | 21 +++++++++------- tests/unit/test_llm_provider.py | 31 +++++++++++++++++++++++- 2 files changed, 42 insertions(+), 10 deletions(-) diff --git a/src/openarmature/llm/providers/openai.py b/src/openarmature/llm/providers/openai.py index cc13a173..81fe9881 100644 --- a/src/openarmature/llm/providers/openai.py +++ b/src/openarmature/llm/providers/openai.py @@ -523,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, @@ -567,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. @@ -585,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 @@ -605,7 +607,7 @@ def emit_attempt( # 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): + if _schema_not_honored(request, attempt_exc, stop_sent=stop_sent): self._warn_schema_not_honored(call_id, idx) if dispatch is None: return @@ -1601,21 +1603,22 @@ def _as_sent(request: _EventRequest, exc: LlmProviderError | None) -> _EventRequ # 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) -> bool: +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 _carries_stop_sequence(request) + and not stop_sent and not _is_json_object(exc.output_content) ) -# A matched stop sequence also reports "stop", so §5.5.7 reads both places a -# request can carry one: the declared field and §8.1's `stop` in extras. An -# empty list carries none. -def _carries_stop_sequence(request: _EventRequest) -> bool: - return bool(request.request_params.get("stop_sequences")) or bool(request.request_extras.get("stop")) +# 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 diff --git a/tests/unit/test_llm_provider.py b/tests/unit/test_llm_provider.py index 3b7714ba..46e11065 100644 --- a/tests/unit/test_llm_provider.py +++ b/tests/unit/test_llm_provider.py @@ -2741,6 +2741,33 @@ def _not_honored(caplog: pytest.LogCaptureFixture) -> list[logging.LogRecord]: 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"), ], @@ -2758,7 +2785,9 @@ async def test_the_record_fires_only_for_malformed_content_on_a_normal_native_fi # 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. + # 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",