From 5f565411d7a169dd4e684fc4643cea7faeb54baf Mon Sep 17 00:00:00 2001 From: alexstocks Date: Mon, 24 Aug 2026 18:10:36 +0800 Subject: [PATCH 1/2] fix(server): display uvicorn lifecycle logs without an error logger name uvicorn hardcodes uvicorn.error as its lifecycle logger name, which reads like an error channel while it mostly carries INFO startup lines. Rewrite the record name in the display layer only: attach a filter to the uvicorn.error logger that renders it as uvicorn. The logger tree, level routing, and JSON output stay consistent, and powercontext's own loggers are untouched. --- src/powercontext/server/logging.py | 22 +++++++++++++++++++++- tests/test_server_logging.py | 30 +++++++++++++++++++++++++++++- 2 files changed, 50 insertions(+), 2 deletions(-) diff --git a/src/powercontext/server/logging.py b/src/powercontext/server/logging.py index 36f569c64..297c3dd50 100644 --- a/src/powercontext/server/logging.py +++ b/src/powercontext/server/logging.py @@ -91,6 +91,22 @@ def filter(self, record: logging.LogRecord) -> bool: return True +class _UvicornDisplayNameFilter(logging.Filter): + """Rewrite uvicorn's lifecycle logger name for display. + + uvicorn hardcodes "uvicorn.error" for its lifecycle logger, which mostly + carries INFO startup lines but reads like an error channel. Rewriting the + record name here is display-only: the logger tree, level routing, and any + filtering keyed on the original name are untouched. + """ + + @override + def filter(self, record: logging.LogRecord) -> bool: + if record.name == "uvicorn.error": + record.name = "uvicorn" + return True + + def configure_server_logging(config: ServerLoggingConfig) -> None: """Configure process logging for the foreground Server command.""" @@ -106,7 +122,10 @@ def configure_server_logging(config: ServerLoggingConfig) -> None: logging.config.dictConfig({ "version": 1, "disable_existing_loggers": False, - "filters": {"operational": {"()": _HumanContextFilter}}, + "filters": { + "operational": {"()": _HumanContextFilter}, + "uvicorn_display_name": {"()": _UvicornDisplayNameFilter}, + }, "formatters": {"server": formatter}, "handlers": { "server": { @@ -126,6 +145,7 @@ def configure_server_logging(config: ServerLoggingConfig) -> None: "handlers": ["server"], "level": config.level, "propagate": False, + "filters": ["uvicorn_display_name"], }, }, }) diff --git a/tests/test_server_logging.py b/tests/test_server_logging.py index 657202729..210193758 100644 --- a/tests/test_server_logging.py +++ b/tests/test_server_logging.py @@ -21,10 +21,38 @@ from powercontext.builtin.persistence.sqlite import SQLiteConfig from powercontext.server.factory import create_server_app -from powercontext.server.logging import JsonFormatter, OperationalContextFilter +from powercontext.server.logging import JsonFormatter, OperationalContextFilter, _UvicornDisplayNameFilter from powercontext.server.settings import McpConfig, ServerLoggingConfig, ServerSettings +def test_uvicorn_error_records_are_displayed_as_uvicorn() -> None: + record = logging.makeLogRecord({ + "name": "uvicorn.error", + "levelno": logging.INFO, + "levelname": "INFO", + "msg": "Started server process", + }) + + _UvicornDisplayNameFilter().filter(record) + + payload = json.loads(JsonFormatter().format(record)) + assert payload["logger"] == "uvicorn" + assert payload["message"] == "Started server process" + + +def test_uvicorn_display_name_filter_leaves_other_loggers_untouched() -> None: + record = logging.makeLogRecord({ + "name": "powercontext.server.factory", + "levelno": logging.INFO, + "levelname": "INFO", + "msg": "PowerContext Server is ready", + }) + + _UvicornDisplayNameFilter().filter(record) + + assert record.name == "powercontext.server.factory" + + def test_json_formatter_emits_stable_operational_fields() -> None: record = logging.makeLogRecord({ "name": "powercontext.server.access", From 054f5e97c63262976e40c6ab3d66d9954e16a060 Mon Sep 17 00:00:00 2001 From: alexstocks Date: Mon, 24 Aug 2026 23:47:05 +0800 Subject: [PATCH 2/2] test(server): cover uvicorn logging configuration --- src/powercontext/server/logging.py | 11 +++--- tests/test_server_logging.py | 60 +++++++++++++++++++----------- 2 files changed, 45 insertions(+), 26 deletions(-) diff --git a/src/powercontext/server/logging.py b/src/powercontext/server/logging.py index 297c3dd50..10e13c6ce 100644 --- a/src/powercontext/server/logging.py +++ b/src/powercontext/server/logging.py @@ -92,12 +92,13 @@ def filter(self, record: logging.LogRecord) -> bool: class _UvicornDisplayNameFilter(logging.Filter): - """Rewrite uvicorn's lifecycle logger name for display. + """Rewrite uvicorn's logger name for downstream display. - uvicorn hardcodes "uvicorn.error" for its lifecycle logger, which mostly - carries INFO startup lines but reads like an error channel. Rewriting the - record name here is display-only: the logger tree, level routing, and any - filtering keyed on the original name are untouched. + Uvicorn emits lifecycle and error records through ``uvicorn.error``. + Logger selection, hierarchy, and effective-level checks use that logger. + This filter then rewrites only ``record.name``, so later filters on the + same logger and downstream handler filters and formatters observe + ``uvicorn``. Parent logger filters are not applied during propagation. """ @override diff --git a/tests/test_server_logging.py b/tests/test_server_logging.py index 210193758..33f8432c6 100644 --- a/tests/test_server_logging.py +++ b/tests/test_server_logging.py @@ -16,41 +16,59 @@ import json import logging +import subprocess +import sys from fastapi.testclient import TestClient from powercontext.builtin.persistence.sqlite import SQLiteConfig from powercontext.server.factory import create_server_app -from powercontext.server.logging import JsonFormatter, OperationalContextFilter, _UvicornDisplayNameFilter +from powercontext.server.logging import JsonFormatter, OperationalContextFilter from powercontext.server.settings import McpConfig, ServerLoggingConfig, ServerSettings -def test_uvicorn_error_records_are_displayed_as_uvicorn() -> None: - record = logging.makeLogRecord({ - "name": "uvicorn.error", - "levelno": logging.INFO, - "levelname": "INFO", - "msg": "Started server process", - }) +def _run_configured_logging_probe(log_format: str) -> list[str]: + script = f""" +import logging + +from powercontext.server.logging import configure_server_logging +from powercontext.server.settings import ServerLoggingConfig + +configure_server_logging(ServerLoggingConfig(format={log_format!r})) +logging.getLogger("uvicorn.error").info("Started server process") +logging.getLogger("uvicorn.error").error("Server startup failed") +logging.getLogger("powercontext.server.factory").info("PowerContext Server is ready") +""" + result = subprocess.run( + [sys.executable, "-c", script], + check=True, + capture_output=True, + text=True, + timeout=120, + ) + return result.stdout.splitlines() - _UvicornDisplayNameFilter().filter(record) - payload = json.loads(JsonFormatter().format(record)) - assert payload["logger"] == "uvicorn" - assert payload["message"] == "Started server process" +def test_configured_console_logging_uses_uvicorn_display_name() -> None: + lines = _run_configured_logging_probe("console") + assert len(lines) == 3 + messages = [line.split(" ", 1)[1] for line in lines] + assert messages == [ + "INFO uvicorn Started server process", + "ERROR uvicorn Server startup failed", + "INFO powercontext.server.factory PowerContext Server is ready", + ] -def test_uvicorn_display_name_filter_leaves_other_loggers_untouched() -> None: - record = logging.makeLogRecord({ - "name": "powercontext.server.factory", - "levelno": logging.INFO, - "levelname": "INFO", - "msg": "PowerContext Server is ready", - }) - _UvicornDisplayNameFilter().filter(record) +def test_configured_json_logging_uses_uvicorn_display_name() -> None: + payloads = [json.loads(line) for line in _run_configured_logging_probe("json")] - assert record.name == "powercontext.server.factory" + assert [(payload["level"], payload["logger"], payload["message"]) for payload in payloads] == [ + ("INFO", "uvicorn", "Started server process"), + ("ERROR", "uvicorn", "Server startup failed"), + ("INFO", "powercontext.server.factory", "PowerContext Server is ready"), + ] def test_json_formatter_emits_stable_operational_fields() -> None: