diff --git a/backend/ai-service/Dockerfile b/backend/ai-service/Dockerfile index f327f2ee..55b81091 100644 --- a/backend/ai-service/Dockerfile +++ b/backend/ai-service/Dockerfile @@ -32,6 +32,7 @@ RUN uv export \ && pip install --no-cache-dir -r /tmp/requirements-ai.txt \ && pip install --no-cache-dir --force-reinstall opencv-contrib-python-headless==4.10.0.84 +COPY backend/shared /app/backend/shared COPY backend/ai-service /app/backend/ai-service WORKDIR /app/backend/ai-service diff --git a/backend/ai-service/app/core/safe_logging.py b/backend/ai-service/app/core/safe_logging.py new file mode 100644 index 00000000..3fa281c7 --- /dev/null +++ b/backend/ai-service/app/core/safe_logging.py @@ -0,0 +1,30 @@ +from __future__ import annotations + +import sys +from pathlib import Path + +_BACKEND_ROOT = Path(__file__).resolve().parents[3] +if str(_BACKEND_ROOT) not in sys.path: + sys.path.insert(0, str(_BACKEND_ROOT)) + +from shared.logging_redaction import ( # noqa: E402 + LOG_FORMAT_ERROR, + REDACTED, + REDACTED_BINARY, + install_safe_logging, + is_sensitive_key, + redact_text, + redact_value, + sanitize_log_record, +) + +__all__ = [ + "LOG_FORMAT_ERROR", + "REDACTED", + "REDACTED_BINARY", + "install_safe_logging", + "is_sensitive_key", + "redact_text", + "redact_value", + "sanitize_log_record", +] diff --git a/backend/ai-service/app/main.py b/backend/ai-service/app/main.py index ad3b9286..c30ca18b 100644 --- a/backend/ai-service/app/main.py +++ b/backend/ai-service/app/main.py @@ -1,8 +1,14 @@ -from fastapi import FastAPI +from app.core.safe_logging import install_safe_logging -from app.core.auth import enforce_internal_token as _enforce_internal_token -from app.routers.health import healthcheck, readiness, router as health_router -from app.routers.processing import ( +# Install before importing processing modules so initialization failures and +# exception paths cannot emit raw evidence or credentials. +install_safe_logging() + +from fastapi import FastAPI # noqa: E402 + +from app.core.auth import enforce_internal_token as _enforce_internal_token # noqa: E402 +from app.routers.health import healthcheck, readiness, router as health_router # noqa: E402 +from app.routers.processing import ( # noqa: E402 document_classify, document_ocr, document_quality, @@ -10,8 +16,8 @@ liveness_check, router as processing_router, ) -from app.runtime import configure_runtime_environment -from app.schemas.processing import ( +from app.runtime import configure_runtime_environment # noqa: E402 +from app.schemas.processing import ( # noqa: E402 AIResultResponse, DocumentClassificationRequest, DocumentOCRRequest, @@ -21,7 +27,7 @@ LivenessCheckRequest, ReadinessResponse, ) -from app.settings import get_settings +from app.settings import get_settings # noqa: E402 settings = get_settings() diff --git a/backend/ai-service/app/pipeline.py b/backend/ai-service/app/pipeline.py index 8792517f..9cca8a96 100644 --- a/backend/ai-service/app/pipeline.py +++ b/backend/ai-service/app/pipeline.py @@ -31,9 +31,7 @@ class ProcessingError(RuntimeError): class MediaAssetNotFoundError(RuntimeError): def __init__(self, storage_key: str, bucket_name: str): - message = ( - f"Media asset '{storage_key}' was not found in bucket '{bucket_name}'." - ) + message = "Media asset was not found in configured storage (media_asset_not_found)." super().__init__(message) self.storage_key = storage_key self.bucket_name = bucket_name diff --git a/backend/ai-service/tests/test_safe_logging.py b/backend/ai-service/tests/test_safe_logging.py new file mode 100644 index 00000000..fdfc744a --- /dev/null +++ b/backend/ai-service/tests/test_safe_logging.py @@ -0,0 +1,125 @@ +import io +import logging + +from app.core.safe_logging import REDACTED, install_safe_logging, redact_value + + +def _capture(logger: logging.Logger, formatter: str = "%(message)s"): + stream = io.StringIO() + handler = logging.StreamHandler(stream) + handler.setFormatter(logging.Formatter(formatter)) + logger.handlers = [handler] + logger.propagate = False + logger.setLevel(logging.INFO) + return stream + + +def test_managed_ai_uses_shared_nested_redaction_corpus(): + install_safe_logging() + payload = { + "authorization": "Bearer ai-secret", + "request": { + "email": "subject@example.test", + "document_number": "P1234567", + "safe_operation": "face_compare", + }, + "biometrics": { + "face_embedding": [0.12, 0.34], + "selfie_image": "base64-selfie", + }, + } + + redacted = redact_value(payload) + + assert redacted["authorization"] == REDACTED + assert redacted["request"]["email"] == REDACTED + assert redacted["request"]["document_number"] == REDACTED + assert redacted["request"]["safe_operation"] == "face_compare" + # A container explicitly named "biometrics" is sensitive as a whole. The + # redactor intentionally fails closed instead of retaining its structure. + assert redacted["biometrics"] == REDACTED + + +def test_managed_ai_logger_redacts_structured_context_and_exception_text(): + install_safe_logging() + logger = logging.getLogger("identitycore.ai.redaction-test") + stream = _capture(logger, "%(message)s context=%(context)s") + + try: + raise ValueError( + "api_key=provider-secret email=subject@example.test " + "image_base64=raw-biometric" + ) + except ValueError: + logger.exception( + "AI processing failed Authorization: Bearer %s", + "internal-shared-token", + extra={ + "context": { + "document_storage_key": "tenant/evidence/document.jpg", + "ocr_text": "raw OCR contents", + "operation": "document_ocr", + } + }, + ) + + output = stream.getvalue() + assert "provider-secret" not in output + assert "subject@example.test" not in output + assert "raw-biometric" not in output + assert "internal-shared-token" not in output + assert "tenant/evidence/document.jpg" not in output + assert "raw OCR contents" not in output + assert "document_ocr" in output + assert "Traceback" in output + + +def test_uvicorn_access_formatter_preserves_protocol_without_private_data(): + from uvicorn.logging import AccessFormatter + + install_safe_logging() + logger = logging.getLogger("uvicorn.access") + previous = (logger.handlers[:], logger.propagate, logger.level) + stream = _capture(logger) + logger.handlers[0].setFormatter( + AccessFormatter( + '%(client_addr)s - "%(request_line)s" %(status_code)s', use_colors=False + ) + ) + try: + logger.info( + '%s - "%s %s HTTP/%s" %d', + "192.0.2.1:1234", + "GET", + "/check?access_token=private-token", + "1.1", + 200, + ) + output = stream.getvalue() + assert "GET" in output + assert "200 OK" in output + assert "private-token" not in output + assert "192.0.2.1" not in output + assert "HTTP/1.1" in output + finally: + logger.handlers, logger.propagate, logger.level = previous + + +def test_numpy_buffers_do_not_render_pixels_or_embeddings(): + import numpy as np + from app.core.safe_logging import REDACTED_BINARY + + for value in ( + np.array([17, 18], dtype=np.uint8), + np.array([0.125, 0.25], dtype=np.float32), + ): + assert redact_value({"frame": value}) == {"frame": REDACTED_BINARY} + + +def test_missing_media_error_does_not_expose_evidence_location(): + from app.pipeline import MediaAssetNotFoundError + + error = MediaAssetNotFoundError("tenant/evidence/private.jpg", "private-bucket") + assert "tenant/evidence/private.jpg" not in str(error) + assert "private-bucket" not in str(error) + assert "media_asset_not_found" in str(error) diff --git a/backend/django/Dockerfile b/backend/django/Dockerfile index 33111902..6a7b8056 100644 --- a/backend/django/Dockerfile +++ b/backend/django/Dockerfile @@ -22,6 +22,7 @@ RUN uv export \ --output-file /tmp/requirements-django.txt \ && pip install --no-cache-dir -r /tmp/requirements-django.txt +COPY backend/shared /app/backend/shared COPY backend/django /app/backend/django COPY docs/openapi/identitycore-public-api.yaml /app/docs/openapi/identitycore-public-api.yaml diff --git a/backend/django/apps/core/apps.py b/backend/django/apps/core/apps.py index 68868e8b..665f028d 100644 --- a/backend/django/apps/core/apps.py +++ b/backend/django/apps/core/apps.py @@ -5,3 +5,10 @@ class CoreConfig(AppConfig): default_auto_field = "django.db.models.BigAutoField" name = "apps.core" label = "core" + + def ready(self) -> None: + # Install the redaction boundary after Django configures logging but before + # request/worker code can emit application records. + from common.safe_logging import install_safe_logging + + install_safe_logging() diff --git a/backend/django/apps/identity_documents/tasks.py b/backend/django/apps/identity_documents/tasks.py index bce3b65e..6dade485 100644 --- a/backend/django/apps/identity_documents/tasks.py +++ b/backend/django/apps/identity_documents/tasks.py @@ -563,10 +563,10 @@ def process_identity_document_task(identity_document_id: str) -> str: promote_upload_to_media_by_storage_key(capture.storage_key) except Exception as exc: logger.warning( - "Failed to promote document upload %s for verification %s: %s", - capture.storage_key, + "Failed to promote document upload for verification %s (%s)", verification.public_id, - exc, + type(exc).__name__, + extra={"storage_key": capture.storage_key}, ) record_audit_event( tenant=verification.tenant, diff --git a/backend/django/apps/identity_documents/tests.py b/backend/django/apps/identity_documents/tests.py index 94799f75..052716f3 100644 --- a/backend/django/apps/identity_documents/tests.py +++ b/backend/django/apps/identity_documents/tests.py @@ -437,7 +437,10 @@ def test_process_identity_document_task_keeps_processing_when_promotion_fails( } mock_promote.side_effect = RuntimeError("storage unavailable") - result = process_identity_document_task(self.identity_document.public_id) + with self.assertLogs("apps.identity_documents.tasks", level="WARNING") as captured: + result = process_identity_document_task(self.identity_document.public_id) + self.assertNotIn(self.upload.storage_key, " ".join(captured.output)) + self.assertEqual(captured.records[0].storage_key, "[REDACTED]") self.assertEqual(result, IdentityDocumentStatus.PROCESSED) self.identity_document.refresh_from_db() diff --git a/backend/django/common/safe_logging.py b/backend/django/common/safe_logging.py new file mode 100644 index 00000000..5c0ef2dc --- /dev/null +++ b/backend/django/common/safe_logging.py @@ -0,0 +1,30 @@ +from __future__ import annotations + +import sys +from pathlib import Path + +_BACKEND_ROOT = Path(__file__).resolve().parents[2] +if str(_BACKEND_ROOT) not in sys.path: + sys.path.insert(0, str(_BACKEND_ROOT)) + +from shared.logging_redaction import ( # noqa: E402 + LOG_FORMAT_ERROR, + REDACTED, + REDACTED_BINARY, + install_safe_logging, + is_sensitive_key, + redact_text, + redact_value, + sanitize_log_record, +) + +__all__ = [ + "LOG_FORMAT_ERROR", + "REDACTED", + "REDACTED_BINARY", + "install_safe_logging", + "is_sensitive_key", + "redact_text", + "redact_value", + "sanitize_log_record", +] diff --git a/backend/django/common/test_safe_logging.py b/backend/django/common/test_safe_logging.py new file mode 100644 index 00000000..3c8fecd8 --- /dev/null +++ b/backend/django/common/test_safe_logging.py @@ -0,0 +1,122 @@ +import io +import logging + +from celery.utils.log import get_task_logger +from django.test import SimpleTestCase + +from common.safe_logging import REDACTED, REDACTED_BINARY, install_safe_logging, redact_value + + +class SafeLoggingTests(SimpleTestCase): + @classmethod + def setUpClass(cls): + super().setUpClass() + install_safe_logging() + + def _capture(self, logger: logging.Logger, formatter: str = "%(levelname)s %(message)s"): + stream = io.StringIO() + handler = logging.StreamHandler(stream) + handler.setFormatter(logging.Formatter(formatter)) + logger.handlers = [handler] + logger.propagate = False + logger.setLevel(logging.INFO) + self.addCleanup(logger.handlers.clear) + return stream + + def test_recursive_redaction_covers_secret_pii_and_biometric_fields(self): + payload = { + "authorization": "Bearer top-secret", + "profile": { + "email": "ada@example.test", + "phone_number": "+233241234567", + "document_number": "GHA-123456789", + "safe_status": "pending_review", + }, + "evidence": { + "selfie_image": "base64-sensitive-selfie", + "face_embedding": [0.1, 0.2, 0.3], + "document_storage_key": "tenant/evidence/front.jpg", + }, + "binary": b"document-bytes", + } + + redacted = redact_value(payload) + + self.assertEqual(redacted["authorization"], REDACTED) + self.assertEqual(redacted["profile"]["email"], REDACTED) + self.assertEqual(redacted["profile"]["phone_number"], REDACTED) + self.assertEqual(redacted["profile"]["document_number"], REDACTED) + self.assertEqual(redacted["profile"]["safe_status"], "pending_review") + self.assertEqual(redacted["evidence"]["selfie_image"], REDACTED) + self.assertEqual(redacted["evidence"]["face_embedding"], REDACTED) + self.assertEqual(redacted["evidence"]["document_storage_key"], REDACTED) + self.assertEqual(redacted["binary"], REDACTED_BINARY) + + def test_django_logger_redacts_message_arguments_and_structured_extra(self): + logger = logging.getLogger("django.identitycore.redaction-test") + stream = self._capture(logger, "%(message)s payload=%(payload)s") + + logger.info( + "request rejected email=%s Authorization: Bearer %s", + "ada@example.test", + "secret-access-token", + extra={ + "payload": { + "password": "never-log-this", + "selfie_image": "raw-biometric-data", + "safe_reason": "credentials_missing", + } + }, + ) + + output = stream.getvalue() + self.assertNotIn("ada@example.test", output) + self.assertNotIn("secret-access-token", output) + self.assertNotIn("never-log-this", output) + self.assertNotIn("raw-biometric-data", output) + self.assertIn("credentials_missing", output) + self.assertIn(REDACTED, output) + + def test_celery_task_logger_uses_the_same_redaction_boundary(self): + logger = get_task_logger("identitycore.redaction-test") + stream = self._capture(logger, "%(message)s context=%(context)s") + + logger.warning( + "worker retry token=%s", + "celery-secret-token", + extra={ + "context": { + "api_key": "provider-key", + "ocr_text": "raw document text", + "verification_id": "ver_safe_public_id", + } + }, + ) + + output = stream.getvalue() + self.assertNotIn("celery-secret-token", output) + self.assertNotIn("provider-key", output) + self.assertNotIn("raw document text", output) + self.assertIn("ver_safe_public_id", output) + + def test_exception_traceback_is_preserved_without_sensitive_values(self): + logger = logging.getLogger("identitycore.exception-redaction-test") + stream = self._capture(logger) + + try: + raise RuntimeError( + "token=runtime-secret email=ada@example.test " + "phone=+233241234567 document_number=GHA-123456789" + ) + except RuntimeError: + logger.exception("provider failed first_name=Ada") + + output = stream.getvalue() + self.assertIn("Traceback", output) + self.assertIn("RuntimeError", output) + self.assertNotIn("runtime-secret", output) + self.assertNotIn("ada@example.test", output) + self.assertNotIn("+233241234567", output) + self.assertNotIn("GHA-123456789", output) + self.assertNotIn("first_name=Ada", output) + self.assertIn("first_name=[REDACTED]", output) diff --git a/backend/django/common/test_safe_logging_boundaries.py b/backend/django/common/test_safe_logging_boundaries.py new file mode 100644 index 00000000..8dd6d1c6 --- /dev/null +++ b/backend/django/common/test_safe_logging_boundaries.py @@ -0,0 +1,286 @@ +import io +import logging + +from django.test import SimpleTestCase +from django.test import RequestFactory, override_settings +from django.utils.log import AdminEmailHandler + +from common.safe_logging import LOG_FORMAT_ERROR, install_safe_logging + + +class CapturingAdminEmailHandler(AdminEmailHandler): + def __init__(self): + super().__init__() + self.sent_messages = [] + + def send_mail( + self, subject, message, *args, fail_silently=False, html_message=None, **kwargs + ): + self.sent_messages.append((subject, message, html_message)) + + +class SafeLoggingBoundaryTests(SimpleTestCase): + @classmethod + def setUpClass(cls): + super().setUpClass() + install_safe_logging() + + def _capture(self, logger_name: str): + stream = io.StringIO() + handler = logging.StreamHandler(stream) + handler.setFormatter(logging.Formatter("%(message)s context=%(context)s")) + logger = logging.getLogger(logger_name) + logger.handlers = [handler] + logger.propagate = False + logger.setLevel(logging.INFO) + self.addCleanup(logger.handlers.clear) + return logger, stream + + def test_storage_and_provider_loggers_share_the_global_boundary(self): + for logger_name in ("common.storage", "apps.providers.services"): + with self.subTest(logger=logger_name): + logger, stream = self._capture(logger_name) + logger.info( + "operation completed", + extra={ + "context": { + "storage_key": "tenant/evidence/private.jpg", + "client_secret": "provider-secret", + "external_reference": "customer-4482", + "device_fingerprint": "device-secret", + "user_agent": "browser-fingerprint", + "verification_subject_id": "vs_sensitive", + "provider_code": "safe-provider-code", + } + }, + ) + output = stream.getvalue() + self.assertNotIn("tenant/evidence/private.jpg", output) + self.assertNotIn("provider-secret", output) + self.assertNotIn("customer-4482", output) + self.assertNotIn("device-secret", output) + self.assertNotIn("browser-fingerprint", output) + self.assertNotIn("vs_sensitive", output) + self.assertIn("safe-provider-code", output) + + def test_exception_objects_and_sensitive_mapping_keys_are_sanitized(self): + logger, stream = self._capture("identitycore.argument-redaction-test") + error = RuntimeError("token=exception-secret; email=subject@example.test") + + logger.error( + "provider error: %s", + error, + extra={"context": {"subject@example.test": "lookup", "status": "failed"}}, + ) + + output = stream.getvalue() + self.assertNotIn("exception-secret", output) + self.assertNotIn("subject@example.test", output) + self.assertIn("RuntimeError", output) + self.assertIn("failed", output) + + def test_admin_email_handler_receives_sanitized_exception_context(self): + handler = CapturingAdminEmailHandler() + logger = logging.getLogger("django.request.safe-email-test") + logger.handlers = [handler] + logger.propagate = False + logger.setLevel(logging.ERROR) + self.addCleanup(logger.handlers.clear) + + try: + raise RuntimeError("token=email-secret; status=failed") + except RuntimeError: + logger.exception("request failed") + + self.assertEqual(len(handler.sent_messages), 1) + message = handler.sent_messages[0][1] + self.assertIn( + "test_admin_email_handler_receives_sanitized_exception_context", message + ) + self.assertIn("RuntimeError", message) + self.assertNotIn("email-secret", message) + + @override_settings(INTERNAL_IPS=["10.0.0.1"]) + def test_admin_email_handler_receives_safe_request_context(self): + handler = CapturingAdminEmailHandler() + logger = logging.getLogger("django.request.safe-request-email-test") + logger.handlers = [handler] + logger.propagate = False + logger.setLevel(logging.ERROR) + self.addCleanup(logger.handlers.clear) + request = RequestFactory().post( + "/api/v1/verifications/", + {"email": "subject@example.test", "token": "request-secret"}, + HTTP_AUTHORIZATION="Bearer auth-secret", + REMOTE_ADDR="10.0.0.1", + ) + request.user = "subject@example.test" + + try: + raise RuntimeError("token=exception-secret") + except RuntimeError: + logger.exception("request failed", extra={"request": request}) + + self.assertEqual(len(handler.sent_messages), 1) + subject, message, html_message = handler.sent_messages[0] + self.assertIn("internal IP", subject) + self.assertIn("/api/v1/verifications/", message) + self.assertIn("POST", message) + self.assertIn("REMOTE_ADDR = '[REDACTED]'", message) + complete_report = message + (html_message or "") + self.assertNotIn("subject@example.test", complete_report) + self.assertNotIn("request-secret", complete_report) + self.assertNotIn("auth-secret", complete_report) + self.assertNotIn("exception-secret", complete_report) + + def test_interpolated_structures_and_bytes_are_redacted(self): + logger, stream = self._capture("identitycore.structured-arguments-test") + logger.info( + "payload=%s binary=%s attempts=%03d", + {"storage_key": "tenant/private.jpg", "status": "failed"}, + b"private-document-content", + 7, + extra={"context": {}}, + ) + output = stream.getvalue() + self.assertNotIn("tenant/private.jpg", output) + self.assertNotIn("private-document-content", output) + self.assertIn("failed", output) + self.assertIn("attempts=007", output) + + def test_mapping_interpolation_preserves_exception_type_and_numbers(self): + logger, stream = self._capture("identitycore.mapping-arguments-test") + logger.error( + "error=%(error)s; attempts=%(attempts)03d", + {"error": RuntimeError("token=private-token"), "attempts": 7}, + extra={"context": {}}, + ) + output = stream.getvalue() + self.assertNotIn("private-token", output) + self.assertIn("RuntimeError", output) + self.assertIn("attempts=007", output) + + def test_multiword_pii_in_free_text_is_fully_removed(self): + logger, stream = self._capture("identitycore.multiword-redaction-test") + logger.info( + "review full_name=Ada Lovelace; external_reference=customer-4482; status=pending", + extra={"context": {"status": "pending"}}, + ) + + output = stream.getvalue() + self.assertNotIn("Ada Lovelace", output) + self.assertNotIn("customer-4482", output) + self.assertIn("status=pending", output) + + def test_malformed_format_string_does_not_raise_or_render_arguments(self): + logger, stream = self._capture("identitycore.format-error-test") + logger.info( + "provider failed without placeholder", + "secret-that-must-not-render", + extra={"context": {"status": "failed"}}, + ) + + output = stream.getvalue() + self.assertNotIn("secret-that-must-not-render", output) + self.assertIn(LOG_FORMAT_ERROR, output) + self.assertIn("failed", output) + + def test_all_sensitive_keys_are_redacted_in_serialized_text(self): + from common.safe_logging import redact_text + from shared.logging_redaction import _SENSITIVE_KEYS + + for key in _SENSITIVE_KEYS: + for spelling in (key, key.replace("_", "-"), key.upper()): + for message in ( + f'{{"{spelling}":"private-value"}}', + f"?{spelling}=private-value&status=failed", + f"{spelling}='private-value'; status=failed", + ): + with self.subTest(message=message): + self.assertNotIn("private-value", redact_text(message)) + for message in ( + '{"context":{"access_token":"private-value"}}', + '{"face_embedding":["private-value", "second-private"]}', + '{"private_key":"private-value\\"still-private"}', + "full_name=Doe, Jane", + 'face_embedding=[\n 0.123,\n 0.456\n], "status":"failed"', + ): + self.assertNotIn("private-value", redact_text(message)) + self.assertNotIn("second-private", redact_text(message)) + self.assertNotIn("still-private", redact_text(message)) + self.assertNotIn("Jane", redact_text(message)) + self.assertNotIn("0.123", redact_text(message)) + self.assertNotIn("0.456", redact_text(message)) + + def test_underscore_prefixed_extras_are_sanitized(self): + logger, stream = self._capture("identitycore.private-extra-test") + logger.handlers[0].setFormatter(logging.Formatter("%(_password)s %(_context)s")) + logger.info( + "request failed", + extra={ + "_password": "private-password", + "_context": {"token": "private-token"}, + }, + ) + self.assertNotIn("private-password", stream.getvalue()) + self.assertNotIn("private-token", stream.getvalue()) + + def test_deployed_credentials_signatures_and_ipv6_are_redacted(self): + from common.safe_logging import REDACTED, redact_text, redact_value + + for key in ( + "SECRET_KEY", + "DJANGO_SECRET_KEY", + "object_storage_access_key_id", + "object_storage_secret_access_key", + "aws_access_key_id", + "aws_secret_access_key", + "X-Amz-Signature", + "X-IdentityCore-Signature", + ): + self.assertEqual(redact_value({key: "private-value"})[key], REDACTED) + self.assertNotIn( + "private-value", redact_text(f"?{key}=private-value&status=ok") + ) + for address in ( + "2001:db8:1234:5678:9abc:def0:1234:5678", + "2001:db8::1", + "::1", + "::ffff:192.0.2.1", + "fe80::1%eth0", + ): + self.assertNotIn(address, redact_text(f"client connected from [{address}]")) + self.assertEqual( + redact_text("time 12:34:56; status=ok"), "time 12:34:56; status=ok" + ) + self.assertNotIn( + "private-value", redact_text("token=[REDACTED]private-value; status=ok") + ) + + def test_camel_case_sensitive_keys_are_redacted(self): + from common.safe_logging import REDACTED, redact_value + + redacted = redact_value( + { + "accessToken": "access-private", + "sessionToken": "session-private", + "clientSecret": "client-private", + "fullName": "Ada Private", + "safeStatus": "ready", + } + ) + self.assertEqual(redacted["accessToken"], REDACTED) + self.assertEqual(redacted["sessionToken"], REDACTED) + self.assertEqual(redacted["clientSecret"], REDACTED) + self.assertEqual(redacted["fullName"], REDACTED) + self.assertEqual(redacted["safeStatus"], "ready") + + def test_missing_mapping_key_and_overflow_do_not_escape_logging(self): + logger, stream = self._capture("identitycore.interpolation-failures-test") + for message, argument in ( + ("%(missing)s", {"present": "private-value"}), + ("%c", 0x110000), + ): + logger.info(message, argument, extra={"context": {}}) + self.assertEqual(stream.getvalue().count(LOG_FORMAT_ERROR), 2) + self.assertNotIn("private-value", stream.getvalue()) diff --git a/backend/django/config/celery.py b/backend/django/config/celery.py index 1d803399..2610c9d7 100644 --- a/backend/django/config/celery.py +++ b/backend/django/config/celery.py @@ -2,6 +2,12 @@ from celery import Celery +from common.safe_logging import install_safe_logging + + +# Celery can initialize its own logging before Django app-ready hooks run. Install +# the redaction boundary here as well so broker/startup and task logs are protected. +install_safe_logging() os.environ.setdefault("DJANGO_SETTINGS_MODULE", "config.settings.development") diff --git a/backend/shared/__init__.py b/backend/shared/__init__.py new file mode 100644 index 00000000..71cd720a --- /dev/null +++ b/backend/shared/__init__.py @@ -0,0 +1 @@ +"""Shared backend utilities used by both Django and managed AI services.""" diff --git a/backend/shared/logging_redaction.py b/backend/shared/logging_redaction.py new file mode 100644 index 00000000..787c6493 --- /dev/null +++ b/backend/shared/logging_redaction.py @@ -0,0 +1,454 @@ +from __future__ import annotations + +import ipaddress +import logging +import re +import traceback +from copy import copy +from collections.abc import Mapping +from threading import Lock +from typing import Any + +REDACTED = "[REDACTED]" +REDACTED_BINARY = "[REDACTED_BINARY]" +MAX_REDACTION_DEPTH = 12 +LOG_FORMAT_ERROR = "[LOG_FORMAT_ERROR]" + + +class _SanitizedLogException(Exception): + """Exception wrapper consumable by handlers without exposing live frames.""" + + +class _SanitizedRequestMeta(dict): + def __init__(self, *args, classification_ip: str, **kwargs): + super().__init__(*args, **kwargs) + self._classification_ip = classification_ip + + def get(self, key, default=None): + if key == "REMOTE_ADDR": + return self._classification_ip + return super().get(key, default) + + +_SENSITIVE_KEYS = frozenset( + { + # Credentials and session material. + "access_key", + "access_key_id", + "secret_key", + "signature", + "access_token", + "api_key", + "authorization", + "client_secret", + "cookie", + "credentials", + "csrf_token", + "csrfmiddlewaretoken", + "id_token", + "password", + "passcode", + "private_key", + "refresh_token", + "secret", + "secret_access_key", + "session_token", + "set_cookie", + "token", + # Direct identifiers / PII / correlation values that may identify a subject. + "address", + "birth_date", + "client_ip", + "date_of_birth", + "device_fingerprint", + "dob", + "document_number", + "email", + "external_reference", + "first_name", + "full_name", + "ghana_card_number", + "ip", + "ip_address", + "last_name", + "middle_name", + "national_id", + "passport_number", + "phone", + "phone_number", + "postal_address", + "remote_addr", + "subject_id", + "tax_identification_number", + "tin", + "user_agent", + "verification_subject_id", + # Evidence locations and raw document / biometric material. + "biometric_payload", + "biometric_template", + "document_bytes", + "document_image", + "document_storage_key", + "face_embedding", + "face_image", + "image", + "image_base64", + "image_bytes", + "liveness_video", + "mrz", + "ocr_text", + "raw_document", + "raw_image", + "raw_ocr", + "selfie", + "selfie_image", + "selfie_storage_key", + "storage_key", + } +) + +_SENSITIVE_SUFFIXES = ( + "_secret_key", + "_access_key", + "_access_key_id", + "_signature", + "_access_token", + "_api_key", + "_authorization", + "_client_secret", + "_credential", + "_credentials", + "_fingerprint", + "_password", + "_private_key", + "_refresh_token", + "_secret", + "_session_token", + "_storage_key", + "_subject_id", + "_token", + "_user_agent", +) + +_SENSITIVE_FRAGMENTS = ( + "biometric", + "face_embedding", + "image_base64", + "image_bytes", + "liveness_video", + "selfie_image", +) + +_BEARER_RE = re.compile(r"(?i)\bBearer\s+[A-Za-z0-9._~+/=-]+") +_JWT_RE = re.compile(r"\beyJ[A-Za-z0-9_-]{8,}\.[A-Za-z0-9_-]{8,}\.[A-Za-z0-9_-]{8,}\b") +_EMAIL_RE = re.compile( + r"(?[\w.-]+)[\"']?\s*[:=]\s*") +_NEXT_ASSIGNMENT_BOUNDARY_RE = re.compile(r"[;&\n\r](?=\s*[\"']?[\w.-]+[\"']?\s*[:=])") +_AWS_ACCESS_KEY_RE = re.compile(r"\b(?:AKIA|ASIA)[A-Z0-9]{16}\b") +_STANDARD_LOG_RECORD_ATTRS = frozenset( + { + *logging.LogRecord(None, 0, "", 0, "", (), None).__dict__.keys(), + "asctime", + "message", + } +) + +_INSTALL_LOCK = Lock() +_INSTALLED = False +_ORIGINAL_MAKE_RECORD = logging.Logger.makeRecord + + +def _normalize_key(key: object) -> str: + text = re.sub(r"([a-z0-9])([A-Z])", r"\1_\2", str(key).strip()) + text = re.sub(r"([A-Z]+)([A-Z][a-z])", r"\1_\2", text) + normalized = re.sub(r"[^a-z0-9]+", "_", text.lower()) + return normalized.strip("_") + + +def is_sensitive_key(key: object) -> bool: + normalized = _normalize_key(key) + if not normalized: + return False + if normalized in _SENSITIVE_KEYS: + return True + if normalized.endswith(_SENSITIVE_SUFFIXES): + return True + return any(fragment in normalized for fragment in _SENSITIVE_FRAGMENTS) + + +def _assignment_value_end(value: str, start: int) -> int: + if start >= len(value): + return start + opener = value[start] + if opener in "\"'": + escaped = False + for index in range(start + 1, len(value)): + character = value[index] + if character == opener and not escaped: + return index + 1 + escaped = character == "\\" and not escaped + if character != "\\": + escaped = False + elif opener in "[{" and not value.startswith("[REDACTED", start): + pairs = {"[": "]", "{": "}"} + stack = [pairs[opener]] + quote = None + escaped = False + for index in range(start + 1, len(value)): + character = value[index] + if quote: + if character == quote and not escaped: + quote = None + escaped = character == "\\" and not escaped + if character != "\\": + escaped = False + elif character in "\"'": + quote = character + elif character in pairs: + stack.append(pairs[character]) + elif stack and character == stack[-1]: + stack.pop() + if not stack: + return index + 1 + boundary = _NEXT_ASSIGNMENT_BOUNDARY_RE.search(value, start) + return boundary.start() if boundary else len(value) + + +def redact_text(value: str) -> str: + """Redact common secret and PII shapes from unstructured log text.""" + redacted = _BEARER_RE.sub("Bearer [REDACTED]", value) + redacted = _JWT_RE.sub(REDACTED, redacted) + redacted = _AWS_ACCESS_KEY_RE.sub(REDACTED, redacted) + parts = [] + cursor = 0 + for match in _CREDENTIAL_ASSIGNMENT_RE.finditer(redacted): + if match.start() < cursor or not is_sensitive_key(match.group("label")): + continue + value_end = _assignment_value_end(redacted, match.end()) + parts.extend( + (redacted[cursor : match.start()], f"{match.group('label')}={REDACTED}") + ) + cursor = value_end + parts.append(redacted[cursor:]) + redacted = "".join(parts) + redacted = _EMAIL_RE.sub(REDACTED, redacted) + + def redact_ipv6(match): + try: + ipaddress.IPv6Address(match.group()) + except ValueError: + return match.group() + return REDACTED + + redacted = _IPV6_RE.sub(redact_ipv6, redacted) + redacted = _IPV4_RE.sub(REDACTED, redacted) + redacted = _PHONE_RE.sub(REDACTED, redacted) + return redacted + + +def redact_value(value: Any, *, key: object | None = None, _depth: int = 0) -> Any: + """Return a logging-safe copy of a nested value. + + Redaction is key-aware for structured payloads and shape-aware for free text. + Bytes are never logged because they can contain document or biometric evidence. + """ + if key is not None and is_sensitive_key(key): + return REDACTED + if _depth >= MAX_REDACTION_DEPTH: + return "[REDACTED_DEPTH_LIMIT]" + if value is None or isinstance(value, (bool, int, float)): + return value + if isinstance(value, str): + return redact_text(value) + if isinstance(value, BaseException): + return f"{value.__class__.__name__}: {redact_text(str(value))}" + if isinstance(value, (bytes, bytearray, memoryview)): + return REDACTED_BINARY + try: + with memoryview(value): + return REDACTED_BINARY + except TypeError: + pass + if isinstance(value, Mapping): + redacted_mapping = {} + for item_key, item_value in value.items(): + safe_key = redact_text(str(item_key)) + redacted_mapping[safe_key] = redact_value( + item_value, + key=item_key, + _depth=_depth + 1, + ) + return redacted_mapping + if isinstance(value, tuple): + return tuple(redact_value(item, _depth=_depth + 1) for item in value) + if isinstance(value, list): + return [redact_value(item, _depth=_depth + 1) for item in value] + if isinstance(value, (set, frozenset)): + return [redact_value(item, _depth=_depth + 1) for item in value] + return redact_text(str(value)) + + +def _redact_exception( + exc_info: tuple[type[BaseException], BaseException, Any], +) -> str: + rendered = "".join(traceback.format_exception(*exc_info)) + return redact_text(rendered) + + +def _sanitize_django_request(value: Any) -> Any: + """Return a shallow request copy that Django's error reporter can inspect safely.""" + if not ( + value.__class__.__module__.startswith("django.") + and hasattr(value, "META") + and hasattr(value, "method") + and hasattr(value, "path") + ): + return None + + sanitized = copy(value) + safe_meta_keys = { + "PATH_INFO", + "REQUEST_METHOD", + "SCRIPT_NAME", + "SERVER_NAME", + "SERVER_PORT", + "SERVER_PROTOCOL", + } + remote_addr = value.META.get("REMOTE_ADDR", "") + try: + from django.conf import settings + + internal_ips = set(settings.INTERNAL_IPS) + except Exception: + internal_ips = set() + classification_ip = ( + next(iter(internal_ips)) + if remote_addr in internal_ips and internal_ips + else REDACTED + ) + sanitized.META = _SanitizedRequestMeta( + { + key: redact_text(str(item)) + for key, item in value.META.items() + if key in safe_meta_keys + }, + classification_ip=classification_ip, + ) + sanitized.META["REMOTE_ADDR"] = REDACTED + + for attribute in ("GET", "POST", "FILES"): + original = getattr(value, attribute, None) + if original is None: + continue + safe_values = original.copy() + if hasattr(safe_values, "setlist"): + for key in safe_values: + safe_values.setlist(key, [REDACTED]) + else: + safe_values = {str(key): REDACTED for key in safe_values} + setattr(sanitized, f"_{attribute.lower()}", safe_values) + + sanitized.COOKIES = {str(key): REDACTED for key in value.COOKIES} + sanitized.user = REDACTED + sanitized._body = b"" + return sanitized + + +def sanitize_log_record(record: logging.LogRecord) -> logging.LogRecord: + """Sanitize rendered messages, structured extras, stack text, and exceptions.""" + if ( + record.name == "uvicorn.access" + and isinstance(record.args, tuple) + and len(record.args) == 5 + ): + # Uvicorn's AccessFormatter unpacks this tuple after getMessage(). Keep + # its protocol shape, but never expose client addresses or query strings. + client, method, path, version, status = record.args + record.args = ( + REDACTED, + redact_value(method), + REDACTED, + redact_value(version), + status, + ) + record.msg = '%s - "%s %s HTTP/%s" %d' + elif record.args: + # Preserve structured redaction and exception types before interpolation + # turns arguments into plain text. Numeric arguments retain their types. + if isinstance(record.args, Mapping): + record.args = { + key: redact_value(value, key=key) for key, value in record.args.items() + } + else: + record.args = redact_value(record.args) + # Render once using Python logging's normal interpolation rules, then redact + # the complete result. If the caller supplied a malformed format string, + # discard the args instead of letting logging break request/worker execution. + try: + rendered_message = record.getMessage() + except Exception: + rendered_message = LOG_FORMAT_ERROR + record.msg = redact_text(str(rendered_message)) + record.args = () + else: + record.msg = redact_value(record.msg) + + for field, value in list(record.__dict__.items()): + if field in _STANDARD_LOG_RECORD_ATTRS: + continue + sanitized_request = ( + _sanitize_django_request(value) if field == "request" else None + ) + record.__dict__[field] = ( + sanitized_request + if sanitized_request is not None + else redact_value(value, key=field) + ) + + if record.stack_info: + record.stack_info = redact_text(record.stack_info) + if record.exc_info: + record.exc_text = _redact_exception(record.exc_info) + record.exc_info = ( + _SanitizedLogException, + _SanitizedLogException(record.exc_text), + None, + ) + elif record.exc_text: + record.exc_text = redact_text(record.exc_text) + return record + + +def _safe_make_record(self, *args, **kwargs): + record = _ORIGINAL_MAKE_RECORD(self, *args, **kwargs) + return sanitize_log_record(record) + + +def install_safe_logging() -> None: + """Install the process-wide logging redaction boundary exactly once.""" + global _INSTALLED + if _INSTALLED: + return + with _INSTALL_LOCK: + if _INSTALLED: + return + logging.Logger.makeRecord = _safe_make_record + _INSTALLED = True + + +__all__ = [ + "LOG_FORMAT_ERROR", + "REDACTED", + "REDACTED_BINARY", + "install_safe_logging", + "is_sensitive_key", + "redact_text", + "redact_value", + "sanitize_log_record", +] diff --git a/docs/operations/logging-redaction.md b/docs/operations/logging-redaction.md new file mode 100644 index 00000000..c6210cbf --- /dev/null +++ b/docs/operations/logging-redaction.md @@ -0,0 +1,41 @@ +# Logging redaction and safe telemetry + +IdentityCore treats logs as an operational data stream, not as a place to store verification evidence or user data. Application logs must never contain credentials, session material, direct subject PII, raw document/OCR content, storage locations for evidence, or biometric payloads. + +## Backend boundary + +Django, Celery workers, storage/provider call paths, and the managed AI service use the shared redaction implementation in `backend/shared/logging_redaction.py`. + +The boundary is installed when Django starts, before Celery initializes its application logger, and before the AI service imports processing routes. It sanitizes every Python `LogRecord` after `extra` fields have been attached and before handlers format the record. This covers: + +- nested dictionaries/lists passed as structured logging context; +- positional and mapping logging arguments; +- bearer/JWT-like credentials and common credential assignments embedded in free text; +- common email, phone, and IP shapes in free text; +- exception messages and tracebacks; +- bytes and byte-like values, which are always replaced rather than rendered. + +Safe operational dimensions such as public request/verification IDs, operation names, status/reason codes, provider codes, durations, retry counts, and queue names may be logged when they do not themselves contain subject data. + +When a new secret, PII field, document field, or biometric representation is introduced, add its normalized key to the shared redaction corpus and add an adversarial test before using it in telemetry. + +## Frontend boundary + +Frontend code must use `safeLog` exported by `@identitycore/api-client`. The logger applies the same categories of key-aware and free-text redaction before calling the browser console. + +Direct `console.log`, `console.info`, `console.warn`, `console.error`, `console.debug`, or `console.trace` calls are rejected by the frontend lint gate for production source. This prevents a future component from bypassing the redaction helper with a raw API error, token, form state, capture payload, or server response. + +## What not to log + +Do not log: + +- authorization headers, API keys, passwords, cookies, refresh/session tokens, provider credentials, or private keys; +- names, email addresses, phone numbers, addresses, dates of birth, national/passport/document numbers, or tax identifiers; +- OCR/MRZ text, raw document images/bytes, evidence storage keys, selfies, face embeddings, liveness media, or biometric templates; +- complete request/response bodies from identity, provider, storage, or webhook operations. + +Prefer stable reason/error codes and public correlation identifiers over raw exception/request payloads. + +## Verification + +The CI suite includes adversarial tests for Django, Celery, managed AI, and frontend logging. Tests intentionally place sensitive values in nested structured fields, positional arguments, binary values, and exception text and assert that those values never reach formatted log output. Frontend lint also fails when production source introduces a direct console logging call. diff --git a/frontend/packages/api-client/package.json b/frontend/packages/api-client/package.json index db440b1f..18a252a8 100644 --- a/frontend/packages/api-client/package.json +++ b/frontend/packages/api-client/package.json @@ -7,6 +7,9 @@ "exports": { ".": "./src/index.ts" }, + "scripts": { + "lint": "tsc -p tsconfig.json && tsc -p tsconfig.safe-logging.json && node --test test/safe-logging.test.mjs ../../scripts/check-safe-logging.test.mjs && node ../../scripts/check-safe-logging.mjs" + }, "devDependencies": { "typescript": "^5" } diff --git a/frontend/packages/api-client/src/index.ts b/frontend/packages/api-client/src/index.ts index da2ff732..1d777429 100644 --- a/frontend/packages/api-client/src/index.ts +++ b/frontend/packages/api-client/src/index.ts @@ -1,3 +1,5 @@ +export * from "./safe-logging"; + export interface ApiSuccess { success: true; data: T; diff --git a/frontend/packages/api-client/src/safe-logging.ts b/frontend/packages/api-client/src/safe-logging.ts new file mode 100644 index 00000000..6f514159 --- /dev/null +++ b/frontend/packages/api-client/src/safe-logging.ts @@ -0,0 +1,263 @@ +export const REDACTED = "[REDACTED]"; +export const REDACTED_BINARY = "[REDACTED_BINARY]"; + +const MAX_REDACTION_DEPTH = 12; + +const SENSITIVE_KEYS = new Set([ + "access_key", + "access_key_id", + "secret_key", + "signature", + "access_token", + "address", + "api_key", + "authorization", + "biometric_payload", + "biometric_template", + "birth_date", + "client_ip", + "client_secret", + "cookie", + "credentials", + "csrf_token", + "csrfmiddlewaretoken", + "date_of_birth", + "device_fingerprint", + "dob", + "document_bytes", + "document_image", + "document_number", + "document_storage_key", + "email", + "external_reference", + "face_embedding", + "face_image", + "first_name", + "full_name", + "ghana_card_number", + "id_token", + "image", + "image_base64", + "image_bytes", + "ip", + "ip_address", + "last_name", + "liveness_video", + "middle_name", + "mrz", + "national_id", + "ocr_text", + "passport_number", + "password", + "passcode", + "phone", + "phone_number", + "postal_address", + "private_key", + "raw_document", + "raw_image", + "raw_ocr", + "refresh_token", + "remote_addr", + "secret", + "secret_access_key", + "selfie", + "selfie_image", + "selfie_storage_key", + "session_token", + "set_cookie", + "storage_key", + "subject_id", + "tax_identification_number", + "tin", + "token", + "user_agent", + "verification_subject_id", +]); + +const SENSITIVE_SUFFIXES = [ + "_secret_key", + "_access_key", + "_access_key_id", + "_signature", + "_access_token", + "_api_key", + "_authorization", + "_client_secret", + "_credential", + "_credentials", + "_fingerprint", + "_password", + "_private_key", + "_refresh_token", + "_secret", + "_session_token", + "_storage_key", + "_subject_id", + "_token", + "_user_agent", +]; + +const SENSITIVE_FRAGMENTS = [ + "biometric", + "face_embedding", + "image_base64", + "image_bytes", + "liveness_video", + "selfie_image", +]; + +function normalizeKey(key: PropertyKey): string { + return String(key) + .trim() + .replace(/([a-z0-9])([A-Z])/g, "$1_$2") + .replace(/([A-Z]+)([A-Z][a-z])/g, "$1_$2") + .toLowerCase() + .replace(/[^a-z0-9]+/g, "_") + .replace(/^_+|_+$/g, ""); +} + +export function isSensitiveLogKey(key: PropertyKey): boolean { + const normalized = normalizeKey(key); + if (!normalized) return false; + return ( + SENSITIVE_KEYS.has(normalized) || + SENSITIVE_SUFFIXES.some((suffix) => normalized.endsWith(suffix)) || + SENSITIVE_FRAGMENTS.some((fragment) => normalized.includes(fragment)) + ); +} + +function assignmentValueEnd(value: string, start: number): number { + if (start >= value.length) return start; + const opener = value[start]; + if (opener === '"' || opener === "'") { + let escaped = false; + for (let index = start + 1; index < value.length; index += 1) { + const character = value[index]; + if (character === opener && !escaped) return index + 1; + escaped = character === "\\" && !escaped; + if (character !== "\\") escaped = false; + } + } else if ((opener === "[" || opener === "{") && !value.startsWith("[REDACTED", start)) { + const pairs: Record = { "[": "]", "{": "}" }; + const stack = [pairs[opener]]; + let quote: string | undefined; + let escaped = false; + for (let index = start + 1; index < value.length; index += 1) { + const character = value[index]; + if (quote) { + if (character === quote && !escaped) quote = undefined; + escaped = character === "\\" && !escaped; + if (character !== "\\") escaped = false; + } else if (character === '"' || character === "'") { + quote = character; + } else if (character in pairs) { + stack.push(pairs[character]); + } else if (character === stack.at(-1)) { + stack.pop(); + if (stack.length === 0) return index + 1; + } + } + } + const boundary = value.slice(start).search(/[;&\n\r](?=\s*["']?[\w.-]+["']?\s*[:=])/); + return boundary === -1 ? value.length : start + boundary; +} + +function isIpv6(value: string): boolean { + const address = value.split("%")[0]; + if (!address.includes(":")) return false; + let normalized = address; + if (address.includes(".")) { + const lastColon = address.lastIndexOf(":"); + const octets = address.slice(lastColon + 1).split("."); + if ( + octets.length !== 4 || + octets.some((part) => !/^\d{1,3}$/.test(part) || Number(part) > 255) + ) + return false; + normalized = address.slice(0, lastColon + 1) + "0:0"; + } + const parts = normalized.split(":"); + if (parts.some((part) => !/^[0-9a-f]{0,4}$/i.test(part))) return false; + if (!normalized.includes("::")) + return parts.length === 8 && parts.every(Boolean); + if (normalized.indexOf("::") !== normalized.lastIndexOf("::")) return false; + if (normalized.startsWith(":") && !normalized.startsWith("::")) return false; + if (normalized.endsWith(":") && !normalized.endsWith("::")) return false; + return parts.filter(Boolean).length < 8; +} + +export function redactLogText(value: string): string { + const redacted = value + .replace(/\bBearer\s+[A-Za-z0-9._~+/=-]+/gi, "Bearer [REDACTED]") + .replace( + /\beyJ[A-Za-z0-9_-]{8,}\.[A-Za-z0-9_-]{8,}\.[A-Za-z0-9_-]{8,}\b/g, + REDACTED, + ) + .replace(/\b(?:AKIA|ASIA)[A-Z0-9]{16}\b/g, REDACTED); + const assignment = /([\w.-]+)["']?\s*[:=]\s*/g; + let output = ""; + let cursor = 0; + for (const match of redacted.matchAll(assignment)) { + if (match.index < cursor || !isSensitiveLogKey(match[1])) continue; + output += redacted.slice(cursor, match.index) + `${match[1]}=${REDACTED}`; + cursor = assignmentValueEnd(redacted, match.index + match[0].length); + } + return (output + redacted.slice(cursor)) + .replace(/[A-Z0-9._%+-]+@[A-Z0-9.-]+\.[A-Z]{2,}/gi, REDACTED) + .replace(/(? + isIpv6(address) ? REDACTED : address, + ) + .replace(/\b(?:\d{1,3}\.){3}\d{1,3}\b/g, REDACTED) + .replace(/(?:\+?\d[\d ().-]{7,}\d)/g, REDACTED); +} + +export function redactLogValue( + value: unknown, + key?: PropertyKey, + depth = 0, +): unknown { + if (key !== undefined && isSensitiveLogKey(key)) return REDACTED; + if (depth >= MAX_REDACTION_DEPTH) return "[REDACTED_DEPTH_LIMIT]"; + if (value === null || value === undefined) return value; + if (typeof value === "string") return redactLogText(value); + if (typeof value === "number" || typeof value === "boolean") return value; + if (ArrayBuffer.isView(value) || value instanceof ArrayBuffer) { + return REDACTED_BINARY; + } + if (Array.isArray(value)) { + return value.map((item) => redactLogValue(item, undefined, depth + 1)); + } + if (typeof value === "object") { + const output: Record = {}; + for (const [entryKey, entryValue] of Object.entries(value)) { + output[redactLogText(entryKey)] = redactLogValue( + entryValue, + entryKey, + depth + 1, + ); + } + return output; + } + return redactLogText(String(value)); +} + +export type SafeLogLevel = "debug" | "info" | "warn" | "error"; + +const LOG_METHODS: Record void> = { + debug: console.debug.bind(console), + info: console.info.bind(console), + warn: console.warn.bind(console), + error: console.error.bind(console), +}; + +export function safeLog( + level: SafeLogLevel, + event: string, + context: Record = {}, +): void { + LOG_METHODS[level]({ + event: redactLogText(event), + context: redactLogValue(context), + }); +} diff --git a/frontend/packages/api-client/test/safe-logging.test.mjs b/frontend/packages/api-client/test/safe-logging.test.mjs new file mode 100644 index 00000000..9eeb376c --- /dev/null +++ b/frontend/packages/api-client/test/safe-logging.test.mjs @@ -0,0 +1,168 @@ +import assert from "node:assert/strict"; +import { rmSync } from "node:fs"; +import { createRequire } from "node:module"; +import { after, test } from "node:test"; + +const require = createRequire(import.meta.url); +const { + REDACTED, + REDACTED_BINARY, + redactLogText, + redactLogValue, +} = require("../.safe-logging-test/safe-logging.js"); + +after(() => { + rmSync(new URL("../.safe-logging-test", import.meta.url), { + force: true, + recursive: true, + }); +}); + +test("redacts nested credentials, PII, evidence, and binary values", () => { + const redacted = redactLogValue({ + authorization: "Bearer secret-token", + profile: { + email: "ada@example.test", + phone_number: "+233241234567", + document_number: "GHA-123456789", + external_reference: "customer-4482", + device_fingerprint: "device-secret", + user_agent: "browser-fingerprint", + verification_subject_id: "vs_sensitive", + safe_status: "pending_review", + }, + evidence: { + selfie_image: "base64-selfie", + face_embedding: [0.1, 0.2], + document_storage_key: "tenant/evidence/front.jpg", + }, + binary: new Uint8Array([1, 2, 3]), + }); + + assert.equal(redacted.authorization, REDACTED); + assert.equal(redacted.profile.email, REDACTED); + assert.equal(redacted.profile.phone_number, REDACTED); + assert.equal(redacted.profile.document_number, REDACTED); + assert.equal(redacted.profile.external_reference, REDACTED); + assert.equal(redacted.profile.device_fingerprint, REDACTED); + assert.equal(redacted.profile.user_agent, REDACTED); + assert.equal(redacted.profile.verification_subject_id, REDACTED); + assert.equal(redacted.profile.safe_status, "pending_review"); + assert.equal(redacted.evidence.selfie_image, REDACTED); + assert.equal(redacted.evidence.face_embedding, REDACTED); + assert.equal(redacted.evidence.document_storage_key, REDACTED); + assert.equal(redacted.binary, REDACTED_BINARY); +}); + +test("redacts secrets and multiword identifiers embedded in free text", () => { + const output = redactLogText( + "full_name=Ada Lovelace; token=top-secret; email=ada@example.test; phone=+233241234567; external_reference=customer-4482; document_number=GHA-123; Authorization: Bearer bearer-secret", + ); + + assert.doesNotMatch( + output, + /Ada Lovelace|top-secret|ada@example\.test|233241234567|customer-4482|GHA-123|bearer-secret/, + ); + assert.match(output, /\[REDACTED\]/); +}); + +test("redacts quoted keys, credential spellings, and nested serialized values", () => { + for (const key of [ + "access_token", + "id_token", + "private_key", + "secret_access_key", + "document_number", + "csrfmiddlewaretoken", + "storage_key", + "face_embedding", + ]) { + for (const spelling of [key, key.replaceAll("_", "-"), key.toUpperCase()]) { + for (const value of [ + `{"${spelling}":"private-value"}`, + `?${spelling}=private-value&status=failed`, + `${spelling}='private-value'; status=failed`, + ]) { + assert.doesNotMatch(redactLogText(value), /private-value/); + } + } + } + for (const value of [ + '{"context":{"access_token":"private-value"}}', + '{"face_embedding":["private-value", "second-private"]}', + '{"private_key":"private-value\\"still-private"}', + "full_name=Doe, Jane", + 'face_embedding=[\n 0.123,\n 0.456\n], "status":"failed"', + ]) { + assert.doesNotMatch( + redactLogText(value), + /private-value|second-private|still-private|Jane|0\.123|0\.456/, + ); + } +}); + +test("redacts all binary array views before object traversal", () => { + for (const view of [ + new Uint8ClampedArray([17]), + new Uint16Array([18]), + new Float32Array([0.25]), + new DataView(new ArrayBuffer(4)), + ]) { + assert.deepEqual(redactLogValue({ imageData: view }), { + imageData: REDACTED_BINARY, + }); + } +}); + +test("redacts deployed credential names, signatures, and IPv6 addresses", () => { + for (const key of [ + "SECRET_KEY", + "DJANGO_SECRET_KEY", + "object_storage_access_key_id", + "object_storage_secret_access_key", + "aws_access_key_id", + "aws_secret_access_key", + "X-Amz-Signature", + "X-IdentityCore-Signature", + ]) { + assert.equal(redactLogValue({ [key]: "private-value" })[key], REDACTED); + assert.doesNotMatch( + redactLogText(`?${key}=private-value&status=ok`), + /private-value/, + ); + } + for (const address of [ + "2001:db8:1234:5678:9abc:def0:1234:5678", + "2001:db8::1", + "::1", + "::ffff:192.0.2.1", + "fe80::1%eth0", + ]) { + assert.ok( + !redactLogText(`client connected from [${address}]`).includes(address), + ); + } + assert.equal( + redactLogText("time 12:34:56; status=ok"), + "time 12:34:56; status=ok", + ); + assert.doesNotMatch( + redactLogText("token=[REDACTED]private-value; status=ok"), + /private-value/, + ); +}); + +test("redacts camelCase credential and identity keys", () => { + const redacted = redactLogValue({ + accessToken: "access-private", + sessionToken: "session-private", + clientSecret: "client-private", + fullName: "Ada Private", + safeStatus: "ready", + }); + assert.equal(redacted.accessToken, REDACTED); + assert.equal(redacted.sessionToken, REDACTED); + assert.equal(redacted.clientSecret, REDACTED); + assert.equal(redacted.fullName, REDACTED); + assert.equal(redacted.safeStatus, "ready"); +}); diff --git a/frontend/packages/api-client/tsconfig.safe-logging.json b/frontend/packages/api-client/tsconfig.safe-logging.json new file mode 100644 index 00000000..c33b4fd3 --- /dev/null +++ b/frontend/packages/api-client/tsconfig.safe-logging.json @@ -0,0 +1,13 @@ +{ + "compilerOptions": { + "target": "ES2022", + "module": "CommonJS", + "moduleResolution": "Node", + "strict": true, + "noEmit": false, + "declaration": false, + "outDir": ".safe-logging-test", + "lib": ["ES2022", "DOM"] + }, + "include": ["src/safe-logging.ts"] +} diff --git a/frontend/scripts/check-safe-logging.mjs b/frontend/scripts/check-safe-logging.mjs new file mode 100644 index 00000000..681d0ab8 --- /dev/null +++ b/frontend/scripts/check-safe-logging.mjs @@ -0,0 +1,146 @@ +import { readFileSync, readdirSync } from "node:fs"; +import { createRequire } from "node:module"; +import { dirname, extname, join, relative, resolve } from "node:path"; +import { fileURLToPath, pathToFileURL } from "node:url"; + +const frontendRoot = resolve(dirname(fileURLToPath(import.meta.url)), ".."); +const require = createRequire(import.meta.url); +const ts = require( + resolve( + frontendRoot, + "packages/api-client/node_modules/typescript/lib/typescript.js", + ), +); +const allowedConsoleFile = resolve( + frontendRoot, + "packages/api-client/src/safe-logging.ts", +); +const sourceRoots = [ + "dashboard", + "developer-portal", + "identitycore", + "platform-admin", + "verification-portal", + "packages", +].map((path) => resolve(frontendRoot, path)); +const extensions = new Set([".js", ".jsx", ".mjs", ".cjs", ".ts", ".tsx"]); +const skipDirectories = new Set([ + ".next", + ".safe-logging-test", + "coverage", + "dist", + "e2e", + "node_modules", + "test", + "tests", +]); + +function scriptKind(path) { + if (path.endsWith(".tsx")) return ts.ScriptKind.TSX; + if (path.endsWith(".jsx")) return ts.ScriptKind.JSX; + if (path.endsWith(".ts")) return ts.ScriptKind.TS; + return ts.ScriptKind.JS; +} + +function propertyName(node) { + if (ts.isIdentifier(node) || ts.isStringLiteralLike(node)) return node.text; + return null; +} + +function isConsoleObject(node) { + if (ts.isIdentifier(node)) return node.text === "console"; + if (ts.isPropertyAccessExpression(node)) { + return ( + ts.isIdentifier(node.expression) && + ["window", "globalThis"].includes(node.expression.text) && + node.name.text === "console" + ); + } + if (ts.isElementAccessExpression(node)) { + return ( + ts.isIdentifier(node.expression) && + ["window", "globalThis"].includes(node.expression.text) && + propertyName(node.argumentExpression) === "console" + ); + } + return false; +} + +function isConsoleMethodReference(node) { + if (ts.isPropertyAccessExpression(node)) { + return isConsoleObject(node.expression); + } + if (ts.isElementAccessExpression(node)) { + return isConsoleObject(node.expression); + } + return false; +} + +function destructuresConsoleMethod(node) { + if (!ts.isVariableDeclaration(node) || !ts.isObjectBindingPattern(node.name)) return false; + if (!node.initializer || !isConsoleObject(node.initializer)) return false; + return node.name.elements.some((element) => { + return propertyName(element.propertyName ?? element.name) !== null; + }); +} + +export function containsUnsafeConsoleUse(path, source) { + const sourceFile = ts.createSourceFile( + path, + source, + ts.ScriptTarget.Latest, + true, + scriptKind(path), + ); + let found = false; + + function visit(node) { + if (found) return; + if ( + ((ts.isCallExpression(node) && isConsoleMethodReference(node.expression)) || + isConsoleMethodReference(node) || + destructuresConsoleMethod(node)) + ) { + found = true; + return; + } + ts.forEachChild(node, visit); + } + + visit(sourceFile); + return found; +} + +function walk(path, findings) { + for (const entry of readdirSync(path, { withFileTypes: true })) { + if (entry.isDirectory() && skipDirectories.has(entry.name)) continue; + const absolute = join(path, entry.name); + if (entry.isDirectory()) { + walk(absolute, findings); + continue; + } + if (!extensions.has(extname(entry.name))) continue; + if (/\.(?:spec|test)\.[cm]?[jt]sx?$/.test(entry.name)) continue; + if (absolute === allowedConsoleFile) continue; + const source = readFileSync(absolute, "utf8"); + if (containsUnsafeConsoleUse(absolute, source)) { + findings.push(relative(frontendRoot, absolute)); + } + } +} + +if (process.argv[1] && import.meta.url === pathToFileURL(resolve(process.argv[1])).href) { + const findings = []; + for (const root of sourceRoots) walk(root, findings); + + if (findings.length) { + console.error( + [ + "Unsafe direct console logging is not allowed in frontend production source.", + "Use safeLog from @identitycore/api-client so sensitive context is redacted.", + ...findings.map((path) => ` - ${path}`), + ].join("\n"), + ); + process.exitCode = 1; + } +} diff --git a/frontend/scripts/check-safe-logging.test.mjs b/frontend/scripts/check-safe-logging.test.mjs new file mode 100644 index 00000000..bb5ba884 --- /dev/null +++ b/frontend/scripts/check-safe-logging.test.mjs @@ -0,0 +1,27 @@ +import assert from "node:assert/strict"; +import test from "node:test"; + +import { containsUnsafeConsoleUse } from "./check-safe-logging.mjs"; + +for (const source of [ + 'console["error"]("secret")', + 'window.console.error("secret")', + 'globalThis.console["warn"]("secret")', + 'window["console"]["info"]("secret")', + 'const { error } = console; error("secret")', + 'const { warn: report } = globalThis.console; report("secret")', + 'const report = console.error; report("secret")', + 'console.table({ accessToken: "secret" })', + 'console.dir({ credentials: "secret" })', + 'console.assert(false, "secret")', + 'console[method]("secret")', +]) { + test(`rejects equivalent console use: ${source}`, () => { + assert.equal(containsUnsafeConsoleUse("fixture.ts", source), true); + }); +} + +test("allows unrelated methods and safe logging", () => { + assert.equal(containsUnsafeConsoleUse("fixture.ts", 'safeLog("error", "event")'), false); + assert.equal(containsUnsafeConsoleUse("fixture.ts", 'reporter.error("safe code")'), false); +}); diff --git a/frontend/verification-portal/src/app/error.tsx b/frontend/verification-portal/src/app/error.tsx index e1b57b3a..008f7216 100644 --- a/frontend/verification-portal/src/app/error.tsx +++ b/frontend/verification-portal/src/app/error.tsx @@ -2,6 +2,7 @@ import { useEffect } from "react"; import { AlertTriangle } from "lucide-react"; +import { safeLog } from "@identitycore/api-client"; import { Button } from "@identitycore/ui"; import { VerificationShell } from "@/components/layout/verification-shell"; @@ -13,10 +14,11 @@ export default function GlobalError({ reset: () => void; }) { useEffect(() => { - // Errors here are boundary-level render failures, not the flow's own - // handled error state. Avoid logging identity evidence or session - // tokens; only the error/digest are safe to surface. - console.error(error); + safeLog("error", "verification_portal_render_error", { + error_name: error.name, + error_message: error.message, + digest: error.digest ?? "", + }); }, [error]); return (