Files
notify-bridge/packages/server/tests/test_request_correlation.py
T
alexei.dolgolyov 6a8f374678 feat: observability, per-receiver Telegram options, oversized-video fallback
Operability:
- Correlation IDs end-to-end: shared dispatch_id between log lines and
  EventLog rows (event/watcher/scheduled/deferred/action/HA/command paths)
  and a new X-Request-Id middleware that normalizes inbound ids and binds
  request_id into log context.
- dispatch_summary block merged into EventLog.details: per-target
  success/failure counts plus Telegram media delivered/skipped/failed and
  truncated error lists, so partial outcomes surface in the UI.
- Diagnostic mode: admin can flip one module to DEBUG for a bounded
  window with auto-revert (in-memory only; setup_logging() resets on
  boot, lifespan reverts on shutdown). New /diagnostic-mode endpoints
  plus DiagnosticsCassette UI on the settings page.

Telegram:
- Per-receiver options: disable_notification (silent send) and
  message_thread_id (forum-topic routing), wired through the dispatcher
  via a ContextVar so all four send sites (sendMessage / sendPhoto-Video-
  Document / sendMediaGroup / cache-hit POST) pick them up.
- send_large_videos_as_documents target setting: bypass the 50 MB
  sendVideo cap by falling back to sendDocument for oversized videos.
- sendMediaGroup byte-budget enforcement (TELEGRAM_MAX_GROUP_TOTAL_BYTES,
  45 MB) with per-item fallback on chunk failure so a stale file_id no
  longer silently drops a cached asset.

Tests:
- New: diagnostic_mode, dispatch_summary, request_correlation,
  telegram_media_group_partial, telegram_per_send_options.

Docs:
- .claude/reviews/: six-axis production-readiness review of v0.8.1.
- .claude/docs/functional-review-2026-05-28.md: focused review of
  Telegram/Immich/logging subsystems.
2026-05-28 15:19:31 +03:00

159 lines
5.4 KiB
Python

"""Request-ID middleware + EventLog dispatch_id correlation.
Covers two halves of the same correlation story:
* ``RequestContextMiddleware`` generates / accepts an inbound request id,
binds it onto the log-context ContextVar for the duration of the request,
and echoes it back as the ``X-Request-Id`` response header.
* ``enrich_details_with_correlation`` merges the active ``dispatch_id`` and
``request_id`` into an ``EventLog.details`` dict so the persisted row can
be cross-referenced with the stderr log lines emitted during the same
dispatch.
"""
from __future__ import annotations
import re
import pytest
from fastapi.testclient import TestClient
_REQ_ID_PATTERN = re.compile(r"^req:[0-9a-f]{12}$")
def test_response_carries_generated_request_id(tmp_data_dir) -> None: # noqa: ARG001
"""No inbound header → server generates ``req:<12 hex>`` and echoes it."""
from notify_bridge_server.main import app
with TestClient(app) as client:
resp = client.get("/api/health")
assert resp.status_code == 200
req_id = resp.headers.get("X-Request-Id")
assert req_id is not None
assert _REQ_ID_PATTERN.match(req_id), (
f"generated id {req_id!r} should match req:<12 hex>"
)
def test_response_echoes_safe_inbound_request_id(tmp_data_dir) -> None: # noqa: ARG001
"""A well-formed inbound ``X-Request-Id`` is preserved unchanged."""
from notify_bridge_server.main import app
inbound = "abc-123_XYZ_trace"
with TestClient(app) as client:
resp = client.get("/api/health", headers={"X-Request-Id": inbound})
assert resp.status_code == 200
assert resp.headers.get("X-Request-Id") == inbound
def test_colon_prefixed_inbound_id_is_replaced(tmp_data_dir) -> None: # noqa: ARG001
"""``:`` is reserved for server-minted ids — a colon in the inbound value
must trigger replacement so a client can't masquerade as ``disp:...``."""
from notify_bridge_server.main import app
with TestClient(app) as client:
resp = client.get(
"/api/health", headers={"X-Request-Id": "disp:fake12345678"},
)
assert resp.status_code == 200
echoed = resp.headers.get("X-Request-Id", "")
assert echoed != "disp:fake12345678"
assert _REQ_ID_PATTERN.match(echoed)
@pytest.mark.parametrize(
"bad_value",
[
# CRLF injection attempt — would split log lines / inject headers.
"abc\r\ninjected: yes",
# Way too long.
"x" * 256,
# Disallowed characters.
"<script>alert(1)</script>",
# Empty after stripping.
" ",
],
)
def test_unsafe_inbound_request_id_is_replaced(
tmp_data_dir, bad_value: str, # noqa: ARG001
) -> None:
"""An attacker-controlled id must not flow into logs verbatim."""
from notify_bridge_server.main import app
with TestClient(app) as client:
resp = client.get("/api/health", headers={"X-Request-Id": bad_value})
assert resp.status_code == 200
echoed = resp.headers.get("X-Request-Id", "")
assert echoed != bad_value, "unsafe id was passed through unchanged"
assert _REQ_ID_PATTERN.match(echoed), (
f"replacement id {echoed!r} should match req:<12 hex>"
)
def test_enrich_details_merges_active_correlation_ids() -> None:
"""Within a ``bind_log_context`` block, the helper copies the active ids."""
from notify_bridge_core.log_context import (
bind_log_context,
enrich_details_with_correlation,
)
with bind_log_context(
dispatch_id="disp:deadbeef0001",
request_id="req:cafecafe0002",
):
result = enrich_details_with_correlation({"existing": "value"})
assert result == {
"existing": "value",
"dispatch_id": "disp:deadbeef0001",
"request_id": "req:cafecafe0002",
}
def test_enrich_details_does_not_overwrite_explicit_keys() -> None:
"""If the caller pre-set a correlation key, the helper leaves it alone."""
from notify_bridge_core.log_context import (
bind_log_context,
enrich_details_with_correlation,
)
with bind_log_context(dispatch_id="disp:newvalue00001"):
result = enrich_details_with_correlation({"dispatch_id": "disp:pinned"})
assert result["dispatch_id"] == "disp:pinned"
def test_enrich_details_no_context_returns_copy() -> None:
"""Outside any binding, the helper returns the dict unchanged but copied."""
from notify_bridge_core.log_context import enrich_details_with_correlation
original = {"key": "value"}
result = enrich_details_with_correlation(original)
assert result == original
# Mutating the result must not leak into the caller's dict.
result["extra"] = "added"
assert "extra" not in original
def test_enrich_details_handles_none() -> None:
"""``None`` is accepted (callers may build details lazily)."""
from notify_bridge_core.log_context import enrich_details_with_correlation
assert enrich_details_with_correlation(None) == {}
def test_ensure_dispatch_id_generates_or_reuses() -> None:
"""Fresh call produces a new id; inside a bind it returns the bound one."""
from notify_bridge_core.log_context import (
bind_log_context,
ensure_dispatch_id,
)
fresh = ensure_dispatch_id()
assert fresh.startswith("disp:")
assert len(fresh) == len("disp:") + 12
with bind_log_context(dispatch_id="disp:bound00000001"):
assert ensure_dispatch_id() == "disp:bound00000001"