diff --git a/docs/ConfigurationGuide.md b/docs/ConfigurationGuide.md index c70626d8..8b3f0a72 100644 --- a/docs/ConfigurationGuide.md +++ b/docs/ConfigurationGuide.md @@ -90,6 +90,73 @@ Several functions in ACAPy VC-AuthN can be tweaked by using the following enviro | LOG_WITH_JSON | bool | If True, logging output should printed as JSON if False it will be pretty printed. | Default behavior will print as JSON. | | LOG_TIMESTAMP_FORMAT | string | determines the timestamp formatting used in logs | Default is "iso" | | LOG_LEVEL | "DEBUG", "INFO", "WARNING", or "ERROR" | sets the minimum log level that will be printed to standard out | Defaults to DEBUG | +| SIAM_AUDIT_ENABLED | bool | Enables or disables SIAM audit event logging. When `false`, all audit events (session lifecycle, proof verification, token issuance, etc.) are silently suppressed. | Defaults to `true` (audit logging is **on**). | +| SIAM_IP_SALT | string | Salt used for one-way hashing of client IP addresses in SIAM audit logs. Should be rotated periodically. Only relevant when `SIAM_AUDIT_ENABLED` is `true`. | Defaults to a built-in placeholder. **Set a unique value in production.** | + +### SIAM Audit Logging + +ACAPy VC-AuthN includes a privacy-preserving audit logger for SIAM (Security Information and Analytics Management) platforms. It emits structured events at key points in the verification flow—session initiation, QR scan, proof verification, token issuance, session expiry, etc.—without ever logging PII or credential attribute values. + +#### Audit Events + +The following events are emitted by the SIAM audit logger: + +| Event | Category | Description | Key Fields | +| --------------------------- | ------------------- | ------------------------------------------------------------------ | ----------------------------------------------------------------------------------------------- | +| `auth_session_initiated` | Session lifecycle | An OIDC authorization request created a new auth session. | `session_id`, `client_id`, `ver_config_id`, `client_ip_hash`, `user_agent_family`, `requested_schemas`, `requested_attributes_count`, `requested_predicates_count` | +| `proof_request_created` | Proof request flow | A proof request was built and is ready for scanning. | `session_id`, `ver_config_id`, `proof_name`, `requested_schemas`, `expected_issuers` | +| `qr_scanned` | Proof request flow | The QR code was scanned or the deep link was invoked by a wallet. | `session_id`, `scan_method` (`qr_code` / `deep_link`), `client_ip_hash`, `user_agent_family` | +| `proof_verified` | Proof request flow | Proof presentation was successfully verified. | `session_id`, `ver_config_id`, `outcome=verified`, `credential_schemas`, `issuer_dids`, `credential_count`, `revocation_checked`, `duration_ms` | +| `proof_verification_failed` | Proof request flow | Proof verification failed. | `session_id`, `ver_config_id`, `outcome=failed`, `failure_category`, `duration_ms` | +| `session_abandoned` | Session termination | The user abandoned or declined the proof request. | `session_id`, `ver_config_id`, `outcome=abandoned`, `phase`, `duration_ms` | +| `session_expired` | Session termination | The session expired before the proof flow completed. | `session_id`, `ver_config_id`, `outcome=expired`, `phase`, `timeout_seconds` | +| `token_issued` | Token flow | An OIDC ID token was successfully issued to the relying party. | `session_id`, `client_id`, `ver_config_id`, `claims_count`, `duration_ms` | +| `webhook_received` | Security / monitoring | An ACA-Py agent webhook was received. | `webhook_topic`, `webhook_state`, `webhook_role` | +| `invalid_client_request` | Security / monitoring | A client request failed validation (unknown client, bad params). | `client_id`, `error_type`, `client_ip_hash` | + +All events share a common base structure containing `audit_event_type`, `timestamp`, and `service`. Fields that are `None` are omitted from the log output for cleaner JSON. + +> **Privacy note:** No attribute values, subject identifiers, or credential contents are ever included. Only safe metadata (schema names, issuer DIDs, counts, durations, and anonymized IPs) is logged. + +**Audit logging is enabled by default.** There are two complementary ways to control it: + +#### 1. Feature flag (`SIAM_AUDIT_ENABLED`) + +Set the environment variable to `false` to disable all SIAM audit events at the application level. No audit log lines will be emitted regardless of log-level settings. + +```yaml +environment: + - SIAM_AUDIT_ENABLED=false # disable SIAM audit events entirely +``` + +To re-enable, remove the variable or set it to `true` (the default). + +#### 2. Log-level override (`logconf.json` / `LOG_LEVEL`) + +The `siam.audit` logger is configured in `logconf.json` at the `INFO` level. You can raise it to `WARNING` or `CRITICAL` to suppress the `INFO`-level audit messages while keeping the feature flag on—useful if you want to silence routine events but still capture any future warning/error-level audit entries. + +```json +{ + "loggers": { + "siam.audit": { + "level": "WARNING", + "handlers": ["out"], + "propagate": false + } + } +} +``` + +Alternatively, setting the global `LOG_LEVEL` environment variable to `WARNING` or higher will also suppress the audit messages, but this will affect **all** loggers, not just SIAM. + +#### IP anonymization salt + +When audit logging is enabled, client IP addresses are one-way hashed before being logged. The hash uses a salt read from the `SIAM_IP_SALT` environment variable. The default salt is a placeholder—**you should set a unique, secret value in production** and rotate it periodically. + +```yaml +environment: + - SIAM_IP_SALT=my-unique-production-salt +``` ### Legacy Variable Support diff --git a/oidc-controller/api/core/siam_audit.py b/oidc-controller/api/core/siam_audit.py new file mode 100644 index 00000000..2ecb57f3 --- /dev/null +++ b/oidc-controller/api/core/siam_audit.py @@ -0,0 +1,427 @@ +""" +SIAM Audit Logger - Privacy-Preserving Audit Events + +This module provides structured logging for SIAM (Security Information and +Analytics Management) platforms while maintaining the privacy-preserving +principles of verifiable credentials. + +PRIVACY GUIDELINES: +- NEVER log attribute values (given_names, email, etc.) - they contain PII +- NEVER log subject identifiers (sub claim) - enables user tracking +- NEVER log presentation data/revealed attributes - credential contents +- NEVER log consistent identifier hashes - allows user correlation +- DO log credential metadata (schema names, issuer DIDs) +- DO log session lifecycle events with ephemeral session IDs +- DO log aggregate counts and durations +- DO log anonymized client information (hashed IPs) +""" + +import hashlib +import os +from datetime import UTC, datetime +from typing import TYPE_CHECKING, Literal, Optional + +import structlog + +if TYPE_CHECKING: + from ..authSessions.models import AuthSession + from ..verificationConfigs.models import VerificationConfig + +logger: structlog.typing.FilteringBoundLogger = structlog.getLogger("siam.audit") + + +def _strtobool(val: str | bool) -> bool: + """Convert a string representation of truth to a boolean.""" + if isinstance(val, bool): + return val + val = val.lower() + if val in ("y", "yes", "t", "true", "on", "1"): + return True + elif val in ("n", "no", "f", "false", "off", "0"): + return False + else: + raise ValueError(f"invalid truth value {val}") + + +# Feature flag: set SIAM_AUDIT_ENABLED=false to disable SIAM audit logging. +# Enabled by default. +SIAM_AUDIT_ENABLED: bool = _strtobool(os.environ.get("SIAM_AUDIT_ENABLED", "true")) + +# Salt for IP anonymization - should be rotated periodically +# In production, load from environment or secrets manager +_IP_ANONYMIZATION_SALT = os.environ.get( + "SIAM_IP_SALT", "vc-authn-oidc-default-salt-rotate-me" +) + +# Audit event types +AuditEventType = Literal[ + # Session lifecycle + "auth_session_initiated", + "auth_session_completed", + # Proof request flow + "proof_request_created", + "qr_scanned", + "wallet_connected", + "proof_submitted", + "proof_verified", + "proof_verification_failed", + # Session termination + "session_timeout", + "session_expired", + "session_abandoned", + # Token flow + "token_issued", + # Security events + "invalid_client_request", + "webhook_received", +] + +# Outcome categories +OutcomeType = Literal[ + "verified", + "failed", + "expired", + "abandoned", + "timeout", +] + +# Failure categories (safe to log - no PII) +FailureCategoryType = Literal[ + "revoked", + "expired_credential", + "invalid_signature", + "missing_attributes", + "schema_mismatch", + "issuer_not_trusted", + "predicate_not_satisfied", + "unknown", +] + + +def _anonymize_ip(ip: Optional[str]) -> Optional[str]: + """ + One-way hash of IP address for fraud detection without tracking. + + Returns a truncated hash that allows detection of repeated IPs + without enabling full IP reconstruction. + """ + if not ip: + return None + # Use first 16 chars of SHA256 - sufficient for anomaly detection + return hashlib.sha256(f"{ip}{_IP_ANONYMIZATION_SALT}".encode()).hexdigest()[:16] + + +def _extract_user_agent_family(user_agent: Optional[str]) -> Optional[str]: + """ + Extract generic browser/client family from User-Agent string. + + Returns generic identifiers like 'Chrome', 'Safari', 'Mobile' + rather than full UA strings which could fingerprint users. + """ + if not user_agent: + return None + + ua_lower = user_agent.lower() + + # Check for common browsers (order matters for accuracy) + if "edg" in ua_lower: + return "Edge" + elif ( + "opera" in ua_lower or "opr" in ua_lower + ): # before Chrome — Opera UAs contain "Chrome" + return "Opera" + elif "chrome" in ua_lower: + return "Chrome" + elif "firefox" in ua_lower: + return "Firefox" + elif "safari" in ua_lower: + return "Safari" + elif "mobile" in ua_lower: + return "Mobile" + elif "bot" in ua_lower or "crawler" in ua_lower: + return "Bot" + else: + return "Other" + + +def _extract_schema_names(ver_config: "VerificationConfig") -> list[str]: + """ + Extract schema names from verification config. + + Schema names are safe metadata - they describe what type of credential + is being requested, not the actual credential contents. + Extracts from both requested_attributes and requested_predicates. + """ + schemas = set() + for item in ( + *ver_config.proof_request.requested_attributes, + *ver_config.proof_request.requested_predicates, + ): + for restriction in item.restrictions: + if restriction.schema_name: + schemas.add(restriction.schema_name) + return sorted(list(schemas)) + + +def _extract_issuer_dids(ver_config: "VerificationConfig") -> list[str]: + """ + Extract issuer DIDs from verification config restrictions. + + Issuer DIDs are public identifiers - safe to log for ecosystem analytics. + Extracts from both requested_attributes and requested_predicates. + """ + issuers = set() + for item in ( + *ver_config.proof_request.requested_attributes, + *ver_config.proof_request.requested_predicates, + ): + for restriction in item.restrictions: + if restriction.issuer_did: + issuers.add(restriction.issuer_did) + if restriction.schema_issuer_did: + issuers.add(restriction.schema_issuer_did) + return sorted(list(issuers)) + + +def audit_event( + event: AuditEventType, + *, + session_id: Optional[str] = None, + client_id: Optional[str] = None, + ver_config_id: Optional[str] = None, + outcome: Optional[OutcomeType] = None, + failure_category: Optional[FailureCategoryType] = None, + duration_ms: Optional[int] = None, + client_ip: Optional[str] = None, + user_agent: Optional[str] = None, + **extra_safe_fields, +) -> None: + """ + Log a privacy-preserving audit event for SIAM collection. + + This function ensures consistent event structure and privacy guarantees. + + Args: + event: The type of audit event (from AuditEventType) + session_id: Ephemeral session identifier (safe - per-request only) + client_id: OIDC client/relying party identifier + ver_config_id: Verification configuration identifier + outcome: Session outcome category + failure_category: Category of failure (if applicable) + duration_ms: Processing duration in milliseconds + client_ip: Client IP (will be anonymized via hashing) + user_agent: User-Agent header (will be reduced to family only) + **extra_safe_fields: Additional fields (caller must ensure privacy) + + WARNING: Never pass PII, attribute values, or subject identifiers + to this function. All extra_safe_fields must be privacy-safe. + """ + if not SIAM_AUDIT_ENABLED: + return + + log_data = { + "audit_event_type": event, + "timestamp": datetime.now(UTC).isoformat(), + "service": "vc-authn-oidc", + # Session context + "session_id": session_id, + "client_id": client_id, + "ver_config_id": ver_config_id, + # Outcome + "outcome": outcome, + "failure_category": failure_category, + "duration_ms": duration_ms, + # Anonymized client info + "client_ip_hash": _anonymize_ip(client_ip), + "user_agent_family": _extract_user_agent_family(user_agent), + } + + # Merge extra fields (caller responsible for privacy) + log_data.update(extra_safe_fields) + + # Remove None values for cleaner logs + log_data = {k: v for k, v in log_data.items() if v is not None} + + logger.info(f"audit_{event}", **log_data) + + +def audit_auth_session_initiated( + session_id: str, + client_id: str, + ver_config: "VerificationConfig", + client_ip: Optional[str] = None, + user_agent: Optional[str] = None, +) -> None: + """Log when an authentication session is initiated.""" + audit_event( + "auth_session_initiated", + session_id=session_id, + client_id=client_id, + ver_config_id=ver_config.ver_config_id, + client_ip=client_ip, + user_agent=user_agent, + requested_schemas=_extract_schema_names(ver_config), + requested_attributes_count=len(ver_config.proof_request.requested_attributes), + requested_predicates_count=len(ver_config.proof_request.requested_predicates), + ) + + +def audit_proof_request_created( + session_id: str, + ver_config: "VerificationConfig", + proof_name: Optional[str] = None, +) -> None: + """Log when a proof request is created and ready for scanning.""" + audit_event( + "proof_request_created", + session_id=session_id, + ver_config_id=ver_config.ver_config_id, + proof_name=proof_name or ver_config.proof_request.name, + requested_schemas=_extract_schema_names(ver_config), + expected_issuers=_extract_issuer_dids(ver_config), + ) + + +def audit_qr_scanned( + session_id: str, + scan_method: Literal["qr_code", "deep_link"], + client_ip: Optional[str] = None, + user_agent: Optional[str] = None, +) -> None: + """Log when QR code is scanned or deep link is invoked.""" + audit_event( + "qr_scanned", + session_id=session_id, + scan_method=scan_method, + client_ip=client_ip, + user_agent=user_agent, + ) + + +def audit_proof_verified( + session_id: str, + ver_config_id: str, + credential_schemas: list[str], + issuer_dids: list[str], + duration_ms: Optional[int] = None, + revocation_checked: bool = False, +) -> None: + """ + Log successful proof verification. + + Only logs credential metadata (schemas, issuers) - never attribute values. + """ + audit_event( + "proof_verified", + session_id=session_id, + ver_config_id=ver_config_id, + outcome="verified", + duration_ms=duration_ms, + credential_schemas=credential_schemas, + issuer_dids=issuer_dids, + credential_count=len(credential_schemas), + revocation_checked=revocation_checked, + ) + + +def audit_proof_verification_failed( + session_id: str, + ver_config_id: str, + failure_category: FailureCategoryType = "unknown", + duration_ms: Optional[int] = None, +) -> None: + """Log failed proof verification with categorized failure reason.""" + audit_event( + "proof_verification_failed", + session_id=session_id, + ver_config_id=ver_config_id, + outcome="failed", + failure_category=failure_category, + duration_ms=duration_ms, + ) + + +def audit_session_abandoned( + session_id: str, + ver_config_id: str, + phase: Literal[ + "qr_scan", "wallet_response", "proof_submission" + ] = "wallet_response", + duration_ms: Optional[int] = None, +) -> None: + """Log when user abandons/declines the proof request.""" + audit_event( + "session_abandoned", + session_id=session_id, + ver_config_id=ver_config_id, + outcome="abandoned", + phase=phase, + duration_ms=duration_ms, + ) + + +def audit_session_expired( + session_id: str, + ver_config_id: str, + phase: Literal["qr_scan", "wallet_response", "proof_submission"] = "qr_scan", + timeout_seconds: Optional[int] = None, +) -> None: + """Log when session expires due to timeout.""" + audit_event( + "session_expired", + session_id=session_id, + ver_config_id=ver_config_id, + outcome="expired", + phase=phase, + timeout_seconds=timeout_seconds, + ) + + +def audit_token_issued( + session_id: str, + client_id: str, + ver_config_id: str, + claims_count: int, + duration_ms: Optional[int] = None, +) -> None: + """ + Log successful token issuance. + + Only logs the count of claims, never the claim names or values. + """ + audit_event( + "token_issued", + session_id=session_id, + client_id=client_id, + ver_config_id=ver_config_id, + claims_count=claims_count, + duration_ms=duration_ms, + ) + + +def audit_webhook_received( + topic: str, + state: Optional[str] = None, + role: Optional[str] = None, +) -> None: + """Log agent webhook receipt for monitoring.""" + audit_event( + "webhook_received", + webhook_topic=topic, + webhook_state=state, + webhook_role=role, + ) + + +def audit_invalid_client_request( + client_id: Optional[str], + error_type: str, + client_ip: Optional[str] = None, +) -> None: + """Log invalid client requests for security monitoring.""" + audit_event( + "invalid_client_request", + client_id=client_id, + error_type=error_type, + client_ip=client_ip, + ) diff --git a/oidc-controller/api/core/tests/test_siam_audit.py b/oidc-controller/api/core/tests/test_siam_audit.py new file mode 100644 index 00000000..1f20646f --- /dev/null +++ b/oidc-controller/api/core/tests/test_siam_audit.py @@ -0,0 +1,827 @@ +"""Tests for the SIAM Audit Logger module.""" + +import hashlib +import os +from unittest.mock import MagicMock, patch + +import pytest +from api.verificationConfigs.models import ( + AttributeFilter, + ReqAttr, + ReqPred, + VerificationConfig, + VerificationProofRequest, +) + +# --------------------------------------------------------------------------- +# Helpers – build mock VerificationConfig objects +# --------------------------------------------------------------------------- + + +def _make_ver_config( + ver_config_id: str = "test-vc-config-1", + schema_names: list[str] | None = None, + issuer_dids: list[str] | None = None, + schema_issuer_dids: list[str] | None = None, + proof_name: str | None = "age-verification", + num_predicates: int = 0, + predicate_schema_names: list[str] | None = None, + predicate_issuer_dids: list[str] | None = None, + predicate_schema_issuer_dids: list[str] | None = None, +) -> VerificationConfig: + """Build a lightweight VerificationConfig for testing.""" + restrictions = [] + if schema_names: + for sn in schema_names: + restrictions.append( + AttributeFilter( + schema_name=sn, + issuer_did=(issuer_dids or [None])[0], + schema_issuer_did=(schema_issuer_dids or [None])[0], + ) + ) + if not restrictions: + restrictions = [AttributeFilter()] + + requested_attributes = [ + ReqAttr(names=["given_names"], restrictions=restrictions), + ] + + # Build predicate restrictions + pred_restrictions: list[AttributeFilter] = [] + if predicate_schema_names: + for sn in predicate_schema_names: + pred_restrictions.append( + AttributeFilter( + schema_name=sn, + issuer_did=(predicate_issuer_dids or [None])[0], + schema_issuer_did=(predicate_schema_issuer_dids or [None])[0], + ) + ) + + requested_predicates = [] + for i in range(num_predicates): + requested_predicates.append( + ReqPred( + name=f"pred_{i}", + restrictions=pred_restrictions or [AttributeFilter()], + p_value=19, + p_type=">=", + ) + ) + + return VerificationConfig( + ver_config_id=ver_config_id, + subject_identifier="given_names", + proof_request=VerificationProofRequest( + name=proof_name, + version="0.0.1", + requested_attributes=requested_attributes, + requested_predicates=requested_predicates, + ), + ) + + +# =================================================================== +# _strtobool +# =================================================================== + + +class TestStrtobool: + """Tests for the _strtobool helper.""" + + def test_truthy_strings(self): + from api.core.siam_audit import _strtobool + + for val in ("y", "yes", "t", "true", "on", "1", "YES", "True", "ON"): + assert _strtobool(val) is True + + def test_falsy_strings(self): + from api.core.siam_audit import _strtobool + + for val in ("n", "no", "f", "false", "off", "0", "NO", "False", "OFF"): + assert _strtobool(val) is False + + def test_bool_passthrough(self): + from api.core.siam_audit import _strtobool + + assert _strtobool(True) is True + assert _strtobool(False) is False + + def test_invalid_value_raises(self): + from api.core.siam_audit import _strtobool + + with pytest.raises(ValueError, match="invalid truth value"): + _strtobool("maybe") + + +# =================================================================== +# _anonymize_ip +# =================================================================== + + +class TestAnonymizeIp: + """Tests for IP anonymization.""" + + def test_none_returns_none(self): + from api.core.siam_audit import _anonymize_ip + + assert _anonymize_ip(None) is None + + def test_empty_string_returns_none(self): + from api.core.siam_audit import _anonymize_ip + + assert _anonymize_ip("") is None + + def test_returns_16_char_hex(self): + from api.core.siam_audit import _anonymize_ip + + result = _anonymize_ip("192.168.1.1") + assert isinstance(result, str) + assert len(result) == 16 + # Verify it's valid hex + int(result, 16) + + def test_deterministic(self): + from api.core.siam_audit import _anonymize_ip + + assert _anonymize_ip("10.0.0.1") == _anonymize_ip("10.0.0.1") + + def test_different_ips_differ(self): + from api.core.siam_audit import _anonymize_ip + + assert _anonymize_ip("10.0.0.1") != _anonymize_ip("10.0.0.2") + + +# =================================================================== +# _extract_user_agent_family +# =================================================================== + + +class TestExtractUserAgentFamily: + """Tests for User-Agent family extraction.""" + + def test_none_returns_none(self): + from api.core.siam_audit import _extract_user_agent_family + + assert _extract_user_agent_family(None) is None + + def test_empty_string_returns_none(self): + from api.core.siam_audit import _extract_user_agent_family + + assert _extract_user_agent_family("") is None + + @pytest.mark.parametrize( + "ua_string,expected", + [ + ( + "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 " + "(KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36", + "Chrome", + ), + ( + "Mozilla/5.0 (Macintosh; Intel Mac OS X 14_0) AppleWebKit/605.1.15 " + "(KHTML, like Gecko) Version/17.0 Safari/605.1.15", + "Safari", + ), + ( + "Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/119.0", + "Firefox", + ), + ( + "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 " + "(KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36 Edg/120.0.0.0", + "Edge", + ), + # Modern Opera UAs contain "OPR" which is checked before Chrome + ( + "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 " + "(KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36 OPR/105.0.0.0", + "Opera", + ), + # Legacy Opera UA also matches Opera + ( + "Opera/9.80 (Windows NT 6.1; WOW64) Presto/2.12.388 Version/12.18", + "Opera", + ), + # MobileSafari contains "safari" so it matches Safari first + ("MobileSafari/604.1", "Safari"), + # Pure mobile UA without safari + ("SomeMobileApp/1.0 (Linux; Android 13; Mobile)", "Mobile"), + ("Googlebot/2.1 (+http://www.google.com/bot.html)", "Bot"), + ("WebCrawler/1.0", "Bot"), + ("some-unknown-client/1.0", "Other"), + ], + ) + def test_browser_families(self, ua_string, expected): + from api.core.siam_audit import _extract_user_agent_family + + assert _extract_user_agent_family(ua_string) == expected + + +# =================================================================== +# _extract_schema_names / _extract_issuer_dids +# =================================================================== + + +class TestExtractSchemaNames: + """Tests for schema name extraction from VerificationConfig.""" + + def test_no_schema_names(self): + from api.core.siam_audit import _extract_schema_names + + vc = _make_ver_config(schema_names=None) + assert _extract_schema_names(vc) == [] + + def test_single_schema(self): + from api.core.siam_audit import _extract_schema_names + + vc = _make_ver_config(schema_names=["Person"]) + assert _extract_schema_names(vc) == ["Person"] + + def test_multiple_schemas_sorted_and_deduped(self): + from api.core.siam_audit import _extract_schema_names + + # Two restrictions with same schema → should deduplicate + vc = _make_ver_config(schema_names=["Zebra", "Alpha", "Alpha"]) + assert _extract_schema_names(vc) == ["Alpha", "Zebra"] + + def test_schemas_from_predicates(self): + from api.core.siam_audit import _extract_schema_names + + vc = _make_ver_config( + num_predicates=1, + predicate_schema_names=["AgeCredential"], + ) + result = _extract_schema_names(vc) + assert "AgeCredential" in result + + def test_schemas_merged_from_attributes_and_predicates(self): + from api.core.siam_audit import _extract_schema_names + + vc = _make_ver_config( + schema_names=["Person"], + num_predicates=1, + predicate_schema_names=["AgeCredential"], + ) + result = _extract_schema_names(vc) + assert result == ["AgeCredential", "Person"] + + def test_schemas_deduped_across_attributes_and_predicates(self): + from api.core.siam_audit import _extract_schema_names + + vc = _make_ver_config( + schema_names=["Person"], + num_predicates=1, + predicate_schema_names=["Person"], + ) + result = _extract_schema_names(vc) + assert result == ["Person"] + + +class TestExtractIssuerDids: + """Tests for issuer DID extraction from VerificationConfig.""" + + def test_no_issuers(self): + from api.core.siam_audit import _extract_issuer_dids + + vc = _make_ver_config() + assert _extract_issuer_dids(vc) == [] + + def test_issuer_did_extracted(self): + from api.core.siam_audit import _extract_issuer_dids + + vc = _make_ver_config( + schema_names=["Person"], + issuer_dids=["did:sov:abc123"], + ) + result = _extract_issuer_dids(vc) + assert "did:sov:abc123" in result + + def test_schema_issuer_did_extracted(self): + from api.core.siam_audit import _extract_issuer_dids + + vc = _make_ver_config( + schema_names=["Person"], + schema_issuer_dids=["did:sov:xyz789"], + ) + result = _extract_issuer_dids(vc) + assert "did:sov:xyz789" in result + + def test_issuer_dids_from_predicates(self): + from api.core.siam_audit import _extract_issuer_dids + + vc = _make_ver_config( + num_predicates=1, + predicate_schema_names=["AgeCredential"], + predicate_issuer_dids=["did:sov:pred1"], + ) + result = _extract_issuer_dids(vc) + assert "did:sov:pred1" in result + + def test_schema_issuer_dids_from_predicates(self): + from api.core.siam_audit import _extract_issuer_dids + + vc = _make_ver_config( + num_predicates=1, + predicate_schema_names=["AgeCredential"], + predicate_schema_issuer_dids=["did:sov:spred1"], + ) + result = _extract_issuer_dids(vc) + assert "did:sov:spred1" in result + + def test_issuer_dids_merged_from_attributes_and_predicates(self): + from api.core.siam_audit import _extract_issuer_dids + + vc = _make_ver_config( + schema_names=["Person"], + issuer_dids=["did:sov:attr1"], + num_predicates=1, + predicate_schema_names=["AgeCredential"], + predicate_issuer_dids=["did:sov:pred1"], + ) + result = _extract_issuer_dids(vc) + assert result == ["did:sov:attr1", "did:sov:pred1"] + + def test_issuer_dids_deduped_across_attributes_and_predicates(self): + from api.core.siam_audit import _extract_issuer_dids + + vc = _make_ver_config( + schema_names=["Person"], + issuer_dids=["did:sov:shared"], + num_predicates=1, + predicate_schema_names=["AgeCredential"], + predicate_issuer_dids=["did:sov:shared"], + ) + result = _extract_issuer_dids(vc) + assert result == ["did:sov:shared"] + + def test_both_dids_deduplicated_and_sorted(self): + from api.core.siam_audit import _extract_issuer_dids + + vc = _make_ver_config( + schema_names=["Person"], + issuer_dids=["did:sov:z"], + schema_issuer_dids=["did:sov:a"], + ) + result = _extract_issuer_dids(vc) + assert result == ["did:sov:a", "did:sov:z"] + + +# =================================================================== +# audit_event – core dispatcher +# =================================================================== + + +class TestAuditEvent: + """Tests for the central audit_event function.""" + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", True) + def test_basic_event_logged(self, mock_logger): + from api.core.siam_audit import audit_event + + audit_event("webhook_received", session_id="sess-1") + + mock_logger.info.assert_called_once() + call_args = mock_logger.info.call_args + assert call_args[0][0] == "audit_webhook_received" + assert call_args[1]["session_id"] == "sess-1" + assert call_args[1]["audit_event_type"] == "webhook_received" + assert call_args[1]["service"] == "vc-authn-oidc" + assert "timestamp" in call_args[1] + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", False) + def test_disabled_flag_suppresses_logging(self, mock_logger): + from api.core.siam_audit import audit_event + + audit_event("webhook_received", session_id="sess-1") + mock_logger.info.assert_not_called() + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", True) + def test_none_fields_omitted(self, mock_logger): + from api.core.siam_audit import audit_event + + audit_event("webhook_received") + + call_kwargs = mock_logger.info.call_args[1] + assert "session_id" not in call_kwargs + assert "client_id" not in call_kwargs + assert "outcome" not in call_kwargs + assert "client_ip_hash" not in call_kwargs + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", True) + def test_ip_anonymized_in_output(self, mock_logger): + from api.core.siam_audit import audit_event + + audit_event("qr_scanned", client_ip="1.2.3.4") + + call_kwargs = mock_logger.info.call_args[1] + assert "client_ip_hash" in call_kwargs + # Raw IP must NOT be in the log data + assert "1.2.3.4" not in str(call_kwargs) + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", True) + def test_user_agent_reduced_to_family(self, mock_logger): + from api.core.siam_audit import audit_event + + ua = ( + "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 " + "(KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36" + ) + audit_event("qr_scanned", user_agent=ua) + + call_kwargs = mock_logger.info.call_args[1] + assert call_kwargs["user_agent_family"] == "Chrome" + # Full UA must NOT be in the log data + assert "Mozilla" not in str(call_kwargs) + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", True) + def test_extra_safe_fields_included(self, mock_logger): + from api.core.siam_audit import audit_event + + audit_event( + "webhook_received", + webhook_topic="present_proof_v2_0", + webhook_state="done", + ) + + call_kwargs = mock_logger.info.call_args[1] + assert call_kwargs["webhook_topic"] == "present_proof_v2_0" + assert call_kwargs["webhook_state"] == "done" + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", True) + def test_outcome_and_failure_category(self, mock_logger): + from api.core.siam_audit import audit_event + + audit_event( + "proof_verification_failed", + outcome="failed", + failure_category="revoked", + ) + + call_kwargs = mock_logger.info.call_args[1] + assert call_kwargs["outcome"] == "failed" + assert call_kwargs["failure_category"] == "revoked" + + +# =================================================================== +# High-level convenience functions +# =================================================================== + + +class TestAuditAuthSessionInitiated: + """Tests for audit_auth_session_initiated.""" + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", True) + def test_logs_session_metadata(self, mock_logger): + from api.core.siam_audit import audit_auth_session_initiated + + vc = _make_ver_config( + schema_names=["Person"], + issuer_dids=["did:sov:abc"], + num_predicates=2, + ) + audit_auth_session_initiated( + session_id="sess-42", + client_id="keycloak-1", + ver_config=vc, + client_ip="10.0.0.5", + user_agent="Chrome/120", + ) + + mock_logger.info.assert_called_once() + kw = mock_logger.info.call_args[1] + assert kw["audit_event_type"] == "auth_session_initiated" + assert kw["session_id"] == "sess-42" + assert kw["client_id"] == "keycloak-1" + assert kw["ver_config_id"] == "test-vc-config-1" + assert kw["requested_schemas"] == ["Person"] + assert kw["requested_attributes_count"] == 1 + assert kw["requested_predicates_count"] == 2 + assert "client_ip_hash" in kw + assert kw["user_agent_family"] == "Chrome" + + +class TestAuditProofRequestCreated: + """Tests for audit_proof_request_created.""" + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", True) + def test_logs_proof_request(self, mock_logger): + from api.core.siam_audit import audit_proof_request_created + + vc = _make_ver_config( + schema_names=["Licence"], + issuer_dids=["did:sov:gov"], + ) + audit_proof_request_created(session_id="sess-1", ver_config=vc) + + kw = mock_logger.info.call_args[1] + assert kw["audit_event_type"] == "proof_request_created" + assert kw["proof_name"] == "age-verification" + assert kw["requested_schemas"] == ["Licence"] + assert "did:sov:gov" in kw["expected_issuers"] + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", True) + def test_custom_proof_name_overrides(self, mock_logger): + from api.core.siam_audit import audit_proof_request_created + + vc = _make_ver_config() + audit_proof_request_created( + session_id="sess-1", + ver_config=vc, + proof_name="custom-proof", + ) + + kw = mock_logger.info.call_args[1] + assert kw["proof_name"] == "custom-proof" + + +class TestAuditQrScanned: + """Tests for audit_qr_scanned.""" + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", True) + def test_qr_code_scan(self, mock_logger): + from api.core.siam_audit import audit_qr_scanned + + audit_qr_scanned( + session_id="sess-1", + scan_method="qr_code", + client_ip="1.1.1.1", + user_agent="Safari/17", + ) + + kw = mock_logger.info.call_args[1] + assert kw["audit_event_type"] == "qr_scanned" + assert kw["scan_method"] == "qr_code" + assert kw["user_agent_family"] == "Safari" + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", True) + def test_deep_link_scan(self, mock_logger): + from api.core.siam_audit import audit_qr_scanned + + audit_qr_scanned(session_id="sess-2", scan_method="deep_link") + + kw = mock_logger.info.call_args[1] + assert kw["scan_method"] == "deep_link" + + +class TestAuditProofVerified: + """Tests for audit_proof_verified.""" + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", True) + def test_logs_verification_metadata(self, mock_logger): + from api.core.siam_audit import audit_proof_verified + + audit_proof_verified( + session_id="sess-1", + ver_config_id="vc-1", + credential_schemas=["Person", "Licence"], + issuer_dids=["did:sov:abc"], + duration_ms=450, + revocation_checked=True, + ) + + kw = mock_logger.info.call_args[1] + assert kw["audit_event_type"] == "proof_verified" + assert kw["outcome"] == "verified" + assert kw["credential_schemas"] == ["Person", "Licence"] + assert kw["credential_count"] == 2 + assert kw["revocation_checked"] is True + assert kw["duration_ms"] == 450 + + +class TestAuditProofVerificationFailed: + """Tests for audit_proof_verification_failed.""" + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", True) + def test_logs_failure(self, mock_logger): + from api.core.siam_audit import audit_proof_verification_failed + + audit_proof_verification_failed( + session_id="sess-1", + ver_config_id="vc-1", + failure_category="revoked", + duration_ms=120, + ) + + kw = mock_logger.info.call_args[1] + assert kw["audit_event_type"] == "proof_verification_failed" + assert kw["outcome"] == "failed" + assert kw["failure_category"] == "revoked" + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", True) + def test_default_failure_category(self, mock_logger): + from api.core.siam_audit import audit_proof_verification_failed + + audit_proof_verification_failed( + session_id="sess-1", + ver_config_id="vc-1", + ) + + kw = mock_logger.info.call_args[1] + assert kw["failure_category"] == "unknown" + + +class TestAuditSessionAbandoned: + """Tests for audit_session_abandoned.""" + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", True) + def test_logs_abandonment(self, mock_logger): + from api.core.siam_audit import audit_session_abandoned + + audit_session_abandoned( + session_id="sess-1", + ver_config_id="vc-1", + phase="qr_scan", + duration_ms=5000, + ) + + kw = mock_logger.info.call_args[1] + assert kw["audit_event_type"] == "session_abandoned" + assert kw["outcome"] == "abandoned" + assert kw["phase"] == "qr_scan" + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", True) + def test_default_phase(self, mock_logger): + from api.core.siam_audit import audit_session_abandoned + + audit_session_abandoned(session_id="sess-1", ver_config_id="vc-1") + + kw = mock_logger.info.call_args[1] + assert kw["phase"] == "wallet_response" + + +class TestAuditSessionExpired: + """Tests for audit_session_expired.""" + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", True) + def test_logs_expiry(self, mock_logger): + from api.core.siam_audit import audit_session_expired + + audit_session_expired( + session_id="sess-1", + ver_config_id="vc-1", + phase="wallet_response", + timeout_seconds=300, + ) + + kw = mock_logger.info.call_args[1] + assert kw["audit_event_type"] == "session_expired" + assert kw["outcome"] == "expired" + assert kw["timeout_seconds"] == 300 + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", True) + def test_default_phase(self, mock_logger): + from api.core.siam_audit import audit_session_expired + + audit_session_expired(session_id="sess-1", ver_config_id="vc-1") + + kw = mock_logger.info.call_args[1] + assert kw["phase"] == "qr_scan" + + +class TestAuditTokenIssued: + """Tests for audit_token_issued.""" + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", True) + def test_logs_token_issuance(self, mock_logger): + from api.core.siam_audit import audit_token_issued + + audit_token_issued( + session_id="sess-1", + client_id="keycloak-1", + ver_config_id="vc-1", + claims_count=5, + duration_ms=80, + ) + + kw = mock_logger.info.call_args[1] + assert kw["audit_event_type"] == "token_issued" + assert kw["claims_count"] == 5 + assert kw["client_id"] == "keycloak-1" + + +class TestAuditWebhookReceived: + """Tests for audit_webhook_received.""" + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", True) + def test_logs_webhook(self, mock_logger): + from api.core.siam_audit import audit_webhook_received + + audit_webhook_received( + topic="present_proof_v2_0", + state="done", + role="verifier", + ) + + kw = mock_logger.info.call_args[1] + assert kw["audit_event_type"] == "webhook_received" + assert kw["webhook_topic"] == "present_proof_v2_0" + assert kw["webhook_state"] == "done" + assert kw["webhook_role"] == "verifier" + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", True) + def test_optional_fields_omitted(self, mock_logger): + from api.core.siam_audit import audit_webhook_received + + audit_webhook_received(topic="connections") + + kw = mock_logger.info.call_args[1] + assert "webhook_state" not in kw + assert "webhook_role" not in kw + + +class TestAuditInvalidClientRequest: + """Tests for audit_invalid_client_request.""" + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", True) + def test_logs_invalid_request(self, mock_logger): + from api.core.siam_audit import audit_invalid_client_request + + audit_invalid_client_request( + client_id="bad-client", + error_type="unknown_client", + client_ip="8.8.8.8", + ) + + kw = mock_logger.info.call_args[1] + assert kw["audit_event_type"] == "invalid_client_request" + assert kw["client_id"] == "bad-client" + assert kw["error_type"] == "unknown_client" + assert "client_ip_hash" in kw + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", True) + def test_none_client_id(self, mock_logger): + from api.core.siam_audit import audit_invalid_client_request + + audit_invalid_client_request( + client_id=None, + error_type="missing_params", + ) + + kw = mock_logger.info.call_args[1] + assert "client_id" not in kw + + +# =================================================================== +# Feature flag integration +# =================================================================== + + +class TestFeatureFlag: + """Test that SIAM_AUDIT_ENABLED properly gates all convenience functions.""" + + @patch("api.core.siam_audit.logger") + @patch("api.core.siam_audit.SIAM_AUDIT_ENABLED", False) + def test_all_functions_suppressed_when_disabled(self, mock_logger): + from api.core.siam_audit import ( + audit_auth_session_initiated, + audit_invalid_client_request, + audit_proof_request_created, + audit_proof_verification_failed, + audit_proof_verified, + audit_qr_scanned, + audit_session_abandoned, + audit_session_expired, + audit_token_issued, + audit_webhook_received, + ) + + vc = _make_ver_config(schema_names=["Person"]) + + audit_auth_session_initiated("s", "c", vc) + audit_proof_request_created("s", vc) + audit_qr_scanned("s", "qr_code") + audit_proof_verified("s", "vc", ["Person"], ["did:sov:1"]) + audit_proof_verification_failed("s", "vc") + audit_session_abandoned("s", "vc") + audit_session_expired("s", "vc") + audit_token_issued("s", "c", "vc", 3) + audit_webhook_received("topic") + audit_invalid_client_request("c", "err") + + mock_logger.info.assert_not_called() diff --git a/oidc-controller/api/logconf.json b/oidc-controller/api/logconf.json index 771d9f21..013757c4 100644 --- a/oidc-controller/api/logconf.json +++ b/oidc-controller/api/logconf.json @@ -18,6 +18,12 @@ "stream": "ext://sys.stdout" } }, - "loggers": {} + "loggers": { + "siam.audit": { + "level": "INFO", + "handlers": ["out"], + "propagate": false + } + } } } diff --git a/oidc-controller/api/routers/acapy_handler.py b/oidc-controller/api/routers/acapy_handler.py index be9f2209..2bc33c90 100644 --- a/oidc-controller/api/routers/acapy_handler.py +++ b/oidc-controller/api/routers/acapy_handler.py @@ -1,25 +1,99 @@ import json -from pydantic.plugin import Any -import structlog -from datetime import datetime, timedelta, UTC +import time +from datetime import UTC, datetime, timedelta +import structlog from fastapi import APIRouter, Depends, Request +from pydantic.plugin import Any from pymongo.database import Database from ..authSessions.crud import AuthSessionCRUD from ..authSessions.models import AuthSession, AuthSessionPatch, AuthSessionState -from ..db.session import get_db from ..core.acapy.client import AcapyClient -from ..verificationConfigs.crud import VerificationConfigCRUD - from ..core.config import settings -from ..routers.socketio import sio, get_socket_id_for_pid, safe_emit +from ..core.siam_audit import ( + audit_proof_verification_failed, + audit_proof_verified, + audit_session_abandoned, + audit_session_expired, + audit_webhook_received, +) +from ..db.session import get_db +from ..routers.socketio import get_socket_id_for_pid, safe_emit, sio +from ..verificationConfigs.crud import VerificationConfigCRUD logger: structlog.typing.FilteringBoundLogger = structlog.getLogger(__name__) router = APIRouter() +def _extract_credential_schemas(presentation_data: dict) -> list[str]: + """ + Extract schema names from verified presentation data. + + Safe to log - schema names are public metadata, not PII. + """ + schemas = set() + try: + # Try to extract from various proof formats + by_format = presentation_data.get("by_format", {}) + for format_key in ["indy", "anoncreds"]: + if format_key in by_format: + pres = by_format[format_key].get("pres", {}) + identifiers = pres.get("identifiers", []) + for identifier in identifiers: + if schema_id := identifier.get("schema_id"): + # schema_id format: :2:: + # The issuer DID may itself contain colons (e.g. did:sov:ABC), + # so we locate the ":2:" marker to split reliably. + marker = ":2:" + marker_pos = schema_id.find(marker) + if marker_pos != -1: + remainder = schema_id[marker_pos + len(marker) :] + # remainder is ":" + rem_parts = remainder.split(":") + if len(rem_parts) >= 2: + schemas.add(rem_parts[0]) + else: + schemas.add(remainder) + else: + schemas.add(schema_id) + except Exception as e: + # Return empty list if extraction fails + logger.debug(f"Failed to extract schemas from presentation data: {e}") + return sorted(list(schemas)) + + +def _extract_issuer_dids(presentation_data: dict) -> list[str]: + """ + Extract issuer DIDs from verified presentation data. + + Safe to log - DIDs are public identifiers, not PII. + """ + issuers = set() + try: + by_format = presentation_data.get("by_format", {}) + for format_key in ["indy", "anoncreds"]: + if format_key in by_format: + pres = by_format[format_key].get("pres", {}) + identifiers = pres.get("identifiers", []) + for identifier in identifiers: + if cred_def_id := identifier.get("cred_def_id"): + # cred_def_id format: :3:CL:: + # The issuer DID may itself contain colons (e.g. did:sov:ABC), + # so we locate the ":3:CL:" marker to extract the DID prefix. + marker = ":3:CL:" + marker_pos = cred_def_id.find(marker) + if marker_pos != -1: + issuers.add(cred_def_id[:marker_pos]) + else: + issuers.add(cred_def_id) + except Exception as e: + # Return empty list if extraction fails + logger.debug(f"Failed to extract issuer DIDs from presentation data: {e}") + return sorted(list(issuers)) + + async def _send_problem_report_safely( client: AcapyClient, pres_ex_id: str, description: str ) -> None: @@ -116,8 +190,10 @@ async def _parse_webhook_body(request: Request) -> dict[Any, Any]: @router.post("/topic/{topic}/") async def post_topic(request: Request, topic: str, db: Database = Depends(get_db)): """Called by aca-py agent.""" + webhook_start_time = time.time() logger.info(f">>> post_topic : topic={topic}") - logger.info(f">>> web hook post_body : {await _parse_webhook_body(request)}") + # Note: Full webhook body is logged at DEBUG level only to protect privacy + logger.debug(f">>> web hook received for topic: {topic}") match topic: case "connections": @@ -235,11 +311,21 @@ async def post_topic(request: Request, topic: str, db: Database = Depends(get_db case "present_proof_v2_0": webhook_body = await _parse_webhook_body(request) - logger.info(f">>>> pres_exch_id: {webhook_body['pres_ex_id']}") - # logger.info(f">>>> web hook: {webhook_body}") + state = webhook_body.get("state") + role = webhook_body.get("role") + + # SIAM Audit: Log webhook receipt (safe metadata only) + audit_webhook_received( + topic="present_proof_v2_0", + state=state, + role=role, + ) + + logger.info( + f">>>> pres_exch_id: {webhook_body['pres_ex_id']}, state: {state}" + ) # Check for prover-role (issue #898) - role = webhook_body.get("role") if role == "prover": # Handle prover-role separately - VC-AuthN is responding to a proof request @@ -296,8 +382,10 @@ async def post_topic(request: Request, topic: str, db: Database = Depends(get_db logger.info("presentation-received") if webhook_body["state"] == "done": - logger.info("VERIFIED") + duration_ms = int((time.time() - webhook_start_time) * 1000) + if webhook_body["verified"] == "true": + logger.info("VERIFIED") auth_session.proof_status = AuthSessionState.VERIFIED # Get presentation data via API call instead of webhook payload @@ -318,6 +406,20 @@ async def post_topic(request: Request, topic: str, db: Database = Depends(get_db f"Retrieved presentation data via API for {webhook_body['pres_ex_id']}" ) + # SIAM Audit: Log successful verification (metadata only, no PII) + # Extract schema names from presentation for audit + credential_schemas = _extract_credential_schemas(presentation_data) + issuer_dids = _extract_issuer_dids(presentation_data) + + audit_proof_verified( + session_id=str(auth_session.id), + ver_config_id=auth_session.ver_config_id, + credential_schemas=credential_schemas, + issuer_dids=issuer_dids, + duration_ms=duration_ms, + revocation_checked=settings.SET_NON_REVOKED, + ) + # Cleanup presentation record and connection after successful verification await _cleanup_presentation_and_connection( auth_session, @@ -327,7 +429,17 @@ async def post_topic(request: Request, topic: str, db: Database = Depends(get_db await _emit_status_to_socket(db, auth_session, "verified") else: + logger.info("VERIFICATION FAILED") auth_session.proof_status = AuthSessionState.FAILED + + # SIAM Audit: Log failed verification + audit_proof_verification_failed( + session_id=str(auth_session.id), + ver_config_id=auth_session.ver_config_id, + failure_category="unknown", # ACA-Py doesn't provide detailed failure reason + duration_ms=duration_ms, + ) + await _emit_status_to_socket(db, auth_session, "failed") # Send problem report for failed verification in connection-based flow @@ -349,8 +461,21 @@ async def post_topic(request: Request, topic: str, db: Database = Depends(get_db # abandoned state if webhook_body["state"] == "abandoned": logger.info("ABANDONED") - logger.info(webhook_body["error_msg"]) + # Note: error_msg may contain sensitive info, log at debug level only + logger.debug( + f"Abandonment reason: {webhook_body.get('error_msg', 'No reason provided')}" + ) auth_session.proof_status = AuthSessionState.ABANDONED + + # SIAM Audit: Log session abandonment + duration_ms = int((time.time() - webhook_start_time) * 1000) + audit_session_abandoned( + session_id=str(auth_session.id), + ver_config_id=auth_session.ver_config_id, + phase="wallet_response", + duration_ms=duration_ms, + ) + await _emit_status_to_socket(db, auth_session, "abandoned") # Send problem report for abandoned presentation in connection-based flow @@ -399,6 +524,15 @@ async def post_topic(request: Request, topic: str, db: Database = Depends(get_db ): logger.info("EXPIRED") auth_session.proof_status = AuthSessionState.EXPIRED + + # SIAM Audit: Log session expiration + audit_session_expired( + session_id=str(auth_session.id), + ver_config_id=auth_session.ver_config_id, + phase="qr_scan", + timeout_seconds=settings.CONTROLLER_PRESENTATION_EXPIRE_TIME, + ) + await _emit_status_to_socket(db, auth_session, "expired") # Send problem report for expired presentation in connection-based flow diff --git a/oidc-controller/api/routers/oidc.py b/oidc-controller/api/routers/oidc.py index cfaed834..a221c9f2 100644 --- a/oidc-controller/api/routers/oidc.py +++ b/oidc-controller/api/routers/oidc.py @@ -1,5 +1,6 @@ import base64 import io +import time import uuid from datetime import UTC, datetime from typing import cast @@ -15,9 +16,9 @@ from oic.oic.message import AuthorizationRequest from pymongo.database import Database from pyop.exceptions import ( - InvalidAuthenticationRequest, - InvalidAccessToken, BearerTokenError, + InvalidAccessToken, + InvalidAuthenticationRequest, ) from ..authSessions.crud import AuthSessionCreate, AuthSessionCRUD @@ -27,6 +28,11 @@ from ..core.logger_util import log_debug from ..core.oidc import provider from ..core.oidc.issue_token_service import Token +from ..core.siam_audit import ( + audit_auth_session_initiated, + audit_proof_request_created, + audit_token_issued, +) from ..db.session import get_db # Access to the websocket @@ -189,6 +195,24 @@ async def get_authorize(request: Request, db: Database = Depends(get_db)): ) auth_session = await AuthSessionCRUD(db).create(new_auth_session) + # SIAM Audit: Log auth session initiation (no PII, safe metadata only) + client_ip = request.client.host if request.client else None + user_agent = request.headers.get("user-agent") + audit_auth_session_initiated( + session_id=str(auth_session.id), + client_id=model.get("client_id", "unknown"), + ver_config=ver_config, + client_ip=client_ip, + user_agent=user_agent, + ) + + # SIAM Audit: Log proof request creation + audit_proof_request_created( + session_id=str(auth_session.id), + ver_config=ver_config, + proof_name=ver_config.proof_request.name, + ) + # QR CONTENTS controller_host = settings.CONTROLLER_URL url_to_message = ( @@ -359,6 +383,7 @@ async def generate_auth_code(claims, auth_session, form_dict, db): @router.post(VerifiedCredentialTokenUri, response_class=JSONResponse) async def post_token(request: Request, db: Database = Depends(get_db)): """Called by oidc platform to retrieve token contents""" + token_start_time = time.time() async with request.form() as form: logger.info(f"post_token: form was {form}") form_dict = cast(dict[str, str], form._dict) @@ -520,6 +545,16 @@ async def post_token(request: Request, db: Database = Depends(get_db)): all_claims=list(decoded.keys()), ) + # SIAM Audit: Log successful token issuance (count only, no claim values) + token_duration_ms = int((time.time() - token_start_time) * 1000) + audit_token_issued( + session_id=str(auth_session.id), + client_id=auth_session.request_parameters.get("client_id", "unknown"), + ver_config_id=auth_session.ver_config_id, + claims_count=len(claims), + duration_ms=token_duration_ms, + ) + return token_response.to_dict() diff --git a/oidc-controller/api/routers/presentation_request.py b/oidc-controller/api/routers/presentation_request.py index b504333a..49f7248a 100644 --- a/oidc-controller/api/routers/presentation_request.py +++ b/oidc-controller/api/routers/presentation_request.py @@ -1,5 +1,4 @@ import structlog - from fastapi import APIRouter, Depends, Request from fastapi.responses import HTMLResponse, JSONResponse, RedirectResponse from jinja2 import Template @@ -7,11 +6,11 @@ from ..authSessions.crud import AuthSessionCRUD from ..authSessions.models import AuthSession, AuthSessionState - from ..core.config import settings -from ..routers.socketio import sio, get_socket_id_for_pid, safe_emit -from ..routers.oidc import gen_deep_link +from ..core.siam_audit import audit_qr_scanned from ..db.session import get_db +from ..routers.oidc import gen_deep_link +from ..routers.socketio import get_socket_id_for_pid, safe_emit, sio logger: structlog.typing.FilteringBoundLogger = structlog.getLogger(__name__) @@ -35,6 +34,19 @@ async def send_connectionless_proof_req( If the user scanes the QR code with a mobile camera, they will be redirected to a help page. """ + # SIAM Audit: Log QR scan before redirect path split to capture all scans + auth_session: AuthSession = await AuthSessionCRUD(db).get_by_pres_exch_id( + pres_exch_id + ) + client_ip = req.client.host if req.client else None + user_agent = req.headers.get("user-agent") + audit_qr_scanned( + session_id=str(auth_session.id), + scan_method="qr_code", + client_ip=client_ip, + user_agent=user_agent, + ) + # First prepare the response depending on the redirect url if ".html" in settings.CONTROLLER_CAMERA_REDIRECT_URL: response = RedirectResponse(settings.CONTROLLER_CAMERA_REDIRECT_URL) @@ -44,14 +56,12 @@ async def send_connectionless_proof_req( "r", ).read() - auth_session: AuthSession = await AuthSessionCRUD(db).get_by_pres_exch_id( - pres_exch_id - ) wallet_deep_link = gen_deep_link(auth_session) template = Template(template_file) # If the qrcode was scanned by mobile phone camera toggle the pending flag await toggle_pending(db, auth_session) + response = HTMLResponse(template.render({"wallet_deep_link": wallet_deep_link})) if "text/html" in req.headers.get("accept"): @@ -69,6 +79,16 @@ async def send_connectionless_proof_req( if auth_session.proof_status is AuthSessionState.NOT_STARTED: await toggle_pending(db, auth_session) + # SIAM Audit: Log QR scan via wallet deep link + client_ip = req.client.host if req.client else None + user_agent = req.headers.get("user-agent") + audit_qr_scanned( + session_id=str(auth_session.id), + scan_method="deep_link", + client_ip=client_ip, + user_agent=user_agent, + ) + msg = auth_session.presentation_request_msg logger.debug(msg) diff --git a/oidc-controller/api/routers/tests/test_acapy_handler.py b/oidc-controller/api/routers/tests/test_acapy_handler.py index 6a71c8b5..ba29541c 100644 --- a/oidc-controller/api/routers/tests/test_acapy_handler.py +++ b/oidc-controller/api/routers/tests/test_acapy_handler.py @@ -4,13 +4,12 @@ from unittest.mock import AsyncMock, MagicMock, patch import pytest -from bson import ObjectId -from fastapi.testclient import TestClient -from pymongo.database import Database - from api.authSessions.models import AuthSession, AuthSessionState from api.core.config import settings from api.routers.acapy_handler import post_topic +from bson import ObjectId +from fastapi.testclient import TestClient +from pymongo.database import Database @pytest.fixture @@ -467,6 +466,7 @@ async def test_problem_report_not_sent_when_no_pres_exch_id( mock_auth_session_no_pres_id.pres_exch_id = None mock_auth_session_no_pres_id.connection_id = "test-connection-id" mock_auth_session_no_pres_id.multi_use = False + mock_auth_session_no_pres_id.ver_config_id = "test-ver-config-id" mock_auth_session_no_pres_id.model_dump = MagicMock( return_value={ "id": "test-session-id", @@ -1429,3 +1429,162 @@ async def test_prover_role_handles_delete_exception( mock_client.delete_presentation_record.assert_called_once_with( "test-pres-ex-id" ) + + +# =================================================================== +# Tests for _extract_credential_schemas / _extract_issuer_dids +# =================================================================== + +from api.routers.acapy_handler import _extract_credential_schemas, _extract_issuer_dids + + +def _make_presentation_data(identifiers, format_key="indy"): + """Helper to build a minimal presentation_data dict.""" + return { + "by_format": { + format_key: { + "pres": { + "identifiers": identifiers, + } + } + } + } + + +class TestExtractCredentialSchemas: + """Tests for _extract_credential_schemas from presentation data.""" + + def test_empty_data(self): + assert _extract_credential_schemas({}) == [] + + def test_unqualified_did_schema_id(self): + """Legacy unqualified DID: DXzMEuV1efR3RbU8vSkMbN:2:Person:1.0""" + data = _make_presentation_data( + [{"schema_id": "DXzMEuV1efR3RbU8vSkMbN:2:Person:1.0"}] + ) + assert _extract_credential_schemas(data) == ["Person"] + + def test_qualified_did_schema_id(self): + """Fully-qualified DID: did:sov:DXzMEuV1efR3RbU8vSkMbN:2:Person:1.0""" + data = _make_presentation_data( + [{"schema_id": "did:sov:DXzMEuV1efR3RbU8vSkMbN:2:Person:1.0"}] + ) + assert _extract_credential_schemas(data) == ["Person"] + + def test_qualified_did_indy_schema_id(self): + """did:indy:sovrin:ABC123:2:HealthCard:2.1""" + data = _make_presentation_data( + [{"schema_id": "did:indy:sovrin:ABC123:2:HealthCard:2.1"}] + ) + assert _extract_credential_schemas(data) == ["HealthCard"] + + def test_multiple_schemas_deduped_and_sorted(self): + data = _make_presentation_data( + [ + {"schema_id": "IssuerA:2:Zebra:1.0"}, + {"schema_id": "IssuerB:2:Alpha:2.0"}, + {"schema_id": "IssuerC:2:Zebra:1.0"}, + ] + ) + assert _extract_credential_schemas(data) == ["Alpha", "Zebra"] + + def test_anoncreds_format(self): + data = _make_presentation_data( + [{"schema_id": "IssuerA:2:Person:1.0"}], format_key="anoncreds" + ) + assert _extract_credential_schemas(data) == ["Person"] + + def test_no_marker_falls_back_to_raw(self): + """When schema_id has no :2: marker, return the raw value.""" + data = _make_presentation_data([{"schema_id": "some-opaque-id"}]) + assert _extract_credential_schemas(data) == ["some-opaque-id"] + + def test_missing_identifiers_key(self): + data = {"by_format": {"indy": {"pres": {}}}} + assert _extract_credential_schemas(data) == [] + + def test_missing_schema_id_key(self): + data = _make_presentation_data([{"cred_def_id": "something"}]) + assert _extract_credential_schemas(data) == [] + + def test_malformed_by_format(self): + assert _extract_credential_schemas({"by_format": "bad"}) == [] + + def test_schema_name_only_after_marker(self): + """schema_id with only one part after :2: (no version).""" + data = _make_presentation_data([{"schema_id": "DID:2:SchemaOnly"}]) + assert _extract_credential_schemas(data) == ["SchemaOnly"] + + +class TestExtractIssuerDids: + """Tests for _extract_issuer_dids from presentation data.""" + + def test_empty_data(self): + assert _extract_issuer_dids({}) == [] + + def test_unqualified_did(self): + """Legacy unqualified DID: DXzMEuV1efR3RbU8vSkMbN:3:CL:123:default""" + data = _make_presentation_data( + [{"cred_def_id": "DXzMEuV1efR3RbU8vSkMbN:3:CL:123:default"}] + ) + assert _extract_issuer_dids(data) == ["DXzMEuV1efR3RbU8vSkMbN"] + + def test_qualified_did_sov(self): + """Fully-qualified DID: did:sov:DXzMEuV1efR3RbU8vSkMbN:3:CL:123:default""" + data = _make_presentation_data( + [{"cred_def_id": "did:sov:DXzMEuV1efR3RbU8vSkMbN:3:CL:123:default"}] + ) + assert _extract_issuer_dids(data) == ["did:sov:DXzMEuV1efR3RbU8vSkMbN"] + + def test_qualified_did_indy(self): + """did:indy:sovrin:ABC123:3:CL:456:latest""" + data = _make_presentation_data( + [{"cred_def_id": "did:indy:sovrin:ABC123:3:CL:456:latest"}] + ) + assert _extract_issuer_dids(data) == ["did:indy:sovrin:ABC123"] + + def test_multiple_issuers_deduped_and_sorted(self): + data = _make_presentation_data( + [ + {"cred_def_id": "did:sov:ZZZ:3:CL:1:tag"}, + {"cred_def_id": "did:sov:AAA:3:CL:2:tag"}, + {"cred_def_id": "did:sov:ZZZ:3:CL:3:other"}, + ] + ) + assert _extract_issuer_dids(data) == ["did:sov:AAA", "did:sov:ZZZ"] + + def test_anoncreds_format(self): + data = _make_presentation_data( + [{"cred_def_id": "IssuerA:3:CL:99:default"}], format_key="anoncreds" + ) + assert _extract_issuer_dids(data) == ["IssuerA"] + + def test_no_marker_falls_back_to_raw(self): + """When cred_def_id has no :3:CL: marker, return the raw value.""" + data = _make_presentation_data([{"cred_def_id": "some-opaque-id"}]) + assert _extract_issuer_dids(data) == ["some-opaque-id"] + + def test_missing_identifiers_key(self): + data = {"by_format": {"indy": {"pres": {}}}} + assert _extract_issuer_dids(data) == [] + + def test_missing_cred_def_id_key(self): + data = _make_presentation_data([{"schema_id": "something"}]) + assert _extract_issuer_dids(data) == [] + + def test_malformed_by_format(self): + assert _extract_issuer_dids({"by_format": "bad"}) == [] + + def test_both_formats_combined(self): + """Identifiers present under both indy and anoncreds.""" + data = { + "by_format": { + "indy": { + "pres": {"identifiers": [{"cred_def_id": "did:sov:A:3:CL:1:t"}]} + }, + "anoncreds": { + "pres": {"identifiers": [{"cred_def_id": "did:sov:B:3:CL:2:t"}]} + }, + } + } + assert _extract_issuer_dids(data) == ["did:sov:A", "did:sov:B"] diff --git a/oidc-controller/api/routers/tests/test_acapy_handler_cleanup.py b/oidc-controller/api/routers/tests/test_acapy_handler_cleanup.py index 602cd538..9f85195e 100644 --- a/oidc-controller/api/routers/tests/test_acapy_handler_cleanup.py +++ b/oidc-controller/api/routers/tests/test_acapy_handler_cleanup.py @@ -27,6 +27,7 @@ def mock_auth_session(self): auth_session.connection_id = "test-connection-id" auth_session.proof_status = AuthSessionState.NOT_STARTED auth_session.multi_use = False + auth_session.ver_config_id = "test-ver-config-id" auth_session.model_dump.return_value = { "id": str(auth_session.id), "pres_exch_id": auth_session.pres_exch_id,