DIF presentation debug logging (#4019)

nodlesh · jamshale · web-flow · commit 0267a942de89 · 2026-01-13T21:15:27.000Z
* DIF presentation debug logging

Signed-off-by: Sheldon Regular &lt;sheldon.regular@gmail.com&gt;

* fixed ruff failures

Signed-off-by: Sheldon Regular &lt;sheldon.regular@gmail.com&gt;

* more ruff lint fixes

Signed-off-by: Sheldon Regular &lt;sheldon.regular@gmail.com&gt;

---------

Signed-off-by: Sheldon Regular &lt;sheldon.regular@gmail.com&gt;
Co-authored-by: jamshale &lt;31809382+jamshale@users.noreply.github.com&gt;
diff --git a/acapy_agent/protocols/present_proof/dif/pres_exch_handler.py b/acapy_agent/protocols/present_proof/dif/pres_exch_handler.py
@@ -1067,6 +1067,12 @@ async def apply_requirements(
         result = {}
         # Get all input_descriptors attached to the PresentationDefinition
         descriptor_list = req.input_descriptors or []
+        LOGGER.debug(
+            "DIF-PRES apply_requirements: descriptors=%s creds=%s records_filter=%s",
+            len(descriptor_list),
+            len(credentials),
+            list(records_filter.keys()) if records_filter else None,
+        )
         for descriptor in descriptor_list:
             # Filter credentials to apply filtering
             # upon by matching each credentialSchema.id
@@ -1090,6 +1096,13 @@ async def apply_requirements(
                 constraints=descriptor.constraint,
                 credentials=filtered_by_schema,
             )
+            LOGGER.debug(
+                "DIF-PRES apply_requirements: descriptor=%s schema_filtered=%s "
+                "constraints_filtered=%s",
+                descriptor.id,
+                len(filtered_by_schema),
+                len(filtered),
+            )
             if len(filtered) != 0:
                 result[descriptor.id] = filtered
 
diff --git a/acapy_agent/protocols/present_proof/v2_0/formats/dif/handler.py b/acapy_agent/protocols/present_proof/v2_0/formats/dif/handler.py
@@ -17,6 +17,7 @@
     Ed25519Signature2018,
     Ed25519Signature2020,
 )
+from ......vc.ld_proofs.validation_result import DocumentVerificationResult
 from ......vc.vc_di.manager import VcDiManager
 from ......vc.vc_ld.manager import VcLdpManager
 from ......vc.vc_ld.models.options import LDProofVCOptions
@@ -167,6 +168,16 @@ async def create_pres(
         if not challenge:
             challenge = str(uuid4())
         input_descriptors = pres_definition.input_descriptors
+        LOGGER.debug(
+            "DIF-PRES create_pres: pres_ex_id=%s thread_id=%s pd_id=%s "
+            "input_descriptors=%s issuer_id=%s record_ids=%s",
+            pres_ex_record.pres_ex_id,
+            pres_ex_record.thread_id,
+            pres_definition.id if pres_definition else None,
+            len(input_descriptors) if input_descriptors else 0,
+            issuer_id,
+            len(limit_record_ids) if limit_record_ids else 0,
+        )
         claim_fmt = pres_definition.fmt
         dif_handler_proof_type = None
         try:
@@ -200,6 +211,15 @@ async def create_pres(
                     uri_list = None
                 if len(one_of_uri_groups) == 0:
                     one_of_uri_groups = None
+                LOGGER.debug(
+                    "DIF-PRES descriptor=%s oneof=%s uri_list=%s uri_groups=%s "
+                    "limit_disclosure=%s",
+                    input_descriptor.id,
+                    bool(one_of_uri_groups),
+                    uri_list,
+                    one_of_uri_groups,
+                    limit_disclosure,
+                )
                 if limit_disclosure:
                     proof_type = [BbsBlsSignature2020.signature_type]
                     dif_handler_proof_type = BbsBlsSignature2020.signature_type
@@ -321,6 +341,14 @@ async def create_pres(
                         )
                         max_results = 1000
                         cred_group = await search.fetch(max_results)
+                        LOGGER.debug(
+                            "DIF-PRES search(oneof): descriptor=%s uris=%s "
+                            "proof_types=%s results=%s",
+                            input_descriptor.id,
+                            uri_group,
+                            proof_type,
+                            len(cred_group),
+                        )
                         (
                             cred_group_vcrecord_list,
                             cred_group_vcrecord_ids_set,
@@ -337,6 +365,14 @@ async def create_pres(
                     # For now, setting to 1000
                     max_results = 1000
                     records = await search.fetch(max_results)
+                    LOGGER.debug(
+                        "DIF-PRES search: descriptor=%s uris=%s proof_types=%s "
+                        "results=%s",
+                        input_descriptor.id,
+                        uri_list,
+                        proof_type,
+                        len(records),
+                    )
 
                 # Avoiding addition of duplicate records
                 (
@@ -345,6 +381,12 @@ async def create_pres(
                 ) = await self.process_vcrecords_return_list(records, record_ids)
                 record_ids = vcrecord_ids_set
                 credentials_list = credentials_list + vcrecord_list
+                LOGGER.debug(
+                    "DIF-PRES candidates: descriptor=%s added=%s total=%s",
+                    input_descriptor.id,
+                    len(vcrecord_list),
+                    len(credentials_list),
+                )
 
         except StorageNotFoundError as err:
             raise V20PresFormatHandlerError(err)
@@ -376,6 +418,15 @@ async def create_pres(
             reveal_doc=reveal_doc_frame,
         )
         try:
+            LOGGER.debug(
+                "DIF-PRES create_vp: pres_ex_id=%s thread_id=%s proof_type=%s "
+                "creds=%s records_filter=%s",
+                pres_ex_record.pres_ex_id,
+                pres_ex_record.thread_id,
+                dif_handler_proof_type,
+                len(credentials_list),
+                len(limit_record_ids) if limit_record_ids else 0,
+            )
             pres = await dif_handler.create_vp(
                 challenge=challenge,
                 domain=domain,
@@ -469,30 +520,98 @@ async def verify_pres(self, pres_ex_record: V20PresExRecord) -> V20PresExRecord:
         dif_proof = pres_ex_record.pres.attachment(DIFPresFormatHandler.format)
         pres_request = pres_ex_record.pres_request.attachment(DIFPresFormatHandler.format)
         pres_ver_result = None
+        log_details = self._profile.settings.get("debug.presentations")
+
+        LOGGER.debug(
+            "DIF-PRES verify_pres: pres_ex_id=%s thread_id=%s proof_is_sequence=%s",
+            pres_ex_record.pres_ex_id,
+            pres_ex_record.thread_id,
+            isinstance(dif_proof, Sequence),
+        )
         if isinstance(dif_proof, Sequence):
             if len(dif_proof) == 0:
                 raise V20PresFormatHandlerError(
                     "Presentation exchange record has no presentations to verify"
                 )
             for proof in dif_proof:
                 manager, options = self._get_type_manager_options(proof, pres_request)
+                proof_type = (proof.get("proof") or {}).get("type")
+                LOGGER.debug(
+                    "DIF-PRES verify_pres: proof_type=%s manager=%s",
+                    proof_type,
+                    manager.__class__.__name__,
+                )
                 pres_ver_result = await manager.verify_presentation(
                     vp=VerifiablePresentation.deserialize(proof),
                     options=options,
                 )
+                LOGGER.debug(
+                    "DIF-PRES verify_pres result: verified=%s errors=%s",
+                    pres_ver_result.verified,
+                    pres_ver_result.errors,
+                )
+                if log_details:
+                    LOGGER.debug(
+                        "DIF-PRES verify_pres details: presentation_result=%s "
+                        "credential_results=%s",
+                        self._summarize_doc_result(pres_ver_result.presentation_result),
+                        [
+                            self._summarize_doc_result(r)
+                            for r in (pres_ver_result.credential_results or [])
+                        ],
+                    )
                 if not pres_ver_result.verified:
                     break
         else:
             manager, options = self._get_type_manager_options(dif_proof, pres_request)
+            proof_type = (dif_proof.get("proof") or {}).get("type")
+            LOGGER.debug(
+                "DIF-PRES verify_pres: proof_type=%s manager=%s",
+                proof_type,
+                manager.__class__.__name__,
+            )
             pres_ver_result = await manager.verify_presentation(
                 vp=VerifiablePresentation.deserialize(dif_proof),
                 options=options,
             )
+            LOGGER.debug(
+                "DIF-PRES verify_pres result: verified=%s errors=%s",
+                pres_ver_result.verified,
+                pres_ver_result.errors,
+            )
+            if log_details:
+                LOGGER.debug(
+                    "DIF-PRES verify_pres details: presentation_result=%s "
+                    "credential_results=%s",
+                    self._summarize_doc_result(pres_ver_result.presentation_result),
+                    [
+                        self._summarize_doc_result(r)
+                        for r in (pres_ver_result.credential_results or [])
+                    ],
+                )
 
         assert pres_ver_result is not None
         pres_ex_record.verified = json.dumps(pres_ver_result.verified)
         return pres_ex_record
 
+    @staticmethod
+    def _summarize_doc_result(doc_result: Optional[DocumentVerificationResult]):
+        if not doc_result:
+            return None
+        proof_results = [
+            {
+                "verified": pr.verified,
+                "error": pr.error,
+                "purpose_error": getattr(pr.purpose_result, "error", None),
+            }
+            for pr in (doc_result.results or [])
+        ]
+        return {
+            "verified": doc_result.verified,
+            "errors": doc_result.errors,
+            "proof_results": proof_results,
+        }
+
     def _get_type_manager_options(self, dif_proof: dict, pres_request: dict):
         """Get the type of manager and options based on the proof type."""
         if dif_proof.get("proof") and dif_proof["proof"]["type"] == "DataIntegrityProof":
diff --git a/acapy_agent/protocols/present_proof/v2_0/formats/dif/tests/test_handler.py b/acapy_agent/protocols/present_proof/v2_0/formats/dif/tests/test_handler.py
@@ -12,6 +12,11 @@
 from .......tests import mock
 from .......utils.testing import create_test_profile, skip_on_jsonld_url_error
 from .......vc.ld_proofs import DocumentLoader
+from .......vc.ld_proofs.validation_result import (
+    DocumentVerificationResult,
+    ProofResult,
+    PurposeResult,
+)
 from .......vc.vc_di.manager import VcDiManager
 from .......vc.vc_ld.manager import VcLdpManager
 from .......vc.vc_ld.validation_result import PresentationVerificationResult
@@ -2379,3 +2384,27 @@ async def test_get_type_manager_options(self):
         manager, options = handler._get_type_manager_options(dif_proof, pres_request)
         assert isinstance(manager, VcLdpManager)
         assert options.challenge == "3fa85f64-5717-4562-b3fc-2c963f66afa7"
+
+    async def test_summarize_doc_result_redacts_sensitive_fields(self):
+        self.profile = await create_test_profile()
+        handler = DIFPresFormatHandler(self.profile)
+        doc_result = DocumentVerificationResult(
+            verified=False,
+            document={"id": "doc", "proof": {"proofValue": "secret"}},
+            results=[
+                ProofResult(
+                    verified=False,
+                    proof={"proofValue": "secret"},
+                    error="bad proof",
+                    purpose_result=PurposeResult(valid=False, error="purpose failed"),
+                )
+            ],
+            errors=["verification failed"],
+        )
+        summary = handler._summarize_doc_result(doc_result)
+        assert summary["verified"] is False
+        assert summary["errors"] == ["verification failed"]
+        assert "document" not in summary
+        assert "proof" not in summary["proof_results"][0]
+        assert summary["proof_results"][0]["error"] == "bad proof"
+        assert summary["proof_results"][0]["purpose_error"] == "purpose failed"
