From 85d48f8936684d862b9cd82d7f37c80a92ff37d4 Mon Sep 17 00:00:00 2001 From: Brent Date: Mon, 20 Jul 2026 12:21:35 -0400 Subject: [PATCH] SMOODEV-2700: Fix Python log-level wire parity + add golden-vector parity corpus Python was the sole outlier across the five hand-written ports. It emitted a lowercase string in `level` ("info") and never emitted `LogLevel` at all, while TS/Go/Rust/.NET all emit BOTH: `level` = pino-compatible numeric, `LogLevel` = canonical lowercase string. This broke downstream log-level ingest: rust/api-prime's observability ingest takes the first matching level key, so our own services' numeric `level` (30) won the race over the unambiguous `LogLevel` ("info") -- which is why prod shows a mixed bag of levels: ['30','40','ERROR','INFO','WARN']. Python now emits both. The numeric codes already existed in `level_to_code()` (trace=10 .. fatal=60); they were simply never written to the record. This is a BREAKING wire-shape change for Python consumers reading `level` as a string -- they should read `LogLevel` instead. Changeset documents the migration. Five hand-written implementations WILL drift; this bug is the proof. Adds `parity-corpus.json`, a committed golden-vector corpus pinning the exact level/LogLevel pair every port must emit for all six levels, asserted by the TS and Python suites so drift fails that language's build. Follows the ADR-089 pattern used by @smooai/audit. Go/Rust/.NET lanes are NOT yet wired -- see the corpus file; wiring them is mechanical and separately scoped. Verified .NET already writes both (SmooLogger.cs:431-432) -- no fix needed. The uvicorn adapter's uppercase "level": "INFO" is a stdlib logging dictConfig threshold, not wire output, and is correctly left alone. Co-Authored-By: Claude Opus 4.8 Claude-Session: https://claude.ai/code/session_01S2bM94GAnVjYSSv1x7HKRB --- .changeset/tidy-pugs-repeat.md | 26 +++++++++++ parity-corpus.json | 29 ++++++++++++ python/src/smooai_logger/logger.py | 14 +++++- python/tests/test_aws_logger.py | 3 +- python/tests/test_logger.py | 24 +++++++--- python/tests/test_parity_corpus.py | 55 +++++++++++++++++++++++ src/parity-corpus.spec.ts | 71 ++++++++++++++++++++++++++++++ 7 files changed, 212 insertions(+), 10 deletions(-) create mode 100644 .changeset/tidy-pugs-repeat.md create mode 100644 parity-corpus.json create mode 100644 python/tests/test_parity_corpus.py create mode 100644 src/parity-corpus.spec.ts diff --git a/.changeset/tidy-pugs-repeat.md b/.changeset/tidy-pugs-repeat.md new file mode 100644 index 00000000..796e3ea4 --- /dev/null +++ b/.changeset/tidy-pugs-repeat.md @@ -0,0 +1,26 @@ +--- +"@smooai/logger": minor +--- + +Fix Python log-level wire parity with the TS/Go/Rust/.NET ports, and add a golden-vector parity corpus. + +**BREAKING for Python consumers that read the `level` field.** The Python port +was the sole outlier across the five implementations: it emitted a lowercase +string in `level` (`"info"`) and never emitted `LogLevel` at all. Every other +port emits both fields. Python now matches: + +| field | value | +| ---------- | -------------------------------------- | +| `level` | pino-compatible **numeric** (info = 30) | +| `LogLevel` | canonical lowercase **string** (`"info"`) | + +Migration for Python consumers: anything asserting `record["level"] == "info"` +should read `record["LogLevel"] == "info"` instead. The numeric codes were +already defined in `level_to_code()` (trace=10 … fatal=60) and are unchanged; +they were simply never written to the record. + +Also adds `parity-corpus.json` — a committed golden-vector corpus pinning the +exact `level`/`LogLevel` pair every port must emit for all six levels, asserted +by the TypeScript (`src/parity-corpus.spec.ts`) and Python +(`python/tests/test_parity_corpus.py`) suites so drift fails the build. +Follows the ADR-089 pattern used by `@smooai/audit`. diff --git a/parity-corpus.json b/parity-corpus.json new file mode 100644 index 00000000..bf09df82 --- /dev/null +++ b/parity-corpus.json @@ -0,0 +1,29 @@ +{ + "$comment": [ + "Golden-vector parity corpus for @smooai/logger's five hand-written ports", + "(TypeScript, Go, Python, Rust, .NET). Pattern follows ADR-089 (@smooai/audit).", + "", + "Every port MUST emit BOTH fields on every record:", + " level -> pino-compatible NUMERIC code", + " LogLevel -> canonical lowercase STRING", + "", + "Downstream (rust/api-prime observability log ingest) keys off LogLevel because", + "it is unambiguous; the numeric `level` is retained for pino-compatible tooling.", + "", + "This file is the contract. Do NOT edit expected values to make a test pass --", + "a failure here means a port has drifted and the PORT is what needs fixing." + ], + "version": 1, + "fields": { + "level": "pino-compatible numeric code", + "LogLevel": "canonical lowercase string" + }, + "levels": [ + { "name": "trace", "LogLevel": "trace", "level": 10 }, + { "name": "debug", "LogLevel": "debug", "level": 20 }, + { "name": "info", "LogLevel": "info", "level": 30 }, + { "name": "warn", "LogLevel": "warn", "level": 40 }, + { "name": "error", "LogLevel": "error", "level": 50 }, + { "name": "fatal", "LogLevel": "fatal", "level": 60 } + ] +} diff --git a/python/src/smooai_logger/logger.py b/python/src/smooai_logger/logger.py index 5cda3d89..0bc9d5e6 100644 --- a/python/src/smooai_logger/logger.py +++ b/python/src/smooai_logger/logger.py @@ -201,7 +201,13 @@ class LambdaEnvContext(TypedDict, total=False): class Context(TypedDict, total=False): - level: str | None + # Level wire contract, shared with the TS/Go/Rust/.NET ports (parity-corpus.json): + # level -> pino-compatible NUMERIC code (int) + # LogLevel -> canonical lowercase STRING + # `level` stays `int | str` because _emit() is a pure serializer and callers may + # hand it a pre-built record; _build_record always writes the numeric form. + level: int | str | None + LogLevel: str | None msg: str | None time: str | None name: str | None @@ -626,7 +632,11 @@ def _build_record(self, lvl: Level, args: list[Any]) -> Context: ] if msgs: rec["msg"] = "; ".join(msgs) - rec["level"] = lvl.value + # Wire contract shared with the TS/Go/Rust/.NET ports (see parity-corpus.json): + # level -> pino-compatible NUMERIC code + # LogLevel -> canonical lowercase STRING + rec["level"] = level_to_code(lvl) + rec["LogLevel"] = lvl.value rec["time"] = now().isoformat() rec["name"] = self._name # reorder keys: msg, time, error, errorDetails, errors first diff --git a/python/tests/test_aws_logger.py b/python/tests/test_aws_logger.py index b6683334..bfd1e6b0 100644 --- a/python/tests/test_aws_logger.py +++ b/python/tests/test_aws_logger.py @@ -406,7 +406,8 @@ def test_aws_lambda_logger_full_workflow(self, mock_stdout): # Check the error log entry error_log = json.loads(lines[1]) assert error_log.get("msg") == "Integration test failed" - assert error_log.get("level") == "error" + assert error_log.get("level") == 50 + assert error_log.get("LogLevel") == "error" assert error_log.get("name") == "IntegrationTest" assert error_log.get("service") == "aws-service" assert error_log.get("version") == "2.0.0" diff --git a/python/tests/test_logger.py b/python/tests/test_logger.py index b30ae117..85fa3220 100644 --- a/python/tests/test_logger.py +++ b/python/tests/test_logger.py @@ -181,7 +181,8 @@ def test_logger_build_record_with_string(self): record = logger._build_record(Level.INFO, ["Test message"]) assert record.get("msg") == "Test message" - assert record.get("level") == "info" + assert record.get("level") == 30 + assert record.get("LogLevel") == "info" assert record.get("name") == "TestLogger" assert "time" in record assert "correlationId" in record @@ -193,7 +194,8 @@ def test_logger_build_record_with_exception(self): record = logger._build_record(Level.ERROR, [exception]) assert record.get("error") == "Test error" - assert record.get("level") == "error" + assert record.get("level") == 50 + assert record.get("LogLevel") == "error" error_details = record.get("errorDetails") assert error_details is not None assert len(error_details) == 1 @@ -283,7 +285,8 @@ def test_logger_build_record_with_multiple_args(self): assert context is not None assert context["key"] == "value" assert record.get("error") == "Something went wrong" - assert record.get("level") == "warn" + assert record.get("level") == 40 + assert record.get("LogLevel") == "warn" @patch("sys.stdout", new_callable=StringIO) def test_logger_emit_json(self, mock_stdout): @@ -295,6 +298,9 @@ def test_logger_emit_json(self, mock_stdout): output = mock_stdout.getvalue() parsed = json.loads(output.strip()) assert parsed["msg"] == "Test message" + # _emit is a pure serializer -- it echoes the record it is given verbatim. + # The level wire-shape contract is built in _build_record and is asserted + # by tests/test_parity_corpus.py against parity-corpus.json. assert parsed["level"] == "info" @patch("sys.stdout", new_callable=StringIO) @@ -317,7 +323,8 @@ def test_logger_info_method(self, mock_stdout): output = mock_stdout.getvalue() parsed = json.loads(output.strip()) assert parsed["msg"] == "Test info message" - assert parsed["level"] == "info" + assert parsed["level"] == 30 + assert parsed["LogLevel"] == "info" @patch("sys.stdout", new_callable=StringIO) def test_logger_debug_method_enabled(self, mock_stdout): @@ -327,7 +334,8 @@ def test_logger_debug_method_enabled(self, mock_stdout): output = mock_stdout.getvalue() parsed = json.loads(output.strip()) assert parsed["msg"] == "Test debug message" - assert parsed["level"] == "debug" + assert parsed["level"] == 20 + assert parsed["LogLevel"] == "debug" @patch("sys.stdout", new_callable=StringIO) def test_logger_debug_method_disabled(self, mock_stdout): @@ -354,7 +362,8 @@ def test_logger_all_level_methods(self, mock_stdout): assert len(lines) == 6 for i, level in enumerate(["trace", "debug", "info", "warn", "error", "fatal"]): parsed = json.loads(lines[i]) - assert parsed["level"] == level + assert parsed["LogLevel"] == level + assert parsed["level"] == level_to_code(Level(level)) def test_logger_context_merging(self): initial_context = cast(Context, cast(object, {"correlationId": "initial", "custom": "value"})) @@ -444,7 +453,8 @@ def test_logger_full_workflow(self, mock_stdout): # Verify all components are present assert parsed["msg"] == "Integration test failed" - assert parsed["level"] == "error" + assert parsed["level"] == 50 + assert parsed["LogLevel"] == "error" assert parsed["name"] == "IntegrationTest" assert parsed["service"] == "test-service" assert parsed["version"] == "1.0.0" diff --git a/python/tests/test_parity_corpus.py b/python/tests/test_parity_corpus.py new file mode 100644 index 00000000..063941de --- /dev/null +++ b/python/tests/test_parity_corpus.py @@ -0,0 +1,55 @@ +"""Golden-vector parity corpus (ADR-089 pattern, as used by @smooai/audit). + +Asserts the Python port emits the level wire-shape every other port +(TypeScript / Go / Rust / .NET) is also held to. A failure here means either +this port drifted or the shared contract moved -- fix the port, not the corpus. +""" + +import io +import json +from pathlib import Path +from typing import Any +from unittest.mock import patch + +import pytest + +from smooai_logger.logger import Level, Logger + +CORPUS_PATH = Path(__file__).resolve().parents[2] / "parity-corpus.json" +CORPUS: dict[str, Any] = json.loads(CORPUS_PATH.read_text()) +LEVELS: list[dict[str, Any]] = CORPUS["levels"] + + +def _emit(level_name: str) -> dict[str, Any]: + """Emit one record at `level_name` and return the parsed JSON payload.""" + logger = Logger(name="ParityCorpus", level=Level.TRACE, pretty_print=False, log_to_file=False) + with patch("sys.stdout", new_callable=io.StringIO) as mock_stdout: + getattr(logger, level_name)("parity corpus probe") + output = mock_stdout.getvalue() + lines = [line for line in output.strip().split("\n") if line] + assert len(lines) == 1, f"expected exactly one record, got {len(lines)}" + return json.loads(lines[0]) + + +def test_corpus_covers_all_six_levels() -> None: + assert len(LEVELS) == 6 + assert [entry["name"] for entry in LEVELS] == ["trace", "debug", "info", "warn", "error", "fatal"] + + +@pytest.mark.parametrize("entry", LEVELS, ids=[e["name"] for e in LEVELS]) +def test_level_wire_shape_matches_corpus(entry: dict[str, Any]) -> None: + record = _emit(entry["name"]) + + # level -> pino-compatible NUMERIC code + assert record["level"] == entry["level"] + assert isinstance(record["level"], int) and not isinstance(record["level"], bool) + + # LogLevel -> canonical lowercase STRING + assert record["LogLevel"] == entry["LogLevel"] + assert isinstance(record["LogLevel"], str) + + +def test_both_fields_present_on_every_record() -> None: + record = _emit("info") + assert "level" in record, "numeric `level` must not be dropped" + assert "LogLevel" in record, "canonical `LogLevel` string must not be dropped" diff --git a/src/parity-corpus.spec.ts b/src/parity-corpus.spec.ts new file mode 100644 index 00000000..c6024f66 --- /dev/null +++ b/src/parity-corpus.spec.ts @@ -0,0 +1,71 @@ +/* eslint-disable @typescript-eslint/no-explicit-any */ +import { readFileSync } from "node:fs"; +import { join } from "node:path"; +import { describe, expect, test } from "vitest"; +import Logger, { ContextKey, Level } from "./Logger"; + +/** + * Golden-vector parity corpus (ADR-089 pattern, as used by @smooai/audit). + * + * Asserts the TypeScript port emits the level wire-shape every other port + * (Go / Python / Rust / .NET) is also held to. A failure here means either + * this port drifted or the shared contract moved -- fix the port, not the + * corpus. + */ + +type CorpusLevel = { name: string; LogLevel: string; level: number }; +type Corpus = { version: number; levels: CorpusLevel[] }; + +const corpus: Corpus = JSON.parse( + readFileSync(join(__dirname, "..", "parity-corpus.json"), "utf8"), +); + +/** Captures the built log object instead of writing it to stdout. */ +class CapturingLogger extends Logger { + public captured: any[] = []; + protected override logFunc = (args: any[]) => { + this.captured.push(...args); + }; +} + +describe("parity corpus: level wire shape", () => { + test("corpus is non-empty and covers all six levels", () => { + expect(corpus.levels).toHaveLength(6); + expect(corpus.levels.map((l) => l.name)).toEqual([ + "trace", + "debug", + "info", + "warn", + "error", + "fatal", + ]); + }); + + test.each(corpus.levels)( + "$name emits level=$level and LogLevel=$LogLevel", + ({ name, level, LogLevel }) => { + const logger = new CapturingLogger({ context: {}, level: Level.Trace }); + (logger as any)[name]("parity corpus probe"); + + expect(logger.captured).toHaveLength(1); + const record = logger.captured[0]; + + // level -> pino-compatible NUMERIC code + expect(record[ContextKey.Level]).toBe(level); + expect(typeof record[ContextKey.Level]).toBe("number"); + + // LogLevel -> canonical lowercase STRING + expect(record[ContextKey.LogLevel]).toBe(LogLevel); + expect(typeof record[ContextKey.LogLevel]).toBe("string"); + }, + ); + + test("both fields are present on every record (neither may be dropped)", () => { + const logger = new CapturingLogger({ context: {}, level: Level.Trace }); + logger.info("parity corpus probe"); + const record = logger.captured[0]; + expect(Object.keys(record)).toEqual( + expect.arrayContaining([ContextKey.Level, ContextKey.LogLevel]), + ); + }); +});