search

openwallet-foundation / acapy

Hyperledger Aries Cloud Agent Python (ACA-Py) is a foundation for building decentralized identity applications and services running in non-mobile environments.
https://wiki.hyperledger.org/display/aries
Apache License 2.0
412 stars 512 forks source link

Connection related issues with py3.9-0.10.0-rc1 / py3.9-0.10.0-dev0 images #2444

Closed WadeBarnes closed 1 year ago

WadeBarnes commented 1 year ago

Seeing the following errors when trying to make connections:

2023-08-24 14:46:56,361 aries_cloudagent.core.conductor ERROR Exception in message handler:
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 256, in __step
    result = coro.send(None)
  File "/home/aries/.local/lib/python3.9/site-packages/aries_cloudagent/core/dispatcher.py", line 261, in handle_message
    await handler(context, responder)
  File "/home/aries/.local/lib/python3.9/site-packages/aries_cloudagent/protocols/connections/v1_0/handlers/connection_request_handler.py", line 38, in handle
    connection = await mgr.receive_request(
  File "/home/aries/.local/lib/python3.9/site-packages/aries_cloudagent/protocols/connections/v1_0/manager.py", line 513, in receive_request
    await self.store_did_document(conn_did_doc)
  File "/home/aries/.local/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 213, in store_did_document
    await self.add_key_for_did(did_doc.did, key.value)
  File "/home/aries/.local/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 226, in add_key_for_did
    await storage.find_record(self.RECORD_TYPE_DID_KEY, {"key": key})
  File "/home/aries/.local/lib/python3.9/site-packages/aries_cloudagent/storage/askar.py", line 167, in find_record
    raise StorageDuplicateError("Duplicate records found")
aries_cloudagent.storage.error.StorageDuplicateError: Duplicate records found
2023-08-24 14:46:56,362 aries_cloudagent.core.conductor ERROR DON'T shutdown on StorageDuplicateError Duplicate records found
2023-08-24 14:46:56,362 aries_cloudagent.core.dispatcher ERROR Handler error: Dispatcher.handle_message
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 256, in __step
    result = coro.send(None)
  File "/home/aries/.local/lib/python3.9/site-packages/aries_cloudagent/core/dispatcher.py", line 261, in handle_message
    await handler(context, responder)
  File "/home/aries/.local/lib/python3.9/site-packages/aries_cloudagent/protocols/connections/v1_0/handlers/connection_request_handler.py", line 38, in handle
    connection = await mgr.receive_request(
  File "/home/aries/.local/lib/python3.9/site-packages/aries_cloudagent/protocols/connections/v1_0/manager.py", line 513, in receive_request
    await self.store_did_document(conn_did_doc)
  File "/home/aries/.local/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 213, in store_did_document
    await self.add_key_for_did(did_doc.did, key.value)
  File "/home/aries/.local/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 226, in add_key_for_did
    await storage.find_record(self.RECORD_TYPE_DID_KEY, {"key": key})
  File "/home/aries/.local/lib/python3.9/site-packages/aries_cloudagent/storage/askar.py", line 167, in find_record
    raise StorageDuplicateError("Duplicate records found")
aries_cloudagent.storage.error.StorageDuplicateError: Duplicate records found

cc: @swcurran, @dbluhm, @marcos-carretero

WadeBarnes commented 1 year ago

@nodlesh, @swcurran mentioned you were reporting connection related issues too.

WadeBarnes commented 1 year ago

@dbluhm, Is this related to https://github.com/hyperledger/aries-cloudagent-python/pull/2409?

dbluhm commented 1 year ago

Yes, this looks like it is related to #2409; my changes to make the add_key_for_did method idempotent don't appear to be working as expected. I'll dig in but any details you can provide on the sequence of exchanges that lead to this error would be helpful.

nodlesh commented 1 year ago

I am also having connection issues. however I don't see the errors Wade is seeing. Let me know if my issue is different enough to warrant it's own issue. Last nights BC Wallet regression tests failed connecting to my test agents which are pulled from acapy main. The agent gets to response-sent and nothing else happens, the wallet is spinning on the connection screen. Using acapy main from the night before is fine, along with the official release of ACA-Py. The error in my agent at the time of the problem is, 

2023-08-24 15:34:37,113 aries_cloudagent.core.dispatcher ERROR Handler error: BaseConnectionManager.get_connection_targets
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/pydid/validation.py", line 13, in wrap_validation_error
    yield
  File "/usr/local/lib/python3.9/site-packages/pydid/resource.py", line 68, in deserialize
    return parse_obj_as(cls, value)
  File "pydantic/tools.py", line 38, in pydantic.tools.parse_obj_as
  File "pydantic/main.py", line 341, in pydantic.main.BaseModel.__init__
pydantic.error_wrappers.ValidationError: 1 validation error for ParsingModel[DIDDocumentRoot]
__root__ -> service -> 0 -> id
  did:sov:PkWfCgY4SSAYeSoaWx3RFP;PkWfCgY4SSAYeSoaWx3RFP#IndyAgentService is not a valid absolute or relative DID URL (type=value_error.invaliddidurl)

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 256, in __step
    result = coro.send(None)
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 603, in get_connection_targets
    targets = await self.fetch_connection_targets(connection)
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 564, in fetch_connection_targets
    return await self.resolve_connection_targets(
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 356, in resolve_connection_targets
    doc, didcomm_services = await self.resolve_didcomm_services(did)
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 263, in resolve_didcomm_services
    doc: ResolvedDocument = pydid.deserialize_document(doc_dict, strict=True)
  File "/usr/local/lib/python3.9/site-packages/pydid/__init__.py", line 63, in deserialize_document
    return cls.deserialize(value)
  File "/usr/local/lib/python3.9/site-packages/pydid/doc/doc.py", line 171, in deserialize
    DIDDocumentRoot.deserialize(value)
  File "/usr/local/lib/python3.9/site-packages/pydid/resource.py", line 68, in deserialize
    return parse_obj_as(cls, value)
  File "/usr/local/lib/python3.9/contextlib.py", line 137, in __exit__
    self.gen.throw(typ, value, traceback)
  File "/usr/local/lib/python3.9/site-packages/pydid/validation.py", line 15, in wrap_validation_error
    raise error_to_raise(
ValueError: Failed to deserialize DIDDocumentRoot:
1 validation error for ParsingModel[DIDDocumentRoot]
__root__ -> service -> 0 -> id
  did:sov:PkWfCgY4SSAYeSoaWx3RFP;PkWfCgY4SSAYeSoaWx3RFP#IndyAgentService is not a valid absolute or relative DID URL (type=value_error.invaliddidurl)
2023-08-24 15:34:37,185 aries_cloudagent.core.conductor ERROR Exception in message handler:
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/pydid/validation.py", line 13, in wrap_validation_error
    yield
  File "/usr/local/lib/python3.9/site-packages/pydid/resource.py", line 68, in deserialize
    return parse_obj_as(cls, value)
  File "pydantic/tools.py", line 38, in pydantic.tools.parse_obj_as
  File "pydantic/main.py", line 341, in pydantic.main.BaseModel.__init__
pydantic.error_wrappers.ValidationError: 1 validation error for ParsingModel[DIDDocumentRoot]
__root__ -> service -> 0 -> id
  did:sov:PkWfCgY4SSAYeSoaWx3RFP;PkWfCgY4SSAYeSoaWx3RFP#IndyAgentService is not a valid absolute or relative DID URL (type=value_error.invaliddidurl)

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 258, in __step
    result = coro.throw(exc)
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/core/dispatcher.py", line 261, in handle_message
    await handler(context, responder)
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/protocols/connections/v1_0/handlers/connection_request_handler.py", line 47, in handle
    await responder.send_reply(
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/messaging/responder.py", line 142, in send_reply
    return await self.send_outbound(
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/core/dispatcher.py", line 406, in send_outbound
    return await self._send(context.profile, message, self._inbound_message)
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/core/conductor.py", line 637, in outbound_message_router
    status: OutboundSendStatus = await self._outbound_message_router(
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/core/conductor.py", line 665, in _outbound_message_router
    return await self.queue_outbound(profile, outbound, inbound)
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/core/conductor.py", line 697, in queue_outbound
    outbound.target_list = await self.dispatcher.run_task(
  File "/usr/local/lib/python3.9/asyncio/futures.py", line 284, in __await__
    yield self  # This tells Task to wait for completion.
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 328, in __wakeup
    future.result()
  File "/usr/local/lib/python3.9/asyncio/futures.py", line 201, in result
    raise self._exception
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 256, in __step
    result = coro.send(None)
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 603, in get_connection_targets
    targets = await self.fetch_connection_targets(connection)
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 564, in fetch_connection_targets
    return await self.resolve_connection_targets(
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 356, in resolve_connection_targets
    doc, didcomm_services = await self.resolve_didcomm_services(did)
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 263, in resolve_didcomm_services
    doc: ResolvedDocument = pydid.deserialize_document(doc_dict, strict=True)
  File "/usr/local/lib/python3.9/site-packages/pydid/__init__.py", line 63, in deserialize_document
    return cls.deserialize(value)
  File "/usr/local/lib/python3.9/site-packages/pydid/doc/doc.py", line 171, in deserialize
    DIDDocumentRoot.deserialize(value)
  File "/usr/local/lib/python3.9/site-packages/pydid/resource.py", line 68, in deserialize
    return parse_obj_as(cls, value)
  File "/usr/local/lib/python3.9/contextlib.py", line 137, in __exit__
    self.gen.throw(typ, value, traceback)
  File "/usr/local/lib/python3.9/site-packages/pydid/validation.py", line 15, in wrap_validation_error
    raise error_to_raise(
ValueError: Failed to deserialize DIDDocumentRoot:
1 validation error for ParsingModel[DIDDocumentRoot]
__root__ -> service -> 0 -> id
  did:sov:PkWfCgY4SSAYeSoaWx3RFP;PkWfCgY4SSAYeSoaWx3RFP#IndyAgentService is not a valid absolute or relative DID URL (type=value_error.invaliddidurl)
2023-08-24 15:34:37,203 aries_cloudagent.core.conductor ERROR DON'T shutdown on ValueError Failed to deserialize DIDDocumentRoot:
1 validation error for ParsingModel[DIDDocumentRoot]
__root__ -> service -> 0 -> id
  did:sov:PkWfCgY4SSAYeSoaWx3RFP;PkWfCgY4SSAYeSoaWx3RFP#IndyAgentService is not a valid absolute or relative DID URL (type=value_error.invaliddidurl)
2023-08-24 15:34:37,204 aries_cloudagent.core.dispatcher ERROR Handler error: Dispatcher.handle_message
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/pydid/validation.py", line 13, in wrap_validation_error
    yield
  File "/usr/local/lib/python3.9/site-packages/pydid/resource.py", line 68, in deserialize
    return parse_obj_as(cls, value)
  File "pydantic/tools.py", line 38, in pydantic.tools.parse_obj_as
  File "pydantic/main.py", line 341, in pydantic.main.BaseModel.__init__
pydantic.error_wrappers.ValidationError: 1 validation error for ParsingModel[DIDDocumentRoot]
__root__ -> service -> 0 -> id
  did:sov:PkWfCgY4SSAYeSoaWx3RFP;PkWfCgY4SSAYeSoaWx3RFP#IndyAgentService is not a valid absolute or relative DID URL (type=value_error.invaliddidurl)

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 258, in __step
    result = coro.throw(exc)
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/core/dispatcher.py", line 261, in handle_message
    await handler(context, responder)
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/protocols/connections/v1_0/handlers/connection_request_handler.py", line 47, in handle
    await responder.send_reply(
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/messaging/responder.py", line 142, in send_reply
    return await self.send_outbound(
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/core/dispatcher.py", line 406, in send_outbound
    return await self._send(context.profile, message, self._inbound_message)
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/core/conductor.py", line 637, in outbound_message_router
    status: OutboundSendStatus = await self._outbound_message_router(
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/core/conductor.py", line 665, in _outbound_message_router
    return await self.queue_outbound(profile, outbound, inbound)
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/core/conductor.py", line 697, in queue_outbound
    outbound.target_list = await self.dispatcher.run_task(
  File "/usr/local/lib/python3.9/asyncio/futures.py", line 284, in __await__
    yield self  # This tells Task to wait for completion.
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 328, in __wakeup
    future.result()
  File "/usr/local/lib/python3.9/asyncio/futures.py", line 201, in result
    raise self._exception
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 256, in __step
    result = coro.send(None)
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 603, in get_connection_targets
    targets = await self.fetch_connection_targets(connection)
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 564, in fetch_connection_targets
    return await self.resolve_connection_targets(
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 356, in resolve_connection_targets
    doc, didcomm_services = await self.resolve_didcomm_services(did)
  File "/usr/local/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 263, in resolve_didcomm_services
    doc: ResolvedDocument = pydid.deserialize_document(doc_dict, strict=True)
  File "/usr/local/lib/python3.9/site-packages/pydid/__init__.py", line 63, in deserialize_document
    return cls.deserialize(value)
  File "/usr/local/lib/python3.9/site-packages/pydid/doc/doc.py", line 171, in deserialize
    DIDDocumentRoot.deserialize(value)
  File "/usr/local/lib/python3.9/site-packages/pydid/resource.py", line 68, in deserialize
    return parse_obj_as(cls, value)
  File "/usr/local/lib/python3.9/contextlib.py", line 137, in __exit__
    self.gen.throw(typ, value, traceback)
  File "/usr/local/lib/python3.9/site-packages/pydid/validation.py", line 15, in wrap_validation_error
    raise error_to_raise(
ValueError: Failed to deserialize DIDDocumentRoot:
1 validation error for ParsingModel[DIDDocumentRoot]
__root__ -> service -> 0 -> id
  did:sov:PkWfCgY4SSAYeSoaWx3RFP;PkWfCgY4SSAYeSoaWx3RFP#IndyAgentService is not a valid absolute or relative DID URL (type=value_error.invaliddidurl)
dbluhm commented 1 year ago

@nodlesh I believe this is a different enough error to warrant a separate issue. Short form is PyDID doesn't like the ; in that service id. That could be an error in the LegacyDocCorrections.

nodlesh commented 1 year ago

New issue logged, #2445

dbluhm commented 1 year ago

@WadeBarnes the extent of what I can determine from the logs you posted is that there's a connection protocol taking place and it fails on receive request. I'm attempting to reproduce the issue and the permutations I've tried so far haven't resulted in the same error yet. Any further details you can provide would be helpful.

dbluhm commented 1 year ago

I think the only time this kind of error can occur is when there are multiple of the same key in the DID Document but that seems unlikely to be the case here. Do you have access to the DID Document sent in the connection request ACA-Py failed on?

WadeBarnes commented 1 year ago

@dbluhm, here are some debug logs matching the initial error I reported.

aca-py-debug.log

Additional context from @marcos-carretero:

WadeBarnes commented 1 year ago

@marcos-carretero, Do you have access to this info:

I think the only time this kind of error can occur is when there are multiple of the same key in the DID Document but that seems unlikely to be the case here. Do you have access to the DID Document sent in the connection request ACA-Py failed on?

marcos-carretero commented 1 year ago

@marcos-carretero, Do you have access to this info:

I think the only time this kind of error can occur is when there are multiple of the same key in the DID Document but that seems unlikely to be the case here. Do you have access to the DID Document sent in the connection request ACA-Py failed on?

I don't think I have access to the connection request details between the wallet and ACA-Py. I consume the abstracted documents/objects from the ACA-Py Admin APIs and webhooks

marcos-carretero commented 1 year ago

I can try a different build of the BC Wallet?

swcurran commented 1 year ago

@cvarjao , @jleach @nodlesh — can one of you provide an example of what a DID and DIDDoc that BC Wallet sends to IDIM looks like? Presumably the same for all connections. We just need an example of what that looks like.

dbluhm commented 1 year ago

I think I was able to scrape the value I needed from the logs @nodlesh / @WadeBarnes provided. I'm getting some unit tests put together for these values. The DIDDoc class in ACA-Py does a real number on things before storing the value as well. I'll have another set of tests for values "canonized" by the DIDDoc class.

dbluhm commented 1 year ago

I believe I've started to narrow down the cause. It looks like we were previously storing the routing keys as if they were recipient keys in our key to DID mapping. So if we get a connection request from two different agents using the same mediator, we'll end up with duplicate records. We never actually got any messages with the routing key as the recipient though (because that just doesn't happen) so we never saw the error before but when I added idempotency rules to the method that stores those keys, we're now running into it.

I'm evaluating workarounds. We'll have some bad records in the wallet to deal with but we should be able to adjust behavior so it doesn't attempt to write routing keys any more as well.