diff --git a/backend/app/services/push_service.py b/backend/app/services/push_service.py index 9f27aee..a267835 100644 --- a/backend/app/services/push_service.py +++ b/backend/app/services/push_service.py @@ -95,4 +95,17 @@ async def send_push_to_user(db: AsyncSession, user_id: uuid.UUID, payload: dict) ) await db.commit() else: - logger.warning("Push delivery failed for %s: %s", subscription.id, exc) + # #56: WNS's own 400s carry the actual reason in a response + # *header* ("Ttl value conflicts with X-WNS-Cache-Policy"), + # not the body -- pywebpush's own exception message only + # ever surfaces the body, so that specific bug still would + # have needed a full journalctl+DB-dump investigation to + # diagnose even with a body-only log line. Logging headers + # too is the difference between "something is broken" and + # this log line alone being enough next time, for any push + # provider's failure, not just WNS's. + response = exc.response + detail = "" + if response is not None: + detail = f" | response: {response.text!r} | headers: {dict(response.headers)!r}" + logger.warning("Push delivery failed for %s: %s%s", subscription.id, exc, detail) diff --git a/backend/pyproject.toml b/backend/pyproject.toml index c8b57ab..92b34cb 100644 --- a/backend/pyproject.toml +++ b/backend/pyproject.toml @@ -15,7 +15,14 @@ dependencies = [ "pydantic-settings>=2.6", "argon2-cffi>=23.1", "itsdangerous>=2.2", - "pywebpush>=2.0", + # #56: >=2.0 let the production venv sit on an old 2.0.x that predates + # the fix for web-push-libs/pywebpush#162 -- WNS (Windows/Edge push) + # has required an X-WNS-Cache-Policy header since April 2024, and an + # old pywebpush that never sends it gets a bodyless 400 on every send. + # Floored at the actual latest release (merged/shipped 2026-01 through + # 2026-08) rather than pinning to whichever exact point release first + # included the fix, since that wasn't independently confirmed. + "pywebpush>=2.4.0", "redis>=5.0", "httpx>=0.27", "gunicorn>=23.0", diff --git a/backend/tests/test_push.py b/backend/tests/test_push.py index 246ca43..5ea5232 100644 --- a/backend/tests/test_push.py +++ b/backend/tests/test_push.py @@ -218,3 +218,57 @@ def test_expired_subscription_is_cleaned_up(ws_client, monkeypatch): assert ws.receive_json()["type"] == "joined" assert _fetch_subscriptions(ws_client, bob["id"]) == [] + + +def test_non_gone_push_failure_logs_response_detail_and_keeps_subscription(ws_client, monkeypatch): + # #56: a real WNS 400 carries its actual reason in a response *header*, + # not the body -- str(WebPushException) alone (what used to be logged) + # would have shown neither, which is exactly why that bug took a DB + # dump + journalctl correlation to diagnose instead of one log line. + class FakeResponse: + status_code = 400 + text = "Bad Request" + headers = {"X-WNS-Error-Description": "Ttl value conflicts with X-WNS-Cache-Policy"} + + def fake_webpush(**kwargs): + raise WebPushException("Push failed: 400 Bad Request", response=FakeResponse()) + + monkeypatch.setattr("app.services.push_service.webpush", fake_webpush) + + # caplog's handler capture isn't reliable here -- the actual push send + # (and its logger.warning call) runs on ws_client_factory's background + # portal thread (see that fixture's own docstring), not pytest's main + # thread. Patching the logger call directly sidesteps that instead of + # depending on cross-thread log propagation. + calls = [] + monkeypatch.setattr( + "app.services.push_service.logger.warning", + lambda msg, *args: calls.append(msg % args), + ) + + alice = _register_ws(ws_client, _unique("alice")) + room = ws_client.post("/api/rooms", json={"name": _unique("general")}).json() + + bob = _register_ws(ws_client, _unique("bob")) + ws_client.post(f"/api/rooms/{room['id']}/join") + ws_client.post("/api/push/subscribe", json=_subscription_payload(_unique("bob"))) + assert len(_fetch_subscriptions(ws_client, bob["id"])) == 1 + + ws_client.post( + "/api/auth/login", json={"username_or_email": alice["username"], "password": "password123"} + ) + with ws_client.websocket_connect("/ws/chat") as ws: + ws.send_json({"type": "join", "room_id": room["id"]}) + assert ws.receive_json()["type"] == "joined" + ws.send_json({"type": "message", "room_id": room["id"], "content": "hello"}) + assert ws.receive_json()["type"] == "message" + ws.send_json({"type": "join", "room_id": room["id"]}) + assert ws.receive_json()["type"] == "joined" + + # A 400 isn't "gone" (404/410) -- the subscription stays, unlike the + # expired-subscription case above. + assert len(_fetch_subscriptions(ws_client, bob["id"])) == 1 + + assert len(calls) == 1 + assert "Bad Request" in calls[0] + assert "Ttl value conflicts with X-WNS-Cache-Policy" in calls[0]