From 04a9ef02ffda6d201dc384d457ce18aa4d986064 Mon Sep 17 00:00:00 2001 From: Adamskiee Date: Fri, 14 Aug 2026 17:00:13 +0800 Subject: [PATCH] fix(server-ws): silence routine auth rejection logs --- server/app/api/gps.py | 5 -- server/app/api/peer_connection.py | 5 -- server/app/main.py | 10 ++-- .../tests/test_websocket_auth_rejection.py | 53 +++++-------------- 4 files changed, 18 insertions(+), 55 deletions(-) diff --git a/server/app/api/gps.py b/server/app/api/gps.py index 9ece7fda..3f9c76f5 100644 --- a/server/app/api/gps.py +++ b/server/app/api/gps.py @@ -1,5 +1,4 @@ from typing import Annotated -import logging from fastapi import WebSocketException, status from fastapi import APIRouter, WebSocket, WebSocketDisconnect, Depends from app.db_operations.auth import SessionDep, get_user_by_ID @@ -21,8 +20,6 @@ from app.models.location import UserLocation from app.db_operations.GPS_manager import gps_manager -logger = logging.getLogger(__name__) - router = APIRouter( prefix='/gps', tags=['GPS'], @@ -42,7 +39,6 @@ async def stream_gps_location( try: authed_id = await authenticate_websocket(websocket, token) except WebSocketAuthError: - logger.warning("WebSocket auth rejected: invalid or expired token client=%s", websocket.client) return if str(authed_id) != user_id: @@ -182,7 +178,6 @@ async def monitor_live_feed( try: authed_id = await authenticate_websocket(websocket, token) except WebSocketAuthError: - logger.warning("WebSocket auth rejected: invalid or expired token client=%s", websocket.client) return if str(authed_id) != rescuer_id: diff --git a/server/app/api/peer_connection.py b/server/app/api/peer_connection.py index b2036d9e..7c7bbc7c 100644 --- a/server/app/api/peer_connection.py +++ b/server/app/api/peer_connection.py @@ -1,6 +1,5 @@ import asyncio import json -import logging import re import ast @@ -24,9 +23,6 @@ from app.db_operations.activity import set_user_status from app.models.websocketComms import MessageData, PublicMessageData -logger = logging.getLogger(__name__) - - def _set_status_bg(user_id: UUID, status: str) -> None: try: with Session(engine) as session: @@ -179,7 +175,6 @@ async def main_web_socket(token: str, websocket: WebSocket, target_id: UUID|None try: user_id = await authenticate_websocket(websocket, token) except WebSocketAuthError: - logger.warning("WebSocket auth rejected: invalid or expired token client=%s", websocket.client) return await manager.connect(UUID(user_id), websocket) diff --git a/server/app/main.py b/server/app/main.py index 6aea5d8b..45d79fe5 100644 --- a/server/app/main.py +++ b/server/app/main.py @@ -163,15 +163,13 @@ def get_version(): class UvicornWebSocket403Filter(logging.Filter): - """Downgrade uvicorn's own `"WebSocket ... " 403` access line. + """Suppress uvicorn's own `"WebSocket ... " 403` access line. uvicorn logs this INFO-level line (on "uvicorn.error") for every WebSocket handshake that closes before being accepted — which includes - our routine, expected auth rejections (invalid/expired token). Those - rejections are already logged once, with more context, by the route - handlers (see app/api/peer_connection.py, app/api/gps.py). Without this - filter the same rejection is reported twice, at two different - severities, drowning genuine faults in access-log noise (#326). + routine, expected auth rejections (invalid/expired token). The route + handlers intentionally leave those rejections silent, so this filter + prevents them from surfacing as access-log noise (#326). """ def filter(self, record: logging.LogRecord) -> bool: diff --git a/server/app/tests/test_websocket_auth_rejection.py b/server/app/tests/test_websocket_auth_rejection.py index e3396dec..942d1c81 100644 --- a/server/app/tests/test_websocket_auth_rejection.py +++ b/server/app/tests/test_websocket_auth_rejection.py @@ -7,15 +7,16 @@ an expected, routine rejection. The fix: `authenticate_websocket` raises a dedicated `WebSocketAuthError`, -which `main_web_socket` catches and logs as a concise warning instead of -letting it propagate as an unhandled exception. +which each route catches instead of letting it propagate as an unhandled +exception. Invalid tokens are expected client input, so the rejection stays +silent after the socket is closed. #326 found the same unhandled-exception gap on the GPS WebSocket routes (`/gps/ws/{user_id}` and `/gps/ws/monitor/rescuers/{rescuer_id}`), which call `authenticate_websocket` without catching `WebSocketAuthError` at all, and it flagged that uvicorn's own access log still emits a `403` -line for every rejection (duplicating the app-level warning at a second -severity) — see `test_websocket_403_access_log_is_suppressed`. +line for every rejection. That line is also suppressed so routine invalid +tokens do not create log noise. """ import logging import uuid @@ -35,22 +36,16 @@ def test_invalid_token_rejects_cleanly_without_unhandled_exception(client: TestC assert exc_info.value.code == 1008 -def test_invalid_token_logs_concise_warning_not_error(client: TestClient, caplog): - # Arrange +def test_invalid_token_rejection_is_silent(client: TestClient, caplog): caplog.set_level(logging.WARNING, logger="app.api.peer_connection") - # Act with pytest.raises(WebSocketDisconnect): with client.websocket_connect("/ws/?token=not-a-real-token"): pass - # Assert: a concise warning was logged, and nothing at ERROR level - # (no unhandled-exception traceback) came out of this rejection. - assert any( - record.levelno == logging.WARNING and "auth rejected" in record.message - for record in caplog.records + assert not any( + record.name == "app.api.peer_connection" for record in caplog.records ) - assert not any(record.levelno >= logging.ERROR for record in caplog.records) def test_gps_stream_invalid_token_rejects_cleanly_without_unhandled_exception(client: TestClient): @@ -66,22 +61,15 @@ def test_gps_stream_invalid_token_rejects_cleanly_without_unhandled_exception(cl assert exc_info.value.code == 1008 -def test_gps_stream_invalid_token_logs_concise_warning_not_error(client: TestClient, caplog): - # Arrange +def test_gps_stream_invalid_token_rejection_is_silent(client: TestClient, caplog): user_id = str(uuid.uuid4()) caplog.set_level(logging.WARNING, logger="app.api.gps") - # Act with pytest.raises(WebSocketDisconnect): with client.websocket_connect(f"/gps/ws/{user_id}?token=not-a-real-token"): pass - # Assert - assert any( - record.levelno == logging.WARNING and "auth rejected" in record.message - for record in caplog.records - ) - assert not any(record.levelno >= logging.ERROR for record in caplog.records) + assert not any(record.name == "app.api.gps" for record in caplog.records) def test_gps_monitor_invalid_token_rejects_cleanly_without_unhandled_exception(client: TestClient): @@ -96,22 +84,15 @@ def test_gps_monitor_invalid_token_rejects_cleanly_without_unhandled_exception(c assert exc_info.value.code == 1008 -def test_gps_monitor_invalid_token_logs_concise_warning_not_error(client: TestClient, caplog): - # Arrange +def test_gps_monitor_invalid_token_rejection_is_silent(client: TestClient, caplog): rescuer_id = str(uuid.uuid4()) caplog.set_level(logging.WARNING, logger="app.api.gps") - # Act with pytest.raises(WebSocketDisconnect): with client.websocket_connect(f"/gps/ws/monitor/rescuers/{rescuer_id}?token=not-a-real-token"): pass - # Assert - assert any( - record.levelno == logging.WARNING and "auth rejected" in record.message - for record in caplog.records - ) - assert not any(record.levelno >= logging.ERROR for record in caplog.records) + assert not any(record.name == "app.api.gps" for record in caplog.records) def _make_ws_403_record() -> logging.LogRecord: @@ -130,14 +111,8 @@ def _make_ws_403_record() -> logging.LogRecord: ) -def test_uvicorn_ws_403_filter_downgrades_duplicate_rejection_line(): - """uvicorn logs its own `"WebSocket ..." 403` line (INFO, logger - "uvicorn.error") for every handshake rejected before accept — the same - event our app-level warning already reports at WARNING with more - context. The filter installed in `app.main` must suppress that - specific line from propagating at INFO so it doesn't double up the - rejection at two severities. - """ +def test_uvicorn_ws_403_filter_suppresses_rejection_line(): + """The filter keeps uvicorn's handshake rejection line silent.""" from app.main import UvicornWebSocket403Filter filt = UvicornWebSocket403Filter()