From 6a1e406fa0f59ce1d697894a9b0de38e145d2ff7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vin=C3=ADcius=20Marques?= Date: Wed, 21 Oct 2026 18:29:42 -0300 Subject: [PATCH] chore(deps): drop the missing-client access-log workaround now that json-logging 1.6 fixes it --- maestro_worker_python/request_logging.py | 36 ---------- maestro_worker_python/serve.py | 2 - pyproject.toml | 2 +- tests/test_request_logging.py | 87 ------------------------ tests/test_serve.py | 31 +++++++++ uv.lock | 8 +-- 6 files changed, 36 insertions(+), 130 deletions(-) delete mode 100644 maestro_worker_python/request_logging.py delete mode 100644 tests/test_request_logging.py diff --git a/maestro_worker_python/request_logging.py b/maestro_worker_python/request_logging.py deleted file mode 100644 index cabcf92..0000000 --- a/maestro_worker_python/request_logging.py +++ /dev/null @@ -1,36 +0,0 @@ -"""Access-log instrumentation hardened against a missing peer address. - -json_logging 1.5.1 dereferences Starlette's optional ``Request.client`` -unguarded, so a request whose peer socket is already gone (kubelet resetting a -timed-out readiness probe, typically) loses its access-log line to a formatter -traceback on stderr. Delete this once bobbui/json-logging-python#116 reaches a -release. -""" - -import json_logging -from json_logging.framework.fastapi import ( - FastAPIAppRequestInstrumentationConfigurator, - FastAPIRequestInfoExtractor, - FastAPIResponseInfoExtractor, -) -from json_logging.frameworks import register_framework_support -from starlette.requests import Request - - -class ClientSafeRequestInfoExtractor(FastAPIRequestInfoExtractor): - def get_remote_ip(self, request: Request) -> str: - return request.client.host if request.client else json_logging.EMPTY_VALUE - - def get_remote_port(self, request: Request) -> int | str: - return request.client.port if request.client else json_logging.EMPTY_VALUE - - -def register_client_safe_request_extractor() -> None: - """Must run before ``init_fastapi``, which freezes the extractor in a singleton.""" - register_framework_support( - "fastapi", - app_configurator=None, - app_request_instrumentation_configurator=FastAPIAppRequestInstrumentationConfigurator, - request_info_extractor_class=ClientSafeRequestInfoExtractor, - response_info_extractor_class=FastAPIResponseInfoExtractor, - ) diff --git a/maestro_worker_python/serve.py b/maestro_worker_python/serve.py index 67744f1..e3ead71 100644 --- a/maestro_worker_python/serve.py +++ b/maestro_worker_python/serve.py @@ -21,7 +21,6 @@ from .health import get_health_metadata from .kill_process import kill_child_processes, terminate_current_process from .load_worker import load_worker -from .request_logging import register_client_safe_request_extractor from .response import FatalWorkerError, ValidationError, WorkerResponse @@ -88,7 +87,6 @@ async def lifespan(_app: FastAPI) -> AsyncIterator[None]: logging.basicConfig(level=settings.log_level.upper()) if settings.enable_json_logging: - register_client_safe_request_extractor() # json_logging pins its own logger to DEBUG at import, and init logs at DEBUG before # the root handler is JSON, leaking a plain-text line that Cloud Logging files as ERROR. logging.getLogger("json_logging").setLevel(logging.INFO) diff --git a/pyproject.toml b/pyproject.toml index 5bfe7f7..4533287 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -8,7 +8,7 @@ license = "MIT" authors = [{ name = "Moises.ai" }] dependencies = [ "fastapi>=0.139.2,<0.140", - "json-logging>=1.3,<2", + "json-logging>=1.6,<2", "nvidia-ml-py>=12.535,<14", "psutil>=6.0.0,<7.1", "pydantic>=2.9,<3", diff --git a/tests/test_request_logging.py b/tests/test_request_logging.py deleted file mode 100644 index cec09b3..0000000 --- a/tests/test_request_logging.py +++ /dev/null @@ -1,87 +0,0 @@ -import subprocess -import sys -import textwrap - -import json_logging -import pytest -from starlette.requests import Request - -from maestro_worker_python.request_logging import ( - ClientSafeRequestInfoExtractor, - register_client_safe_request_extractor, -) - - -def _request(client: tuple[str, int] | None) -> Request: - return Request({"type": "http", "method": "GET", "path": "/health", "headers": [], "client": client}) - - -@pytest.fixture -def extractor() -> ClientSafeRequestInfoExtractor: - return ClientSafeRequestInfoExtractor() - - -def test_reports_peer_address_when_present(extractor): - request = _request(("10.0.0.1", 54321)) - assert extractor.get_remote_ip(request) == "10.0.0.1" - assert extractor.get_remote_port(request) == 54321 - - -def test_reports_empty_value_when_peer_is_gone(extractor): - request = _request(None) - assert extractor.get_remote_ip(request) == json_logging.EMPTY_VALUE - assert extractor.get_remote_port(request) == json_logging.EMPTY_VALUE - - -def test_registration_replaces_only_the_request_extractor(monkeypatch: pytest.MonkeyPatch): - before = json_logging._framework_support_map["fastapi"] - monkeypatch.setitem(json_logging._framework_support_map, "fastapi", dict(before)) - - register_client_safe_request_extractor() - - after = json_logging._framework_support_map["fastapi"] - assert after["request_info_extractor_class"] is ClientSafeRequestInfoExtractor - assert {k: v for k, v in after.items() if k != "request_info_extractor_class"} == { - k: v for k, v in before.items() if k != "request_info_extractor_class" - } - - -# json_logging's init mutates process-wide logging state and caches the extractor in a -# singleton, so the serving path can only be exercised honestly in a fresh interpreter. -SERVE_A_REQUEST_WITHOUT_A_PEER = """ -import asyncio, sys -from maestro_worker_python import serve - -scope = { - "type": "http", "asgi": {"version": "3.0"}, "http_version": "1.1", "scheme": "http", - "method": "GET", "path": "/health", "raw_path": b"/health", "query_string": b"", - "root_path": "", "headers": [], "client": None, "server": ("testserver", 80), -} - -async def receive(): - return {"type": "http.request", "body": b"", "more_body": False} - -messages = [] - -async def send(message): - messages.append(message) - -asyncio.run(serve.app(scope, receive, send)) -print([m["status"] for m in messages if m["type"] == "http.response.start"], file=sys.stderr) -""" - - -def test_serving_a_request_without_a_peer_logs_cleanly(tmp_path): - worker_path = tmp_path / "worker.py" - worker_path.write_text("class MoisesWorker:\n pass\n") - - result = subprocess.run( - [sys.executable, "-c", textwrap.dedent(SERVE_A_REQUEST_WITHOUT_A_PEER)], - capture_output=True, - text=True, - env={"ENABLE_JSON_LOGGING": "true", "MODEL_PATH": str(worker_path)}, - ) - - assert result.returncode == 0, result.stderr - assert "[200]" in result.stderr - assert "Logging error" not in result.stderr, result.stderr diff --git a/tests/test_serve.py b/tests/test_serve.py index 447c6ed..a231f2a 100644 --- a/tests/test_serve.py +++ b/tests/test_serve.py @@ -390,3 +390,34 @@ def test_json_logging_keeps_reporting_its_own_warnings(tmp_path): assert result.returncode == 0, result.stderr records = [json.loads(line) for line in _log_lines(result) if line.startswith("{")] assert any(r["msg"] == "probe" and r["level"] == "WARNING" for r in records), records + + +SERVE_A_REQUEST_WITHOUT_A_PEER = """ +import asyncio, sys + +scope = { + "type": "http", "asgi": {"version": "3.0"}, "http_version": "1.1", "scheme": "http", + "method": "GET", "path": "/health", "raw_path": b"/health", "query_string": b"", + "root_path": "", "headers": [], "client": None, "server": ("testserver", 80), +} + +async def receive(): + return {"type": "http.request", "body": b"", "more_body": False} + +messages = [] + +async def send(message): + messages.append(message) + +asyncio.run(serve.app(scope, receive, send)) +print([m["status"] for m in messages if m["type"] == "http.response.start"], file=sys.stderr) +""" + + +def test_json_logging_serves_a_request_without_a_peer_cleanly(tmp_path): + # A kubelet resetting a timed-out readiness probe leaves Request.client as None. + result = _start_with_json_logging(tmp_path, SERVE_A_REQUEST_WITHOUT_A_PEER) + + assert result.returncode == 0, result.stderr + assert "[200]" in result.stderr + assert "Logging error" not in result.stderr, result.stderr diff --git a/uv.lock b/uv.lock index 3611116..c43387b 100644 --- a/uv.lock +++ b/uv.lock @@ -211,11 +211,11 @@ wheels = [ [[package]] name = "json-logging" -version = "1.5.1" +version = "1.6.0" source = { registry = "https://pypi.org/simple" } -sdist = { url = "https://files.pythonhosted.org/packages/74/cc/6bef021352f8a4d4e1b0ab4216f65ed313f66b0adaf279e8ff08ea03ad68/json-logging-1.5.1.tar.gz", hash = "sha256:7c938750996a1cc66042b516caf75214513bcc25a105012865496864f5f3983b", size = 26072, upload-time = "2025-07-07T07:09:45.397Z" } +sdist = { url = "https://files.pythonhosted.org/packages/b5/67/1c37cff6d305dc2472cdc18109f4cac7358d47c58caa7c7d410bbeb8a75f/json_logging-1.6.0.tar.gz", hash = "sha256:d708f7ce02fea741b9f41b61fc8e9fdcb14a86092f2ff53061cdb07e1e11241a", size = 47342, upload-time = "2026-10-21T20:27:13.445Z" } wheels = [ - { url = "https://files.pythonhosted.org/packages/76/6c/4a74f61a66b1360425339f5fd57178c47f44e8a38a214ae3d4104f9fc19e/json_logging-1.5.1-py2.py3-none-any.whl", hash = "sha256:df39ee1e6709c46830654e96a769894832061207c653c851baeacf655bff596d", size = 23689, upload-time = "2025-07-07T07:09:44.505Z" }, + { url = "https://files.pythonhosted.org/packages/34/d1/9a6cc57d796aad69b8d36d3205c944f1458403fdec37c3ffe5f944225a5e/json_logging-1.6.0-py2.py3-none-any.whl", hash = "sha256:d9201ffa11dc90a67d33e52add828acf2e97c6359678785907d038c71db6eb6b", size = 26238, upload-time = "2026-10-21T20:27:12.484Z" }, ] [[package]] @@ -246,7 +246,7 @@ dev = [ [package.metadata] requires-dist = [ { name = "fastapi", specifier = ">=0.139.2,<0.140" }, - { name = "json-logging", specifier = ">=1.3,<2" }, + { name = "json-logging", specifier = ">=1.6,<2" }, { name = "nvidia-ml-py", specifier = ">=12.535,<14" }, { name = "psutil", specifier = ">=6.0.0,<7.1" }, { name = "pydantic", specifier = ">=2.9,<3" },