From ebdac209c1ed96131f9eb90b546ba03e1ebfdc44 Mon Sep 17 00:00:00 2001 From: thomas-samoht <54805624+thomas-samoht@users.noreply.github.com> Date: Fri, 4 Sep 2026 21:53:49 +0200 Subject: [PATCH] Send plain text to stdout and keep JSON for the log server stdout carried JSON, and debug_logs_in_console replaced the console rather than configuring it. stdout is now plain text, JSON is the syslog format alone, and console_streams selects which streams reach the terminal: one tagged line per stream, each under its own field allow-list. Defaults to ["app", "siem"], empty silences stdout, an unknown name fails at boot. --- .markdownlint-cli2.jsonc | 3 + CHANGELOG.md | 25 ++++ docs/STARTING_GUIDE.md | 16 ++- gfmodules/logging/__init__.py | 3 +- gfmodules/logging/config.py | 4 +- gfmodules/logging/config_builder.py | 102 +++++++++----- gfmodules/logging/formatter.py | 14 +- tests/test_config.py | 10 +- tests/test_config_builder.py | 204 +++++++++++++++++++++++----- tests/test_end_to_end.py | 47 ++++++- tests/test_formatter.py | 14 +- 11 files changed, 357 insertions(+), 85 deletions(-) diff --git a/.markdownlint-cli2.jsonc b/.markdownlint-cli2.jsonc index c84a7ce..2ee135b 100644 --- a/.markdownlint-cli2.jsonc +++ b/.markdownlint-cli2.jsonc @@ -4,6 +4,9 @@ "line_length": 120, "code_blocks": false, "tables": false + }, + "MD024": { + "siblings_only": true } } } diff --git a/CHANGELOG.md b/CHANGELOG.md index 5720d00..ada2e35 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,30 @@ # Changelog +## Unreleased + +### Changed (breaking) + +- The console is now plain text only; JSON is the syslog wire format alone. The + `json`/`json_traces`/`plain` formatters and the `console` handler are gone, replaced + by `console_app`, `console_siem` and `console_debug`, one per selected stream. +- `debug_logs_in_console` is removed; use `console_streams=["debug"]` instead. +- The console carries the SIEM stream by default (previously app only), so an + app-and-SIEM event now prints one line per stream. Set `console_streams=["app"]` for + the old behavior. +- Only the debug stream is bound to the root logger, so records logged outside the + application's logger tree no longer reach stdout by default. + +### Added + +- `console_streams` on `ConfigLogging` selects which streams (`app`, `siem`, `debug`) + reach stdout as readable text. An empty list silences stdout; an unknown stream name + fails at boot. +- `include_traces` now also controls tracebacks in the console formatters. + +### Fixed + +- A rejected logging setting is no longer misreported as an unreachable log server. + ## 0.2.0 - 2026-09-01 ### Changed (breaking) diff --git a/docs/STARTING_GUIDE.md b/docs/STARTING_GUIDE.md index 5f2b745..5117895 100644 --- a/docs/STARTING_GUIDE.md +++ b/docs/STARTING_GUIDE.md @@ -130,7 +130,7 @@ application's own config module makes every import of it from there fail. | `syslog_path` | `host:port`; unset means console only | | `application_id` | stamped on every JSON record so the log server can tell applications apart; omitted entirely when unset, so set it wherever `syslog_path` is set | | `include_traces` | include tracebacks in the console stream | -| `debug_logs_in_console` | human-readable console output instead of JSON | +| `console_streams` | which streams reach stdout, from `app`, `siem` and `debug`; defaults to `["app", "siem"]`, and empty silences stdout | | `correlation_id_expected` | log when a request arrives without a correlation id | | `trust_forwarded_for` | read the client ip from `X-Forwarded-For`; only where a proxy rewrites it | | `access_logs` | log a record per request; **off by default**, so nothing is access-logged until an application asks | @@ -174,9 +174,17 @@ a stream that would otherwise have stayed quietly empty reports itself instead. ### What reaches the console -With `debug_logs_in_console = False` the console carries the app stream only, so -a SIEM-only event is not printed there. That is intended, but during development -it reads as "nothing was logged": check the stream, not the terminal. +The console is plain text; JSON goes to syslog. By default both the app and SIEM +streams reach stdout, each as a separate line with its own field allow-list. + +```python +ConfigLogging(syslog_path="log-server:5514", console_streams=["app"]) # app only +ConfigLogging(syslog_path="log-server:5514", console_streams=[]) # silence stdout +``` + +An empty list silences stdout, leaving Python's own WARNING-and-above handler +on stderr. Silencing stdout with no `syslog_path` set leaves no handlers at all. + `configure()` builds its dict config through `LogConfigBuilder`, which is exported for an application that needs to inspect or extend it. diff --git a/gfmodules/logging/__init__.py b/gfmodules/logging/__init__.py index d714463..025068a 100644 --- a/gfmodules/logging/__init__.py +++ b/gfmodules/logging/__init__.py @@ -135,8 +135,9 @@ def configure( register_access_logs(config.access_logs) register_catalogue(catalogue, access_logs=config.access_logs) register_logger_root(logger_root) + document = LogConfigBuilder(logging_config=config, loglevel=level).build() try: - dictConfig(LogConfigBuilder(logging_config=config, loglevel=level).build()) + dictConfig(document) except ValueError as exc: if not config.syslog_path: raise diff --git a/gfmodules/logging/config.py b/gfmodules/logging/config.py index 902c96c..3f97b56 100644 --- a/gfmodules/logging/config.py +++ b/gfmodules/logging/config.py @@ -6,9 +6,11 @@ class ConfigLogging(BaseModel): syslog_path: str | None = Field(default=None) application_id: str | None = Field(default=None) include_traces: bool = Field(default=True) - debug_logs_in_console: bool = Field(default=False) correlation_id_expected: bool = Field(default=False) # Whether to include access logs per request. access_logs: bool = Field(default=False) # Only enable this where a proxy rewrites X-Forwarded-For; anywhere else the caller might set it. trust_forwarded_for: bool = Field(default=False) + # Which streams reach stdout as readable text, from "app", "siem" and "debug". + # Empty leaves stdout silent. + console_streams: list[str] = Field(default=["app", "siem"]) diff --git a/gfmodules/logging/config_builder.py b/gfmodules/logging/config_builder.py index 186eac0..d78189e 100644 --- a/gfmodules/logging/config_builder.py +++ b/gfmodules/logging/config_builder.py @@ -7,6 +7,8 @@ from gfmodules.logging.loggers import active_logger_root from gfmodules.logging.streams import LoggingStreams +CONSOLE_STREAMS = ("app", "siem", "debug") + def _at_least(loglevel: str, floor: int) -> str: numeric = logging.getLevelNamesMapping().get(loglevel.upper()) @@ -24,7 +26,7 @@ def __init__( self.loglevel = loglevel self.logging_config = logging_config - def _syslog_handler(self, path: str, formatter: str = "json", filters: list[str] | None = None) -> dict[str, Any]: + def _syslog_handler(self, path: str, formatter: str, filters: list[str] | None = None) -> dict[str, Any]: host, port_str = path.rsplit(":", 1) cfg: dict[str, Any] = { "class": "logging.handlers.SysLogHandler", @@ -36,22 +38,7 @@ def _syslog_handler(self, path: str, formatter: str = "json", filters: list[str] return cfg def build(self) -> dict[str, Any]: - if self.logging_config.debug_logs_in_console: - console: dict[str, Any] = { - "class": "logging.StreamHandler", - "level": "DEBUG", - "formatter": "plain", - "stream": "ext://sys.stdout", - } - else: - console = { - "class": "logging.StreamHandler", - "level": self.loglevel, - "formatter": "json_traces" if self.logging_config.include_traces else "json", - "filters": ["app_filter"], - "stream": "ext://sys.stdout", - } - + traces = self.logging_config.include_traces conf: dict[str, Any] = { "version": 1, "disable_existing_loggers": False, @@ -61,14 +48,6 @@ def build(self) -> dict[str, Any]: "public_inspect_filter": {"()": PublicInspectFilter}, }, "formatters": { - "json": { - "()": JsonFormatter, - "include_traces": False, - }, - "json_traces": { - "()": JsonFormatter, - "include_traces": True, - }, # Only a formatter bound to a stream applies that stream's field # allow-list, and its stream_id is how the log server splits the # shared syslog channel again. @@ -95,26 +74,38 @@ def build(self) -> dict[str, Any]: "include_traces": True, "stream_id": "debug", }, - "plain": { + "plain_app": { "()": PlainTextFormatter, + "include_traces": traces, + "stream": LoggingStreams.APP, + "stream_id": "app", + }, + "plain_siem": { + "()": PlainTextFormatter, + "include_traces": traces, + "stream": LoggingStreams.SIEM, + "stream_id": "siem", + }, + "plain_debug": { + "()": PlainTextFormatter, + "include_traces": traces, + "stream_id": "debug", }, }, - "handlers": { - "console": console, - }, + "handlers": {}, "loggers": { active_logger_root(): { - "handlers": ["console"], + "handlers": [], "level": self.loglevel, "propagate": False, }, "uvicorn": { - "handlers": ["console"], + "handlers": [], "level": self.loglevel, "propagate": False, }, "uvicorn.error": { - "handlers": ["console"], + "handlers": [], "level": self.loglevel, "propagate": False, }, @@ -131,7 +122,7 @@ def build(self) -> dict[str, Any]: "propagate": True, }, }, - "root": {"handlers": ["console"], "level": self.loglevel}, + "root": {"handlers": [], "level": self.loglevel}, } if self.logging_config.application_id: @@ -139,10 +130,55 @@ def build(self) -> dict[str, Any]: if formatter["()"] is JsonFormatter: formatter["application_id"] = self.logging_config.application_id + self._add_console_streams(conf) self._add_log_handlers(conf) return conf + def _selected_console_streams(self) -> list[str]: + unknown = [name for name in self.logging_config.console_streams if name not in CONSOLE_STREAMS] + if unknown: + raise ValueError(f"unknown console_streams {unknown}, choose from {list(CONSOLE_STREAMS)}") + + return list(dict.fromkeys(self.logging_config.console_streams)) + + def _add_console_streams(self, conf: dict[str, Any]) -> None: + app_logger_handlers = conf["loggers"][active_logger_root()]["handlers"] + uvicorn_handlers = conf["loggers"]["uvicorn"]["handlers"] + uvicorn_error_handlers = conf["loggers"]["uvicorn.error"]["handlers"] + root_handlers = conf["root"]["handlers"] + + bindings: dict[str, tuple[str, str | None, str, list[list[str]]]] = { + "app": ( + "plain_app", + "app_filter", + self.loglevel, + [app_logger_handlers, uvicorn_handlers, uvicorn_error_handlers], + ), + "siem": ("plain_siem", "siem_filter", self.loglevel, [app_logger_handlers]), + "debug": ( + "plain_debug", + None, + "DEBUG", + [app_logger_handlers, uvicorn_handlers, uvicorn_error_handlers, root_handlers], + ), + } + + for stream_name in self._selected_console_streams(): + formatter, filter_name, level, logger_handler_lists = bindings[stream_name] + handler_name = f"console_{stream_name}" + handler: dict[str, Any] = { + "class": "logging.StreamHandler", + "level": level, + "formatter": formatter, + "stream": "ext://sys.stdout", + } + if filter_name: + handler["filters"] = [filter_name] + conf["handlers"][handler_name] = handler + for logger_handlers in logger_handler_lists: + logger_handlers.append(handler_name) + def _add_log_handlers(self, conf: dict[str, Any]) -> None: path = self.logging_config.syslog_path if not path: diff --git a/gfmodules/logging/formatter.py b/gfmodules/logging/formatter.py index de633a9..ab925c4 100644 --- a/gfmodules/logging/formatter.py +++ b/gfmodules/logging/formatter.py @@ -77,20 +77,28 @@ def format(self, record: logging.LogRecord) -> str: class PlainTextFormatter(logging.Formatter): - def __init__(self, stream: LoggingStreams | None = None) -> None: + def __init__( + self, + include_traces: bool = True, + stream: LoggingStreams | None = None, + stream_id: str | None = None, + ) -> None: super().__init__() + self.include_traces = include_traces self.stream = stream + self.stream_id = stream_id def format(self, record: logging.LogRecord) -> str: timestamp = datetime.fromtimestamp(record.created, tz=timezone.utc).strftime("%Y-%m-%dT%H:%M:%SZ") event_id = getattr(record, "event_id", None) or "-" - base = f"{timestamp} {record.levelname:<8} {record.name} [{event_id}] {_sanitize_message(record.getMessage())}" + stream_tag = f" [{self.stream_id}]" if self.stream_id else "" + base = f"{timestamp}{stream_tag} {record.levelname:<8} {record.name} [{event_id}] {_sanitize_message(record.getMessage())}" data = {**collect_context(), **_collect_extras(record)} pairs = [f"{key}={value}" for key, value in _allowed_on(record, self.stream, data).items()] out = base if not pairs else f"{base} {' '.join(pairs)}" - if record.exc_info: + if record.exc_info and self.include_traces: out = f"{out}\n{self.formatException(record.exc_info)}" return out diff --git a/tests/test_config.py b/tests/test_config.py index a1156cf..fee8d22 100644 --- a/tests/test_config.py +++ b/tests/test_config.py @@ -7,7 +7,7 @@ def test_defaults_match_the_pre_extraction_behaviour() -> None: assert config.syslog_path is None assert config.application_id is None assert config.include_traces is True - assert config.debug_logs_in_console is False + assert config.console_streams == ["app", "siem"] assert config.correlation_id_expected is False @@ -15,12 +15,16 @@ def test_access_logging_is_off_until_an_application_asks_for_it() -> None: assert ConfigLogging().access_logs is False +def test_an_empty_console_selection_is_kept_rather_than_read_as_the_default() -> None: + assert ConfigLogging(console_streams=[]).console_streams == [] + + def test_accepts_an_application_supplied_configuration() -> None: config = ConfigLogging( syslog_path="syslog:5514", application_id="example-service", include_traces=False, - debug_logs_in_console=True, + console_streams=["app", "debug"], correlation_id_expected=True, access_logs=True, ) @@ -28,6 +32,6 @@ def test_accepts_an_application_supplied_configuration() -> None: assert config.syslog_path == "syslog:5514" assert config.application_id == "example-service" assert config.include_traces is False - assert config.debug_logs_in_console is True + assert config.console_streams == ["app", "debug"] assert config.correlation_id_expected is True assert config.access_logs is True diff --git a/tests/test_config_builder.py b/tests/test_config_builder.py index c2e6fc9..ed135a0 100644 --- a/tests/test_config_builder.py +++ b/tests/test_config_builder.py @@ -23,8 +23,6 @@ "public_inspect_filter": {"()": PublicInspectFilter}, }, "formatters": { - "json": {"()": JsonFormatter, "include_traces": False, "application_id": APP_ID}, - "json_traces": {"()": JsonFormatter, "include_traces": True, "application_id": APP_ID}, "json_app": { "()": JsonFormatter, "include_traces": False, @@ -52,16 +50,39 @@ "stream_id": "debug", "application_id": APP_ID, }, - "plain": {"()": PlainTextFormatter}, + "plain_app": { + "()": PlainTextFormatter, + "include_traces": True, + "stream": LoggingStreams.APP, + "stream_id": "app", + }, + "plain_siem": { + "()": PlainTextFormatter, + "include_traces": True, + "stream": LoggingStreams.SIEM, + "stream_id": "siem", + }, + "plain_debug": { + "()": PlainTextFormatter, + "include_traces": True, + "stream_id": "debug", + }, }, "handlers": { - "console": { + "console_app": { "class": "logging.StreamHandler", "level": "INFO", - "formatter": "json_traces", + "formatter": "plain_app", "filters": ["app_filter"], "stream": "ext://sys.stdout", }, + "console_siem": { + "class": "logging.StreamHandler", + "level": "INFO", + "formatter": "plain_siem", + "filters": ["siem_filter"], + "stream": "ext://sys.stdout", + }, "syslog_app": { "class": "logging.handlers.SysLogHandler", "address": ADDRESS, @@ -88,24 +109,31 @@ }, "loggers": { "app": { - "handlers": ["console", "syslog_app", "syslog_siem", "syslog_public_inspect", "syslog_debug"], + "handlers": [ + "console_app", + "console_siem", + "syslog_app", + "syslog_siem", + "syslog_public_inspect", + "syslog_debug", + ], "level": "INFO", "propagate": False, }, "uvicorn": { - "handlers": ["console", "syslog_app", "syslog_debug"], + "handlers": ["console_app", "syslog_app", "syslog_debug"], "level": "INFO", "propagate": False, }, "uvicorn.error": { - "handlers": ["console", "syslog_app", "syslog_debug"], + "handlers": ["console_app", "syslog_app", "syslog_debug"], "level": "INFO", "propagate": False, }, "uvicorn.access": {"handlers": [], "level": "CRITICAL", "propagate": False}, "inject": {"level": "INFO", "propagate": True}, }, - "root": {"handlers": ["console", "syslog_debug"], "level": "INFO"}, + "root": {"handlers": ["syslog_debug"], "level": "INFO"}, } @@ -117,44 +145,153 @@ def test_builds_the_expected_document_for_a_syslog_configuration() -> None: assert build(ConfigLogging(application_id=APP_ID, syslog_path=SYSLOG)) == EXPECTED_SYSLOG_DOCUMENT -class TestConsoleHandler: - def test_uses_the_plain_formatter_when_debugging_in_the_console(self) -> None: - console = build(ConfigLogging(debug_logs_in_console=True))["handlers"]["console"] +def console_handlers(conf: dict[str, Any]) -> dict[str, Any]: + return {name: spec for name, spec in conf["handlers"].items() if name.startswith("console")} - assert console["formatter"] == "plain" - assert console["level"] == "DEBUG" - assert "filters" not in console - def test_filters_to_the_app_stream_otherwise(self) -> None: - console = build(ConfigLogging())["handlers"]["console"] +class TestTheConsoleIsPlainTextOnly: + def test_no_console_handler_formats_as_json(self) -> None: + conf = build(ConfigLogging(syslog_path=SYSLOG, console_streams=["app", "siem", "debug"])) - assert console["filters"] == ["app_filter"] - assert console["formatter"] == "json_traces" + for spec in console_handlers(conf).values(): + assert conf["formatters"][spec["formatter"]]["()"] is PlainTextFormatter - def test_drops_traces_when_the_configuration_disables_them(self) -> None: - console = build(ConfigLogging(include_traces=False))["handlers"]["console"] + def test_the_json_formatters_that_only_the_console_used_are_gone(self) -> None: + formatters = build(ConfigLogging(syslog_path=SYSLOG))["formatters"] - assert console["formatter"] == "json" + assert "json" not in formatters + assert "json_traces" not in formatters + + def test_every_console_handler_writes_to_stdout(self) -> None: + conf = build(ConfigLogging(console_streams=["app", "siem", "debug"])) + + for spec in console_handlers(conf).values(): + assert spec["stream"] == "ext://sys.stdout" + + +class TestTheDefaultConsole: + def test_it_carries_the_app_and_siem_streams_as_plain_text(self) -> None: + conf = build(ConfigLogging()) + + assert list(console_handlers(conf)) == ["console_app", "console_siem"] + assert conf["handlers"]["console_app"]["formatter"] == "plain_app" + assert conf["handlers"]["console_app"]["filters"] == ["app_filter"] + assert conf["handlers"]["console_siem"]["formatter"] == "plain_siem" + assert conf["handlers"]["console_siem"]["filters"] == ["siem_filter"] + + def test_a_siem_only_event_is_no_longer_invisible_in_the_terminal(self) -> None: + """The default used to carry app alone, so a SIEM-only event read as + "nothing was logged" during development.""" + conf = build(ConfigLogging()) + + assert "console_siem" in conf["loggers"]["app"]["handlers"] + + def test_the_debug_stream_is_not_on_by_default(self) -> None: + conf = build(ConfigLogging()) + + assert "console_debug" not in console_handlers(conf) + assert conf["root"]["handlers"] == [] def test_honours_the_requested_log_level(self) -> None: conf = build(ConfigLogging(), loglevel="WARNING") - assert conf["handlers"]["console"]["level"] == "WARNING" + assert conf["handlers"]["console_app"]["level"] == "WARNING" + assert conf["handlers"]["console_siem"]["level"] == "WARNING" assert conf["loggers"]["app"]["level"] == "WARNING" assert conf["root"]["level"] == "WARNING" +class TestConsoleStreamSelection: + def test_an_explicit_selection_replaces_the_default_rather_than_adding_to_it(self) -> None: + """Otherwise the app stream prints twice, once per handler.""" + conf = build(ConfigLogging(console_streams=["siem"])) + + assert list(console_handlers(conf)) == ["console_siem"] + + def test_each_selected_stream_gets_its_own_handler(self) -> None: + conf = build(ConfigLogging(console_streams=["app", "siem", "debug"])) + + assert set(console_handlers(conf)) == {"console_app", "console_siem", "console_debug"} + + def test_a_stream_is_bound_to_a_logger_exactly_once(self) -> None: + handlers = build(ConfigLogging(console_streams=["app", "siem", "debug"]))["loggers"]["app"]["handlers"] + + assert handlers == ["console_app", "console_siem", "console_debug"] + + def test_the_siem_stream_stays_off_the_uvicorn_loggers(self) -> None: + conf = build(ConfigLogging(console_streams=["app", "siem"])) + + assert conf["loggers"]["uvicorn"]["handlers"] == ["console_app"] + + def test_only_the_debug_stream_reaches_the_root_logger(self) -> None: + assert build(ConfigLogging(console_streams=["app"]))["root"]["handlers"] == [] + assert build(ConfigLogging(console_streams=["debug"]))["root"]["handlers"] == ["console_debug"] + + def test_the_debug_stream_is_unfiltered_so_it_sees_everything(self) -> None: + console = build(ConfigLogging(console_streams=["debug"]))["handlers"]["console_debug"] + + assert "filters" not in console + + def test_an_unknown_stream_is_rejected_rather_than_silently_ignored(self) -> None: + with pytest.raises(ValueError, match="nonsense"): + build(ConfigLogging(console_streams=["nonsense"])) + + def test_an_empty_selection_leaves_stdout_quiet(self) -> None: + conf = build(ConfigLogging(console_streams=[])) + + assert console_handlers(conf) == {} + assert conf["loggers"]["app"]["handlers"] == [] + assert conf["root"]["handlers"] == [] + + def test_an_empty_selection_still_reaches_the_log_server(self) -> None: + conf = build(ConfigLogging(syslog_path=SYSLOG, console_streams=[])) + + assert console_handlers(conf) == {} + assert conf["loggers"]["app"]["handlers"] == [ + "syslog_app", + "syslog_siem", + "syslog_public_inspect", + "syslog_debug", + ] + + def test_a_stream_named_twice_still_gets_one_handler(self) -> None: + conf = build(ConfigLogging(console_streams=["debug", "debug"])) + + assert list(console_handlers(conf)) == ["console_debug"] + assert conf["loggers"]["app"]["handlers"] == ["console_debug"] + + +class TestIncludeTraces: + def test_the_console_formatters_keep_traces_by_default(self) -> None: + formatters = build(ConfigLogging())["formatters"] + + assert formatters["plain_app"]["include_traces"] is True + + def test_disabling_traces_reaches_every_console_formatter(self) -> None: + formatters = build(ConfigLogging(include_traces=False))["formatters"] + + for name in ("plain_app", "plain_siem", "plain_debug"): + assert formatters[name]["include_traces"] is False + + class TestSyslogHandlers: def test_no_syslog_handlers_are_added_without_a_path(self) -> None: conf = build(ConfigLogging()) - assert list(conf["handlers"]) == ["console"] - assert conf["loggers"]["app"]["handlers"] == ["console"] + assert list(conf["handlers"]) == ["console_app", "console_siem"] + assert conf["loggers"]["app"]["handlers"] == ["console_app", "console_siem"] def test_each_stream_gets_its_own_handler_over_the_shared_channel(self) -> None: handlers = build(ConfigLogging(syslog_path=SYSLOG))["handlers"] - assert set(handlers) == {"console", "syslog_app", "syslog_siem", "syslog_public_inspect", "syslog_debug"} + assert set(handlers) == { + "console_app", + "console_siem", + "syslog_app", + "syslog_siem", + "syslog_public_inspect", + "syslog_debug", + } for name in ("syslog_app", "syslog_siem", "syslog_public_inspect", "syslog_debug"): assert handlers[name]["address"] == ("syslog-server", 5514) @@ -176,11 +313,11 @@ def test_parses_an_ipv6_host_correctly(self) -> None: assert handlers["syslog_debug"]["address"] == ("fd00::1", 5514) def test_a_debug_console_keeps_the_syslog_handlers(self) -> None: - conf = build(ConfigLogging(syslog_path=SYSLOG, debug_logs_in_console=True)) + conf = build(ConfigLogging(syslog_path=SYSLOG, console_streams=["debug"])) - assert conf["handlers"]["console"]["formatter"] == "plain" + assert conf["handlers"]["console_debug"]["formatter"] == "plain_debug" assert set(conf["handlers"]) == { - "console", + "console_debug", "syslog_app", "syslog_siem", "syslog_public_inspect", @@ -190,7 +327,7 @@ def test_a_debug_console_keeps_the_syslog_handlers(self) -> None: def test_only_the_debug_stream_reaches_the_root_logger(self) -> None: conf = build(ConfigLogging(syslog_path=SYSLOG)) - assert conf["root"]["handlers"] == ["console", "syslog_debug"] + assert conf["root"]["handlers"] == ["syslog_debug"] def test_siem_and_public_inspect_are_bound_to_the_app_logger_only(self) -> None: conf = build(ConfigLogging(syslog_path=SYSLOG)) @@ -230,15 +367,16 @@ class TestApplicationIdStamping: def test_every_json_formatter_is_stamped(self) -> None: formatters = build(ConfigLogging(application_id=APP_ID, syslog_path=SYSLOG))["formatters"] - json_formatters = [name for name, spec in formatters.items() if name != "plain"] + json_formatters = [name for name, spec in formatters.items() if spec.get("()") is JsonFormatter] assert json_formatters for name in json_formatters: assert formatters[name]["application_id"] == APP_ID - def test_the_plain_formatter_is_never_stamped(self) -> None: + def test_the_plain_formatters_are_never_stamped(self) -> None: formatters = build(ConfigLogging(application_id=APP_ID))["formatters"] - assert "application_id" not in formatters["plain"] + for name in ("plain_app", "plain_siem", "plain_debug"): + assert "application_id" not in formatters[name] def test_nothing_is_stamped_without_an_application_id(self) -> None: formatters = build(ConfigLogging())["formatters"] diff --git a/tests/test_end_to_end.py b/tests/test_end_to_end.py index 35ca7aa..a63f671 100644 --- a/tests/test_end_to_end.py +++ b/tests/test_end_to_end.py @@ -66,7 +66,7 @@ async def unhandled(request: Request, exc: Exception) -> Response: @pytest.fixture(autouse=True) def configured() -> Iterator[None]: gflog.configure( - config=gflog.ConfigLogging(application_id="example-service", debug_logs_in_console=False, access_logs=True), + config=gflog.ConfigLogging(application_id="example-service", access_logs=True), loglevel="info", catalogue=CompleteCatalogue, extra_context_fields=(TENANT_ID,), @@ -198,13 +198,48 @@ def test_rejects_a_catalogue_missing_required_events(self) -> None: with pytest.raises(ValueError, match="does not define required events"): gflog.configure(config=config, loglevel="INFO", catalogue=IncompleteCatalogue) - def test_installs_handlers_that_emit_the_agreed_json_shape(self) -> None: - stream = logging.getLogger().handlers[0].stream # type: ignore[attr-defined] - assert stream is not None - + def _app_record(self) -> logging.LogRecord: record = logging.LogRecord("app.x", logging.INFO, "", 1, "hello", (), None) record.event_id = "100601" - payload = json.loads(logging.getLogger().handlers[0].format(record)) + record.stream = [LoggingStreams.APP] + return record + + def _handler(self, name: str) -> logging.Handler: + return next(h for h in logging.getLogger("app").handlers if h.name == name) + + def test_installs_a_console_handler_that_emits_plain_text_rather_than_json(self) -> None: + formatted = self._handler("console_app").format(self._app_record()) + + with pytest.raises(json.JSONDecodeError): + json.loads(formatted) + assert "INFO" in formatted + assert "[100601]" in formatted + + def test_installs_syslog_handlers_that_emit_the_agreed_json_shape(self) -> None: + gflog.configure( + config=gflog.ConfigLogging( + application_id="example-service", + syslog_path="127.0.0.1:5514", + access_logs=True, + ), + loglevel="info", + catalogue=CompleteCatalogue, + ) + try: + payload = json.loads(self._handler("syslog_app").format(self._app_record())) + finally: + for handler in list(logging.getLogger("app").handlers): + handler.close() assert payload["application_id"] == "example-service" + assert payload["stream_id"] == "app" assert set(payload) >= {"event_id", "timestamp", "level", "event_description", "source", "message"} + + def test_an_invalid_console_stream_is_not_reported_as_an_unreachable_log_server(self) -> None: + config = gflog.ConfigLogging(syslog_path="127.0.0.1:5514", console_streams=["nonsense"]) + + with pytest.raises(ValueError) as raised: + gflog.configure(config=config, loglevel="INFO", catalogue=CompleteCatalogue) + + assert "unknown console_streams" in str(raised.value) + assert "could not reach the log server" not in str(raised.value) diff --git a/tests/test_formatter.py b/tests/test_formatter.py index 31eb88a..01d968f 100644 --- a/tests/test_formatter.py +++ b/tests/test_formatter.py @@ -208,10 +208,16 @@ def expected_record( ), } +PLAIN_APP_LINE_WITH_TAG = ( + "2026-04-12T13:20:00Z [app] ERROR app.health [100600] Component database is unhealthy " + "request_id=req-1 ip=10.0.0.7 client_trace_id=trace-1 correlation_id=corr-1 " + "component=database status=unhealthy error_detail=connection refused" +) + PLAIN_CASES: dict[str, tuple[PlainTextFormatter, dict[str, Any], str]] = { "unrouted": (PlainTextFormatter(), {}, PLAIN_LINE), "with_exc": (PlainTextFormatter(), {"with_exc": True}, f"{PLAIN_LINE}\n{TRACEBACK}"), - "app_stream": (PlainTextFormatter(stream=LoggingStreams.APP), {}, PLAIN_APP_LINE), + "app_stream": (PlainTextFormatter(stream=LoggingStreams.APP, stream_id="app"), {}, PLAIN_APP_LINE_WITH_TAG), } @@ -303,6 +309,12 @@ def test_stack_info_is_included_when_traces_are_enabled(self) -> None: assert out["message"]["stack_info"].startswith("Stack (most recent call last):") + def test_plain_output_keeps_the_traceback_by_default(self) -> None: + assert format_case(PlainTextFormatter(), with_exc=True) == f"{PLAIN_LINE}\n{TRACEBACK}" + + def test_plain_output_omits_the_traceback_when_traces_are_disabled(self) -> None: + assert format_case(PlainTextFormatter(include_traces=False), with_exc=True) == PLAIN_LINE + def test_non_serialisable_values_fall_back_to_their_string_form(self) -> None: record = make_record() record.thing = object()