fix: emit one physical line per rendered structlog event (#194)

* fix: emit one physical line per rendered structlog event

`MemoryLoggerFactory` attached a bare `StreamHandler`, so the default
`logging.Formatter` appended `record.exc_text` after the rendered JSON.
`logging.Logger.exception` hardcodes `exc_info=True`, so every
`structlog.get_logger().exception(...)` shipped the traceback twice.

Give that handler a formatter that emits the rendered line verbatim.

Closes #193

* docs: name the rendered line and record why wrap_for_formatter is out

`CONTEXT.md` had no word for the producer's JSON string, so the invariant
added in the previous commit asserts a relationship between two concepts
the glossary does not name.

ADR-0008 gains the rejected alternative, since `wrap_for_formatter` is
that ADR's constraint biting a second time rather than a new decision.

Author: lesnik512

CONTEXT.md

@@ -50,3 +50,10 @@ Without a web framework — `FreeBootstrapper`, `FreeConfig`, the `free-all` ext
 application, so nothing to attach teardown to and no double-bootstrap guard.
 _Avoid_: bare "free" for PEP 703 free-threaded CPython, which this project also supports. Write
 "free-threaded" in full.
+
+**Rendered line**:
+The complete JSON string the logging instrument produces for one event — message, level, metadata
+and traceback together. One event is one rendered line is one physical line of stdout; the three
+never diverge.
+_Avoid_: formatted message — reserve that for Sentry's own `logentry.formatted` field, which holds
+a rendered line only until the seam lifts the message out of it.

docs/adr/0008-structlog-sentry-seam-stays-a-heuristic.md

@@ -31,6 +31,16 @@ drift impossible, and would change the emitted log shape for every user. The del
 top-level meta-processor whose key is not added to `STRUCTLOG_META_KEYS` still leaks, and that is a
 known, accepted limit.
 
+**Deferring the render to `ProcessorFormatter.wrap_for_formatter`.** This is structlog's own
+idiomatic stdlib integration, it is already what `_configure_foreign_loggers` uses ten lines away,
+and it was the obvious fix for #193's double-rendered traceback. It is incompatible with this seam.
+`wrap_for_formatter` moves rendering to handler-flush time, so `record.msg` is the `EventDict`
+rather than a rendered line; `sentry_sdk` builds `logentry.formatted` from `record.getMessage()`,
+which for a dict `msg` is a Python repr. That repr opens with `{`, so `StructuredLogPayload.parse`
+accepts it, fails to decode it, and returns `None` — `skip_sentry` stops being honoured and
+`contexts.structlog` stops being attached, with nothing failing. The seam requires that the line
+be rendered before it becomes a `LogRecord`; anything downstream of the chain is transport only.
+
 `IGNORED_STRUCTLOG_ATTRIBUTES` survives in `sentry_instrument.py` as a silent alias of
 `STRUCTLOG_META_KEYS` for external importers of the old name.
 

lite_bootstrap/instruments/logging_factory.py

@@ -96,6 +96,13 @@ def parse(cls, formatted: str) -> "StructuredLogPayload | None":
         return cls(message=message, extra=extra, skip_sentry=skip_sentry)
 
 
+class _RenderedLineFormatter(logging.Formatter):
+    """Emit the rendered line verbatim; stdlib appends nothing after it."""
+
+    def format(self, record: logging.LogRecord) -> str:
+        return record.getMessage()
+
+
 if import_checker.is_structlog_installed:
     import structlog
 
@@ -113,6 +120,7 @@ def __init__(
         def __call__(self, *args: typing.Any) -> logging.Logger:  # noqa: ANN401
             logger: typing.Final = super().__call__(*args)
             stream_handler: typing.Final = logging.StreamHandler(stream=self.config.log_stream)
+            stream_handler.setFormatter(_RenderedLineFormatter())
             handler: typing.Final = logging.handlers.MemoryHandler(
                 capacity=self.config.logging_buffer_capacity,
                 flushLevel=self.config.logging_flush_level,

tests/instruments/test_logging_instrument.py

@@ -1,4 +1,5 @@
 import contextlib
+import json
 import logging
 from io import StringIO
 from unittest.mock import patch
@@ -227,3 +228,57 @@ def test_logging_instrument_binds_log_stream_at_bootstrap() -> None:
         logging_instrument.teardown()
 
     assert "bound at bootstrap" in redirected_stdout.getvalue()
+
+
+def test_one_rendered_event_is_one_physical_line(capsys: pytest.CaptureFixture[str]) -> None:
+    """INVARIANT: a structlog event reaches stdout as exactly one physical line.
+
+    The processor chain renders the whole event — traceback included, under the `exception` key —
+    before the string ever becomes a `LogRecord`. Everything downstream of that is transport, so
+    the handler must emit the rendered string verbatim.
+
+    Dropping the formatter from the stream handler `MemoryLoggerFactory` builds is what breaks it,
+    and the break is invisible until something raises: stdlib's `Logger.exception` hardcodes
+    `exc_info=True` on the record, so the default `logging.Formatter` appends `record.exc_text`
+    after the JSON and the same traceback ships twice. Every line-oriented log shipper reads the
+    suffix as four malformed events.
+    """
+    logging_instrument = LoggingInstrument(bootstrap_config=LoggingConfig(logging_buffer_capacity=0))
+    try:
+        logging_instrument.bootstrap()
+        logger = structlog.getLogger("one_physical_line")
+        try:
+            msg = "some error"
+            raise ValueError(msg)  # noqa: TRY301
+        except ValueError:
+            logger.exception("logging error")
+    finally:
+        logging_instrument.teardown()
+
+    lines = capsys.readouterr().out.splitlines()
+
+    assert len(lines) == 1, lines
+    payload = json.loads(lines[0])
+    assert payload["event"] == "logging error"
+    assert "ValueError: some error" in payload["exception"]
+
+
+def test_foreign_logger_exception_is_one_physical_line(capsys: pytest.CaptureFixture[str]) -> None:
+    """The same one-line contract holds for a plain stdlib logger going through the root handler."""
+    logging_instrument = LoggingInstrument(bootstrap_config=LoggingConfig(logging_buffer_capacity=0))
+    try:
+        logging_instrument.bootstrap()
+        try:
+            msg = "some error"
+            raise ValueError(msg)  # noqa: TRY301
+        except ValueError:
+            logging.getLogger("foreign_one_physical_line").exception("logging error")
+    finally:
+        logging_instrument.teardown()
+
+    lines = capsys.readouterr().out.splitlines()
+
+    assert len(lines) == 1, lines
+    payload = json.loads(lines[0])
+    assert payload["event"] == "logging error"
+    assert "ValueError: some error" in payload["exception"]