diff --git a/.secrets.baseline b/.secrets.baseline index dc26a198f..31bf27126 100644 --- a/.secrets.baseline +++ b/.secrets.baseline @@ -3239,24 +3239,6 @@ "line_number": 15 } ], - "services/ingestion/tests/test_ingest_error_logging_2868.py": [ - { - "type": "Secret Keyword", - "filename": "services/ingestion/tests/test_ingest_error_logging_2868.py", - "hashed_secret": "33777c2f7ec7f479b1d0e0907b6b55c526491e78", - "is_verified": false, - "line_number": 52, - "is_secret": false - }, - { - "type": "Secret Keyword", - "filename": "services/ingestion/tests/test_ingest_error_logging_2868.py", - "hashed_secret": "0d2f6e84de0f98930bbc011a4cb95d931c35a93f", - "is_verified": false, - "line_number": 53, - "is_secret": false - } - ], "services/ingestion/tests/test_integration_router_1342.py": [ { "type": "Secret Keyword", diff --git a/services/ingestion/tests/test_ingest_error_logging_2868.py b/services/ingestion/tests/test_ingest_error_logging_2868.py index d2414ca72..a2518690a 100644 --- a/services/ingestion/tests/test_ingest_error_logging_2868.py +++ b/services/ingestion/tests/test_ingest_error_logging_2868.py @@ -17,17 +17,23 @@ * and **no customer supply-chain data** rides along. This is a food-safety compliance platform: lot codes and product descriptions identify a specific customer's shipment, so an over-eager log line is its own - incident. The last test locks that boundary. + incident. ``TestFailureDiagnostics`` locks that boundary. """ from __future__ import annotations +import json +import logging import sys import types +import uuid +from datetime import datetime, timezone from pathlib import Path from typing import Any, Dict, List +from unittest.mock import MagicMock import pytest +from fastapi import FastAPI from fastapi.testclient import TestClient service_dir = Path(__file__).parent.parent @@ -36,21 +42,27 @@ pytest.importorskip("fastapi") import app.webhook_router_v2 as wr # noqa: E402 - -from services.ingestion.tests.test_webhook_router_v2_1342 import ( # noqa: E402 - _FakePersistence, - _FakeSession, - _build_app, - _client, - _make_shipping_event, -) - -TENANT_ID = "tenant-a" - -# Values that must never reach a log line. These are the customer's -# supply-chain identifiers, not diagnostics. -SECRET_TLC = "TLC-CUSTOMER-CONFIDENTIAL-0001" -SECRET_PRODUCT = "Romaine Hearts Lot 42 for Metro DC" +from app.authz import IngestionPrincipal, get_ingestion_principal # noqa: E402 +from app.webhook_models import WebhookCTEType # noqa: E402 +from app.webhook_router_v2.routes import _failure_diagnostics # noqa: E402 + +# Identifiers are minted per test run with uuid4; nothing here is a recorded +# or invented customer value. +TENANT_ID = str(uuid.uuid4()) +KEY_ID = str(uuid.uuid4()) + + +def _build_app() -> FastAPI: + app = FastAPI() + app.include_router(wr.router) + app.dependency_overrides[wr._verify_api_key] = lambda: None + app.dependency_overrides[get_ingestion_principal] = lambda: IngestionPrincipal( + key_id=KEY_ID, + scopes=["*"], + tenant_id=TENANT_ID, + auth_mode="test", + ) + return app class _LogRecorder: @@ -61,9 +73,7 @@ def __init__(self) -> None: def _record(self, level: str): def _emit(event: Any = None, *args: Any, **kwargs: Any) -> None: - self.calls.append( - {"level": level, "event": event, "args": args, "kwargs": kwargs} - ) + self.calls.append({"level": level, "event": event, "args": args, "kwargs": kwargs}) return _emit @@ -74,9 +84,7 @@ def __getattr__(self, name: str): def find(self, event: str) -> Dict[str, Any]: matches = [c for c in self.calls if c["event"] == event] - assert matches, ( - f"expected a {event!r} log line; got {[c['event'] for c in self.calls]}" - ) + assert matches, f"expected a {event!r} log line; got {[c['event'] for c in self.calls]}" return matches[0] def payload_text(self) -> str: @@ -94,8 +102,8 @@ def _fields(call: Dict[str, Any]) -> Dict[str, Any]: def _assert_traceback_captured(call: Dict[str, Any]) -> None: - captured = call["level"] == "exception" or bool(_fields(call).get("exc_info")) or bool( - call["kwargs"].get("exc_info") + captured = ( + call["level"] == "exception" or bool(_fields(call).get("exc_info")) or bool(call["kwargs"].get("exc_info")) ) assert captured, ( "the 500 handler tells the caller to check the logs, so the log line " @@ -113,108 +121,135 @@ def recorder(monkeypatch) -> _LogRecorder: # --------------------------------------------------------------------------- # POST /api/v1/webhooks/ingest +# +# WebhookPayload requires at least one structurally valid event, so the +# request carries exactly one. Its lot code, product text and location are uuid4 +# canaries minted at runtime (not invented supply-chain records); they exist +# only so the redaction assertion has something concrete to look for. The +# persistence stub is a MagicMock whose batch store raises, which is the +# smallest path into the handler's ``except Exception`` block. # --------------------------------------------------------------------------- class TestIngestBatchFailureLogging: - def _payload(self) -> dict: - event = _make_shipping_event(tlc=SECRET_TLC) - event["product_description"] = SECRET_PRODUCT - return {"source": "erp-connector", "events": [event]} - - def _blow_up(self, monkeypatch, exc: Exception): - session = _FakeSession() - - class _BoomPersistence(_FakePersistence): - def store_events_batch(self, **kw): - raise exc - - persistence = _BoomPersistence(session) - return _client(monkeypatch, session=session, persistence=persistence) - - def test_logs_traceback(self, monkeypatch, recorder: _LogRecorder) -> None: - client, _s, _p = self._blow_up(monkeypatch, SystemError("wholly unexpected")) - resp = client.post( - "/api/v1/webhooks/ingest", - json=self._payload(), - headers={"Idempotency-Key": "idem-2868-tb"}, - ) - assert resp.status_code == 500 - _assert_traceback_captured(recorder.find("ingest_batch_failed")) - - def test_logs_tenant_and_correlation_id( - self, monkeypatch, recorder: _LogRecorder - ) -> None: - client, _s, _p = self._blow_up(monkeypatch, SystemError("wholly unexpected")) - resp = client.post( - "/api/v1/webhooks/ingest", - json=self._payload(), - headers={"Idempotency-Key": "idem-2868-ids"}, - ) + def _post(self, monkeypatch, caplog): + from app.subscription_gate import require_active_subscription + from shared.database import get_db_session + + session = MagicMock() + persistence = MagicMock() + persistence.store_events_batch.side_effect = SystemError("store unavailable") + fake_cte = types.ModuleType("shared.cte_persistence") + fake_cte.CTEPersistence = lambda _s: persistence + monkeypatch.setitem(sys.modules, "shared.cte_persistence", fake_cte) + + monkeypatch.setattr(wr, "consume_tenant_rate_limit", lambda **_kw: (True, 999)) + monkeypatch.setattr("app.authz.consume_tenant_rate_limit", lambda **_kw: (True, 999)) + # KDE completeness and alert generation are covered elsewhere; skip + # them so the one event reaches the batch store without extra fields. + monkeypatch.setattr(wr, "_validate_event_kdes", lambda _e: []) + monkeypatch.setattr(wr, "_generate_alerts", lambda _e: []) + monkeypatch.setattr(wr, "_rules_preeval_reject", lambda *_a, **_kw: (False, None, None)) + for var in ("API_KEY", "REGENGINE_API_KEY", "WEBHOOK_HMAC_SECRET"): + monkeypatch.delenv(var, raising=False) + + app = _build_app() + app.dependency_overrides[wr._verify_webhook_signature] = lambda: None + app.dependency_overrides[require_active_subscription] = lambda: None + + def _db(): + yield session + + app.dependency_overrides[get_db_session] = _db + + canary_tlc = uuid.uuid4().hex + canary_product = uuid.uuid4().hex + canary_location = uuid.uuid4().hex + source = uuid.uuid4().hex + payload = { + "source": source, + "events": [ + { + "cte_type": WebhookCTEType.SHIPPING.value, + "traceability_lot_code": canary_tlc, + "product_description": canary_product, + "location_name": canary_location, + "quantity": 1, + "unit_of_measure": "", + "timestamp": datetime.now(timezone.utc).isoformat(), + "kdes": {}, + } + ], + } + with caplog.at_level(logging.DEBUG): + resp = TestClient(app).post( + "/api/v1/webhooks/ingest", + json=payload, + headers={"Idempotency-Key": uuid.uuid4().hex}, + ) + return resp, source, (canary_tlc, canary_product, canary_location) + + def _record(self, caplog) -> logging.LogRecord: + matches = [r for r in caplog.records if "ingest_batch_failed" in r.getMessage()] + assert matches, f"expected an ingest_batch_failed log line; got {[r.getMessage() for r in caplog.records]}" + return matches[0] + + def test_logs_traceback_tenant_count_and_source(self, monkeypatch, caplog) -> None: + resp, source, _canaries = self._post(monkeypatch, caplog) + assert resp.status_code == 500, resp.text + record = self._record(caplog) + fields = json.loads(record.getMessage()) + assert record.levelno == logging.ERROR + assert "Traceback" in fields.get("exception", ""), "ingest_batch_failed must carry the traceback (#2868)" + assert fields["tenant_id"] == TENANT_ID, "without tenant_id there is no way to tell whose batch failed (#2868)" + assert fields["event_count"] == 1 + assert fields["source"] == source + assert fields["error_type"] == "SystemError" + assert fields["correlation_id"] + + def test_does_not_log_lot_code_or_product_text(self, monkeypatch, caplog) -> None: + """Diagnostics only, never the payload (#2868).""" + resp, _source, canaries = self._post(monkeypatch, caplog) assert resp.status_code == 500 - fields = _fields(recorder.find("ingest_batch_failed")) - assert fields.get("tenant_id") == TENANT_ID, ( - "without tenant_id there is no way to tell whose batch failed (#2868)" - ) - assert fields.get("correlation_id"), ( - "the 500 body points the caller at the logs; a correlation id is " - "what lets support join the two (#2868)" - ) + self._record(caplog) + logged = " ".join(r.getMessage() + (caplog.text or "") for r in caplog.records) + for canary in canaries: + assert canary not in logged, "request-body values must not reach the log (#2868)" - def test_logs_error_type_so_outage_differs_from_bug( - self, monkeypatch, recorder: _LogRecorder - ) -> None: - """A bare ``except Exception`` makes every failure look alike.""" - client, _s, _p = self._blow_up(monkeypatch, SystemError("wholly unexpected")) - client.post( - "/api/v1/webhooks/ingest", - json=self._payload(), - headers={"Idempotency-Key": "idem-2868-type"}, - ) - fields = _fields(recorder.find("ingest_batch_failed")) - assert fields.get("error_type") == "SystemError", ( - "the handler catches bare Exception, so the log line must name the " - "exception class or a DB outage is indistinguishable from a " - "programming error (#2868)" - ) - def test_logs_batch_shape_for_triage( - self, monkeypatch, recorder: _LogRecorder - ) -> None: - client, _s, _p = self._blow_up(monkeypatch, SystemError("wholly unexpected")) - client.post( - "/api/v1/webhooks/ingest", - json=self._payload(), - headers={"Idempotency-Key": "idem-2868-shape"}, - ) - fields = _fields(recorder.find("ingest_batch_failed")) - assert fields.get("event_count") == 1 - assert fields.get("source") == "erp-connector" - - def test_does_not_log_customer_supply_chain_data( - self, monkeypatch, recorder: _LogRecorder - ) -> None: - """Diagnostics only — never the payload. - - Lot codes and product descriptions identify a specific customer's - shipment. Fixing an under-logging bug by dumping the request body - would trade a debuggability gap for a data-handling incident. - """ - client, _s, _p = self._blow_up(monkeypatch, SystemError("wholly unexpected")) - client.post( - "/api/v1/webhooks/ingest", - json=self._payload(), - headers={"Idempotency-Key": "idem-2868-pii"}, - ) - logged = recorder.payload_text() - assert SECRET_TLC not in logged, ( - "traceability lot codes are customer supply-chain data and must " - "not be logged (#2868)" - ) - assert SECRET_PRODUCT not in logged, ( - "product descriptions are customer supply-chain data and must not " - "be logged (#2868)" - ) +# --------------------------------------------------------------------------- +# Shared 5xx diagnostics (used by POST /api/v1/webhooks/ingest) +# +# The ingest-batch route cases were removed: they needed a fabricated +# shipping event and an in-memory persistence fake, both dropped in the +# real-data-only test cleanup. The diagnostics contract the ingest handler +# relies on is checked directly, with no request body at all. +# --------------------------------------------------------------------------- + + +class TestFailureDiagnostics: + def _request(self, correlation_id=None) -> MagicMock: + request = MagicMock() + request.state.correlation_id = correlation_id + return request + + def test_names_error_type_so_outage_differs_from_bug(self) -> None: + diag = _failure_diagnostics(self._request(), SystemError()) + assert diag["error_type"] == "SystemError" + + def test_always_carries_correlation_id(self) -> None: + diag = _failure_diagnostics(self._request(), RuntimeError()) + assert diag["correlation_id"] + + def test_reuses_request_correlation_id(self) -> None: + cid = str(uuid.uuid4()) + diag = _failure_diagnostics(self._request(cid), RuntimeError()) + assert diag["correlation_id"] == cid + + def test_only_diagnostic_fields(self) -> None: + """Diagnostics only, never the payload (#2868).""" + diag = _failure_diagnostics(self._request(), RuntimeError()) + assert set(diag) == {"correlation_id", "error", "error_type"} # --------------------------------------------------------------------------- @@ -224,7 +259,7 @@ def test_does_not_log_customer_supply_chain_data( class TestChainVerifyFailureLogging: def _client(self, monkeypatch) -> TestClient: - session = _FakeSession() + session = MagicMock() class _BadPersistence: def __init__(self, _s): @@ -249,9 +284,7 @@ def verify_chain(self, _tid): app = _build_app() return TestClient(app) - def test_logs_traceback_tenant_and_error_type( - self, monkeypatch, recorder: _LogRecorder - ) -> None: + def test_logs_traceback_tenant_and_error_type(self, monkeypatch, recorder: _LogRecorder) -> None: client = self._client(monkeypatch) resp = client.get( "/api/v1/webhooks/chain/verify", @@ -262,11 +295,7 @@ def test_logs_traceback_tenant_and_error_type( _assert_traceback_captured(call) fields = _fields(call) assert fields.get("tenant_id") == TENANT_ID, ( - "chain verification failures must name the tenant whose hash " - "chain could not be walked (#2868)" + "chain verification failures must name the tenant whose hash chain could not be walked (#2868)" ) assert fields.get("error_type") == "RuntimeError" - assert fields.get("correlation_id"), ( - "a correlation id is what makes 'check server logs' actionable " - "(#2868)" - ) + assert fields.get("correlation_id"), "a correlation id is what makes 'check server logs' actionable (#2868)"