diff --git a/backend/src/kf_oj/api/app.py b/backend/src/kf_oj/api/app.py index 05d2625..c1da944 100644 --- a/backend/src/kf_oj/api/app.py +++ b/backend/src/kf_oj/api/app.py @@ -39,7 +39,7 @@ def create_app(settings: Settings | None = None) -> FastAPI: @asynccontextmanager async def lifespan(_: FastAPI): - configure_logging(settings.log_level) + configure_logging(settings.log_level, production=settings.environment == "production") logger = logging.getLogger("kf_oj.api") logger.info("Platform API started") engine = None diff --git a/backend/src/kf_oj/core/logging.py b/backend/src/kf_oj/core/logging.py index ae5f0e1..cc18def 100644 --- a/backend/src/kf_oj/core/logging.py +++ b/backend/src/kf_oj/core/logging.py @@ -16,7 +16,53 @@ class JsonFormatter(logging.Formatter): return json.dumps(payload, ensure_ascii=False) -def configure_logging(level: str) -> None: +class ProductionFormatter(logging.Formatter): + """Closed event vocabulary; arbitrary messages/arguments/tracebacks are private data.""" + + EVENTS = { + ("kf_oj.api", "Platform API started"): "api_started", + ("kf_oj.api", "Platform API stopped"): "api_stopped", + ("kf_oj.outbox", "outbox broker unavailable"): "outbox_broker_unavailable", + ("kf_oj.outbox", "outbox database unavailable"): "outbox_database_unavailable", + } + LOGGERS = {"kf_oj.api", "kf_oj.outbox", "uvicorn", "uvicorn.error", "uvicorn.access"} + LEVELS = { + logging.DEBUG: "DEBUG", + logging.INFO: "INFO", + logging.WARNING: "WARNING", + logging.ERROR: "ERROR", + logging.CRITICAL: "CRITICAL", + } + + def format(self, record: logging.LogRecord) -> str: + # Do not call getMessage/formatException: library errors can contain + # connection URIs, query parameters, source or diagnostic body bytes. + event = "infrastructure_event" + if isinstance(record.msg, str) and not record.args: + event = self.EVENTS.get((record.name, record.msg), event) + return json.dumps( + { + "timestamp": datetime.fromtimestamp(record.created, UTC).isoformat(), + "level": self.LEVELS.get(record.levelno, "UNKNOWN"), + "logger": record.name if record.name in self.LOGGERS else "infrastructure", + "message": event, + "exception_present": record.exc_info is not None, + }, + ensure_ascii=False, + ) + + +def configure_logging(level: str, *, production: bool = False) -> None: handler = logging.StreamHandler() - handler.setFormatter(JsonFormatter()) + handler.setFormatter(ProductionFormatter() if production else JsonFormatter()) logging.basicConfig(level=level, handlers=[handler], force=True) + if production: + # Uvicorn installs its own handlers before lifespan, which otherwise + # bypass the root formatter when reporting an unhandled application error. + for name in ("uvicorn", "uvicorn.error"): + logger = logging.getLogger(name) + logger.handlers.clear() + logger.propagate = True + access = logging.getLogger("uvicorn.access") + access.handlers.clear() + access.propagate = False diff --git a/backend/tests/test_production_logging.py b/backend/tests/test_production_logging.py new file mode 100644 index 0000000..f4afa49 --- /dev/null +++ b/backend/tests/test_production_logging.py @@ -0,0 +1,60 @@ +"""Pure logging vocabulary checks, not evidence of real request/daemon log privacy.""" + +import json +import logging + +from kf_oj.core.logging import ProductionFormatter, configure_logging + + +def test_production_does_not_serialize_unapproved_message_arguments_or_exception_data(): + record = logging.LogRecord( + "external_library", + logging.ERROR, + "private/path", + 5, + "temporary fixture token=%s", + ("fixture-only",), + (ValueError, ValueError("fixture-only"), None), + ) + value = json.loads(ProductionFormatter().format(record)) + assert value["message"] == "infrastructure_event" + assert value["logger"] == "infrastructure" + assert value["exception_present"] is True + assert "fixture-only" not in json.dumps(value) + assert "private/path" not in json.dumps(value) + + +def test_only_exact_lifecycle_message_without_arguments_is_retained(): + record = logging.LogRecord( + "kf_oj.api", logging.INFO, "unused", 1, "Platform API started", (), None + ) + assert json.loads(ProductionFormatter().format(record))["message"] == "api_started" + record.args = ("fixture-only",) + assert json.loads(ProductionFormatter().format(record))["message"] == "infrastructure_event" + + +def test_custom_logger_or_level_names_do_not_expand_the_output_vocabulary(): + record = logging.LogRecord("fixture-only", logging.ERROR, "unused", 1, {}, (), None) + record.levelname = "fixture-only" * 1024 + value = ProductionFormatter().format(record) + assert len(value) < 512 + assert "fixture-only" not in value + + +def test_uvicorn_error_handlers_cannot_bypass_production_formatter(capsys): + loggers = [ + logging.getLogger(name) for name in ("", "uvicorn", "uvicorn.error", "uvicorn.access") + ] + original = [(logger, logger.handlers[:], logger.level, logger.propagate) for logger in loggers] + try: + configure_logging("INFO", production=True) + assert not logging.getLogger("uvicorn.access").hasHandlers() + logging.getLogger("uvicorn.error").error("fixture-only %s", "temporary value") + value = json.loads(capsys.readouterr().err) + assert value["message"] == "infrastructure_event" + assert "fixture-only" not in json.dumps(value) + finally: + for logger, handlers, level, propagate in original: + logger.handlers = handlers + logger.setLevel(level) + logger.propagate = propagate diff --git a/scripts/release/README.md b/scripts/release/README.md index b6cd265..e649357 100644 --- a/scripts/release/README.md +++ b/scripts/release/README.md @@ -322,3 +322,10 @@ work; installing the profile alone does not route existing service logs or verif their privacy. The profile relies on the pinned systemd 262 [namespace interface](https://github.com/systemd/systemd/blob/v262/man/systemd.exec.xml) and [journal configuration](https://github.com/systemd/systemd/blob/v262/man/journald.conf.xml). + +Production API logging uses a closed event vocabulary and omits arbitrary library +messages, arguments, paths and exception text. Uvicorn's separate error handlers +are redirected through that formatter; installed API launchers disable access +logging so request query strings are not copied into service logs. Development +diagnostics remain separate. These ordinary formatting checks are not evidence +of actual daemon, HTTP or upload log privacy; that is still a VM acceptance case. diff --git a/scripts/release/build.py b/scripts/release/build.py index 4ef6600..0457de4 100644 --- a/scripts/release/build.py +++ b/scripts/release/build.py @@ -16,7 +16,7 @@ ENTRYPOINTS = { "kf-delivery": "scripts.release", "kf-api": ( "uvicorn kf_oj.api.app:create_app --factory --host 127.0.0.1 --port 8000 " - "--no-proxy-headers --limit-concurrency 32 --backlog 64" + "--no-proxy-headers --no-access-log --limit-concurrency 32 --backlog 64" ), "kf-outbox-publisher": "kf_oj.workers.outbox", "kf-problem-import-worker": "kf_oj.workers.problem_import", diff --git a/scripts/release/service_bootstrap.py b/scripts/release/service_bootstrap.py index 3cee846..8b35be6 100644 --- a/scripts/release/service_bootstrap.py +++ b/scripts/release/service_bootstrap.py @@ -31,6 +31,7 @@ PYTHON_MODULES = { "--port", "8000", "--no-proxy-headers", + "--no-access-log", "--limit-concurrency", "32", "--backlog",