Bound the length of a logged error reason

Author: thomas-samoht

app/logging/rejections.py

@@ -6,9 +6,17 @@
 logger = logging.getLogger(__name__)
 
 _DENIAL_STATUSES = frozenset({401, 403})
+MAX_REASON_LENGTH = 500
+_TRUNCATED = "..."
 
 
-def summarize_reason(exc: Exception) -> str:
+def _bounded(reason: str) -> str:
+    if len(reason) <= MAX_REASON_LENGTH:
+        return reason
+    return reason[: MAX_REASON_LENGTH - len(_TRUNCATED)] + _TRUNCATED
+
+
+def _describe(exc: Exception) -> str:
     if isinstance(exc, (RequestValidationError, ValidationError)):
         reasons = [
             f"{'.'.join(str(loc) for loc in err.get('loc', ()))}: {err.get('msg', '')}".strip(" :")
@@ -18,6 +26,10 @@ def summarize_reason(exc: Exception) -> str:
     return str(exc)
 
 
+def summarize_reason(exc: Exception) -> str:
+    return _bounded(_describe(exc))
+
+
 def log_rejection(status_code: int, exc: Exception, reason: str) -> None:
     level = logging.WARNING if status_code in _DENIAL_STATUSES else logging.INFO
     logger.log(level, "Request rejected with %s (%s): %s", status_code, type(exc).__name__, reason)

app/services/pseudonym_referral_service.py

@@ -7,6 +7,7 @@
 from app.db.models.referral import ReferralEntity
 from app.errors.mapping import should_log, spec_for
 from app.logging.events import Log
+from app.logging.rejections import summarize_reason
 from app.models.pseudonym import EncryptedPseudonym, OprfPseudonym
 from app.models.ura import UraNumber
 from app.services.pseudonym_resolver import PseudonymResolver
@@ -21,7 +22,7 @@ def _log_failure(event: LogEvent, message: str, exc: Exception) -> None:
             logger,
             event,
             message,
-            fields={"http_status": spec_for(exc).http_status, "error_reason": str(exc)},
+            fields={"http_status": spec_for(exc).http_status, "error_reason": summarize_reason(exc)},
         )
 
 

tests/logging/test_rejections.py

@@ -1,7 +1,7 @@
 import pytest
 from pydantic import BaseModel, ValidationError
 
-from app.logging.rejections import summarize_reason
+from app.logging.rejections import MAX_REASON_LENGTH, summarize_reason
 
 
 class _Model(BaseModel):
@@ -22,3 +22,21 @@ def test_summarizes_a_validation_error_without_its_input() -> None:
 
 def test_summarizes_a_plain_exception_by_its_message() -> None:
     assert summarize_reason(RuntimeError("boom")) == "boom"
+
+
+@pytest.mark.parametrize(
+    "exc",
+    [RuntimeError("x" * (MAX_REASON_LENGTH * 4)), _validation_error(["a"] * 1000)],
+    ids=["long-message", "many-errors"],
+)
+def test_bounds_the_length_of_a_reason(exc: Exception) -> None:
+    reason = summarize_reason(exc)
+
+    assert len(reason) == MAX_REASON_LENGTH
+    assert reason.endswith("...")
+
+
+def test_keeps_a_reason_of_the_maximum_length_whole() -> None:
+    message = "x" * MAX_REASON_LENGTH
+
+    assert summarize_reason(RuntimeError(message)) == message

tests/services/test_pseudonym_referral_service.py

@@ -6,6 +6,7 @@
 
 from app.debug.crypto_service_api_client_mock import CryptoServiceApiClientMock
 from app.logging.events import Log
+from app.logging.rejections import MAX_REASON_LENGTH
 from app.models.pseudonym import OprfPseudonym, PseudonymResponse
 from app.models.ura import UraNumber
 from app.services.exceptions import CryptoServiceError, InvalidKeyInfoError, PseudonymExchangeError
@@ -99,6 +100,24 @@ def test_register_logs_an_error_when_the_crypto_service_fails(
     assert fields["http_status"] == 502
 
 
+def test_register_bounds_the_logged_failure_reason(
+    referral_service: ReferralService,
+    key_info_service: KeyInfoService,
+    ura_number: UraNumber,
+    caplog: pytest.LogCaptureFixture,
+) -> None:
+    class VerboseFailingCryptoClient(CryptoServiceApiClientMock):
+        def exchange(self, pseudonym: OprfPseudonym, label: str, mechanism: str) -> PseudonymResponse:
+            raise RuntimeError("x" * (MAX_REASON_LENGTH * 4))
+
+    service = _service_with(VerboseFailingCryptoClient(), referral_service, key_info_service)
+    with caplog.at_level(logging.INFO), pytest.raises(RuntimeError):
+        service.register(PSEUDONYM, ura_number, SOURCE)
+
+    (fields,) = logged_fields(caplog, Log.REFERRAL_REGISTRATION_ERROR)
+    assert len(fields["error_reason"]) == MAX_REASON_LENGTH
+
+
 def test_register_does_not_log_an_expected_failure(
     pseudonym_referral_service: PseudonymReferralService,
     ura_number: UraNumber,