From b5f347074633955dae0e9f3b2804b31a2e0bb6af Mon Sep 17 00:00:00 2001 From: thomas-samoht <54805624+thomas-samoht@users.noreply.github.com> Date: Tue, 20 Oct 2026 13:55:15 +0200 Subject: [PATCH] Keep the debug stream off the log server by default --- CHANGELOG.md | 17 ++++++ README.md | 3 +- docs/STARTING_GUIDE.md | 28 +++++++-- gfmodules/logging/config.py | 1 + gfmodules/logging/config_builder.py | 57 +++++++++--------- tests/test_config_builder.py | 90 ++++++++++++++++++++--------- tests/test_routing.py | 46 ++++++++++++++- 7 files changed, 180 insertions(+), 62 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index e795107..3119923 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,6 +2,23 @@ ## Unreleased +### Changed (breaking) + +- The debug stream no longer reaches the log server by default. It has no + filter and no field allow-list, so it sent request bodies, SQL parameters + and tracebacks to the log server whatever the application configured. Set + `syslog_streams=["app", "siem", "public_inspect", "debug"]` for the old + behavior. +- The debug stream on the log server now honours `include_traces`, so + `include_traces=False` keeps tracebacks off the log server as well. + +### Added + +- `syslog_streams` on `ConfigLogging` selects which streams (`app`, `siem`, + `public_inspect`, `debug`) reach the log server. It defaults to + `["app", "siem", "public_inspect"]`. An empty list sends nothing; an unknown + stream name fails at boot. + ### Fixed - `loglevel` now applies to every stream. A logger with a lower level of its diff --git a/README.md b/README.md index b62c430..be4ef9c 100644 --- a/README.md +++ b/README.md @@ -131,7 +131,8 @@ Records are JSON with a fixed structure: The format is a fixed contract with the log server: `stream_id` identifies the stream (`app`, `siem`, `public_inspect`, `debug`) and `application_id` identifies -the source application. +the source application. The `debug` stream reaches the log server only when +`syslog_streams` selects it. ## Development diff --git a/docs/STARTING_GUIDE.md b/docs/STARTING_GUIDE.md index ea1dea6..327b3b1 100644 --- a/docs/STARTING_GUIDE.md +++ b/docs/STARTING_GUIDE.md @@ -133,8 +133,9 @@ 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 | +| `include_traces` | include tracebacks in the console streams and in the debug stream on the log server | | `console_streams` | which streams reach stdout, from `app`, `siem` and `debug`; defaults to `["app", "siem"]`, and empty silences stdout | +| `syslog_streams` | which streams reach the log server, from `app`, `siem`, `public_inspect` and `debug`; defaults to `["app", "siem", "public_inspect"]`, so the debug stream stays off the log server unless selected | | `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; **on by default** once `RequestContextMiddleware` is added (see step 3) | @@ -158,10 +159,10 @@ which for a container service name means from inside the compose network. ### Loading list settings from INI files -`console_streams` is `list[str]`; pydantic does not turn a plain string into a -list, so a `ConfigLogging` populated from an INI file (where every value is a -string) needs the setting to arrive already split. An application loading its -own config from INI opts the field in explicitly: +`console_streams` and `syslog_streams` are `list[str]`; pydantic does not turn a +plain string into a list, so a `ConfigLogging` populated from an INI file (where +every value is a string) needs them to arrive already split. An application +loading its own config from INI opts each field in explicitly: ```python from gfmodules.logging import ConfigLogging as GFConfigLogging @@ -172,6 +173,9 @@ class ConfigLogging(GFConfigLogging): _split_console_streams = field_validator("console_streams", mode="before")( split_comma_separated() ) + _split_syslog_streams = field_validator("syslog_streams", mode="before")( + split_comma_separated() + ) ``` `split_comma_separated` takes each stripped item through `item_type` (`str` by @@ -219,6 +223,20 @@ ConfigLogging(syslog_path="log-server:5514", console_streams=[]) # silence 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. +### What reaches the log server + +Each selected stream goes to the log server as JSON over the shared syslog +channel, tagged with its `stream_id`. By default those are the app, SIEM and +public-inspect streams. The debug stream has no filter and no field allow-list, +so it carries every record with every field, request bodies included, and it +reaches the log server only when the application selects it: + +```python +ConfigLogging(syslog_path="log-server:5514", syslog_streams=["app", "siem", "public_inspect", "debug"]) +``` + +`include_traces=False` keeps tracebacks out of the debug stream as well. + `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/config.py b/gfmodules/logging/config.py index 5b9bb8b..b3f708a 100644 --- a/gfmodules/logging/config.py +++ b/gfmodules/logging/config.py @@ -14,3 +14,4 @@ class ConfigLogging(BaseModel): # Which streams reach stdout as readable text, from "app", "siem" and "debug". # Empty leaves stdout silent. console_streams: list[str] = Field(default=["app", "siem"]) + syslog_streams: list[str] = Field(default=["app", "siem", "public_inspect"]) diff --git a/gfmodules/logging/config_builder.py b/gfmodules/logging/config_builder.py index e6557ad..125cc90 100644 --- a/gfmodules/logging/config_builder.py +++ b/gfmodules/logging/config_builder.py @@ -8,6 +8,15 @@ from gfmodules.logging.streams import LoggingStreams CONSOLE_STREAMS = ("app", "siem", "debug") +SYSLOG_STREAMS = ("app", "siem", "public_inspect", "debug") + + +def _selected(setting: str, names: list[str], choices: tuple[str, ...]) -> list[str]: + unknown = [name for name in names if name not in choices] + if unknown: + raise ValueError(f"unknown {setting} {unknown}, choose from {list(choices)}") + + return list(dict.fromkeys(names)) def _at_least(loglevel: str, floor: int) -> str: @@ -72,7 +81,7 @@ def build(self) -> dict[str, Any]: }, "json_debug": { "()": JsonFormatter, - "include_traces": True, + "include_traces": traces, "stream_id": "debug", }, "plain_app": { @@ -136,13 +145,6 @@ def build(self) -> dict[str, Any]: 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"] @@ -159,7 +161,7 @@ def _add_console_streams(self, conf: dict[str, Any]) -> None: ), } - for stream_name in self._selected_console_streams(): + for stream_name in _selected("console_streams", self.logging_config.console_streams, CONSOLE_STREAMS): formatter, filter_name, logger_handler_lists = bindings[stream_name] handler_name = f"console_{stream_name}" handler: dict[str, Any] = { @@ -175,6 +177,7 @@ def _add_console_streams(self, conf: dict[str, Any]) -> None: logger_handlers.append(handler_name) def _add_log_handlers(self, conf: dict[str, Any]) -> None: + streams = _selected("syslog_streams", self.logging_config.syslog_streams, SYSLOG_STREAMS) path = self.logging_config.syslog_path if not path: return @@ -182,22 +185,24 @@ def _add_log_handlers(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"] - conf["handlers"]["syslog_app"] = self._syslog_handler(path, formatter="json_app", filters=["app_filter"]) - app_logger_handlers.append("syslog_app") - uvicorn_handlers.append("syslog_app") - uvicorn_error_handlers.append("syslog_app") - - conf["handlers"]["syslog_siem"] = self._syslog_handler(path, formatter="json_siem", filters=["siem_filter"]) - app_logger_handlers.append("syslog_siem") - - conf["handlers"]["syslog_public_inspect"] = self._syslog_handler( - path, formatter="json_public_inspect", filters=["public_inspect_filter"] - ) - app_logger_handlers.append("syslog_public_inspect") + bindings: dict[str, tuple[str, str | None, list[list[str]]]] = { + "app": ("json_app", "app_filter", [app_logger_handlers, uvicorn_handlers, uvicorn_error_handlers]), + "siem": ("json_siem", "siem_filter", [app_logger_handlers]), + "public_inspect": ("json_public_inspect", "public_inspect_filter", [app_logger_handlers]), + "debug": ( + "json_debug", + None, + [app_logger_handlers, uvicorn_handlers, uvicorn_error_handlers, root_handlers], + ), + } - conf["handlers"]["syslog_debug"] = self._syslog_handler(path, formatter="json_debug") - app_logger_handlers.append("syslog_debug") - uvicorn_handlers.append("syslog_debug") - uvicorn_error_handlers.append("syslog_debug") - conf["root"]["handlers"].append("syslog_debug") + for stream_name in streams: + formatter, filter_name, logger_handler_lists = bindings[stream_name] + handler_name = f"syslog_{stream_name}" + conf["handlers"][handler_name] = self._syslog_handler( + path, formatter=formatter, filters=[filter_name] if filter_name else None + ) + for logger_handlers in logger_handler_lists: + logger_handlers.append(handler_name) diff --git a/tests/test_config_builder.py b/tests/test_config_builder.py index 31dd15f..c0b902c 100644 --- a/tests/test_config_builder.py +++ b/tests/test_config_builder.py @@ -13,6 +13,7 @@ APP_ID = "example-service" SYSLOG = "syslog-server:5514" ADDRESS = ("syslog-server", 5514) +EVERY_SYSLOG_STREAM = ["app", "siem", "public_inspect", "debug"] EXPECTED_SYSLOG_DOCUMENT: dict[str, Any] = { "version": 1, @@ -104,12 +105,6 @@ "formatter": "json_public_inspect", "filters": ["public_inspect_filter"], }, - "syslog_debug": { - "class": "logging.handlers.SysLogHandler", - "address": ADDRESS, - "level": "INFO", - "formatter": "json_debug", - }, }, "loggers": { "app": { @@ -119,25 +114,24 @@ "syslog_app", "syslog_siem", "syslog_public_inspect", - "syslog_debug", ], "level": "INFO", "propagate": False, }, "uvicorn": { - "handlers": ["console_app", "syslog_app", "syslog_debug"], + "handlers": ["console_app", "syslog_app"], "level": "INFO", "propagate": False, }, "uvicorn.error": { - "handlers": ["console_app", "syslog_app", "syslog_debug"], + "handlers": ["console_app", "syslog_app"], "level": "INFO", "propagate": False, }, "uvicorn.access": {"handlers": [], "level": "CRITICAL", "propagate": False}, "inject": {"level": "INFO", "propagate": True}, }, - "root": {"handlers": ["syslog_debug"], "level": "INFO"}, + "root": {"handlers": [], "level": "INFO"}, } @@ -208,7 +202,11 @@ def test_honours_the_requested_log_level(self) -> None: class TestTheLogLevel: def test_every_handler_applies_it(self) -> None: conf = build( - ConfigLogging(syslog_path=SYSLOG, console_streams=["app", "siem", "debug"]), + ConfigLogging( + syslog_path=SYSLOG, + console_streams=["app", "siem", "debug"], + syslog_streams=EVERY_SYSLOG_STREAM, + ), loglevel="WARNING", ) @@ -263,12 +261,7 @@ 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", - ] + assert conf["loggers"]["app"]["handlers"] == ["syslog_app", "syslog_siem", "syslog_public_inspect"] def test_a_stream_named_twice_still_gets_one_handler(self) -> None: conf = build(ConfigLogging(console_streams=["debug", "debug"])) @@ -289,6 +282,11 @@ def test_disabling_traces_reaches_every_console_formatter(self) -> None: for name in ("plain_app", "plain_siem", "plain_debug"): assert formatters[name]["include_traces"] is False + def test_disabling_traces_reaches_the_debug_stream_on_the_log_server(self) -> None: + formatters = build(ConfigLogging(include_traces=False))["formatters"] + + assert formatters["json_debug"]["include_traces"] is False + class TestSyslogHandlers: def test_no_syslog_handlers_are_added_without_a_path(self) -> None: @@ -298,7 +296,7 @@ def test_no_syslog_handlers_are_added_without_a_path(self) -> None: 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"] + handlers = build(ConfigLogging(syslog_path=SYSLOG, syslog_streams=EVERY_SYSLOG_STREAM))["handlers"] assert set(handlers) == { "console_app", @@ -319,29 +317,23 @@ def test_stream_handlers_carry_their_matching_filter(self) -> None: assert handlers["syslog_public_inspect"]["filters"] == ["public_inspect_filter"] def test_the_debug_handler_is_unfiltered_so_it_sees_everything(self) -> None: - handlers = build(ConfigLogging(syslog_path=SYSLOG))["handlers"] + handlers = build(ConfigLogging(syslog_path=SYSLOG, syslog_streams=["debug"]))["handlers"] assert "filters" not in handlers["syslog_debug"] def test_parses_an_ipv6_host_correctly(self) -> None: handlers = build(ConfigLogging(syslog_path="fd00::1:5514"))["handlers"] - assert handlers["syslog_debug"]["address"] == ("fd00::1", 5514) + assert handlers["syslog_app"]["address"] == ("fd00::1", 5514) def test_a_debug_console_keeps_the_syslog_handlers(self) -> None: conf = build(ConfigLogging(syslog_path=SYSLOG, console_streams=["debug"])) assert conf["handlers"]["console_debug"]["formatter"] == "plain_debug" - assert set(conf["handlers"]) == { - "console_debug", - "syslog_app", - "syslog_siem", - "syslog_public_inspect", - "syslog_debug", - } + assert set(conf["handlers"]) == {"console_debug", "syslog_app", "syslog_siem", "syslog_public_inspect"} def test_only_the_debug_stream_reaches_the_root_logger(self) -> None: - conf = build(ConfigLogging(syslog_path=SYSLOG)) + conf = build(ConfigLogging(syslog_path=SYSLOG, syslog_streams=EVERY_SYSLOG_STREAM)) assert conf["root"]["handlers"] == ["syslog_debug"] @@ -353,6 +345,48 @@ def test_siem_and_public_inspect_are_bound_to_the_app_logger_only(self) -> None: assert "syslog_public_inspect" not in conf["loggers"]["uvicorn"]["handlers"] +def syslog_handlers(conf: dict[str, Any]) -> list[str]: + return [name for name in conf["handlers"] if name.startswith("syslog")] + + +class TestSyslogStreamSelection: + def test_the_debug_stream_stays_off_the_log_server_by_default(self) -> None: + conf = build(ConfigLogging(syslog_path=SYSLOG)) + + assert syslog_handlers(conf) == ["syslog_app", "syslog_siem", "syslog_public_inspect"] + assert conf["root"]["handlers"] == [] + + def test_selecting_debug_sends_every_logger_to_the_log_server(self) -> None: + conf = build(ConfigLogging(syslog_path=SYSLOG, syslog_streams=["debug"], console_streams=[])) + + for logger in ("app", "uvicorn", "uvicorn.error"): + assert conf["loggers"][logger]["handlers"] == ["syslog_debug"] + assert conf["root"]["handlers"] == ["syslog_debug"] + + def test_an_explicit_selection_replaces_the_default_rather_than_adding_to_it(self) -> None: + conf = build(ConfigLogging(syslog_path=SYSLOG, syslog_streams=["siem"])) + + assert syslog_handlers(conf) == ["syslog_siem"] + + def test_an_unknown_stream_is_rejected_rather_than_silently_ignored(self) -> None: + with pytest.raises(ValueError, match="nonsense"): + build(ConfigLogging(syslog_path=SYSLOG, syslog_streams=["nonsense"])) + + def test_an_unknown_stream_is_rejected_before_a_log_server_is_configured(self) -> None: + with pytest.raises(ValueError, match="unknown syslog_streams"): + build(ConfigLogging(syslog_streams=["nonsense"])) + + def test_an_empty_selection_sends_nothing_to_the_log_server(self) -> None: + conf = build(ConfigLogging(syslog_path=SYSLOG, syslog_streams=[])) + + assert syslog_handlers(conf) == [] + + def test_a_stream_named_twice_still_gets_one_handler(self) -> None: + conf = build(ConfigLogging(syslog_path=SYSLOG, syslog_streams=["debug", "debug"])) + + assert conf["root"]["handlers"] == ["syslog_debug"] + + class TestLoggers: def test_uvicorn_access_is_silenced_because_the_middleware_logs_access(self) -> None: access = build(ConfigLogging())["loggers"]["uvicorn.access"] diff --git a/tests/test_routing.py b/tests/test_routing.py index 1065b09..6115dff 100644 --- a/tests/test_routing.py +++ b/tests/test_routing.py @@ -39,7 +39,12 @@ def record(handler: logging.handlers.SysLogHandler, entry: logging.LogRecord) -> def configure(loglevel: str = "INFO", logger_root: str = gflog.DEFAULT_LOGGER_ROOT) -> None: gflog.configure( - config=gflog.ConfigLogging(syslog_path="localhost:1514", application_id="routing-test", access_logs=True), + config=gflog.ConfigLogging( + syslog_path="localhost:1514", + application_id="routing-test", + access_logs=True, + syslog_streams=["app", "siem", "public_inspect", "debug"], + ), loglevel=loglevel, catalogue=CompleteCatalogue, logger_root=logger_root, @@ -257,7 +262,7 @@ def test_configure_reports_a_missing_application_id_on_the_app_stream( catalogue=CompleteCatalogue, ) - assert streams_reporting(delivered, "no application_id is configured") == {"app", "debug"} + assert streams_reporting(delivered, "no application_id is configured") == {"app"} def test_it_stays_quiet_when_nothing_reaches_syslog(self, delivered: list[dict[str, Any]]) -> None: gflog.configure( @@ -308,3 +313,40 @@ def test_its_records_stay_off_the_debug_console(self, capsys: pytest.CaptureFixt logging.getLogger("sqlalchemy.engine.Engine").info("below the log level") assert "below the log level" not in capsys.readouterr().out + + +def log_a_failure(secret: str) -> None: + try: + raise ValueError(secret) + except ValueError: + logging.getLogger("app.example").exception("failed") + + +class TestTheDebugStreamOnTheLogServer: + def test_it_stays_off_unless_the_application_selects_it(self, delivered: list[dict[str, Any]]) -> None: + gflog.configure( + config=gflog.ConfigLogging(syslog_path="localhost:1514", application_id="routing-test"), + loglevel="INFO", + catalogue=CompleteCatalogue, + ) + + log_a_failure("value that must not be logged") + + assert "value that must not be logged" not in json.dumps(delivered) + + def test_it_leaves_tracebacks_out_when_traces_are_disabled(self, delivered: list[dict[str, Any]]) -> None: + gflog.configure( + config=gflog.ConfigLogging( + syslog_path="localhost:1514", + application_id="routing-test", + syslog_streams=["debug"], + include_traces=False, + ), + loglevel="INFO", + catalogue=CompleteCatalogue, + ) + + log_a_failure("value that must not be logged") + + assert {payload["event_description"] for payload in delivered} == {"failed"} + assert "value that must not be logged" not in json.dumps(delivered)