Failing to deserialize DIDDocumentRoot error when using the Indicio mediator and 0.10.2 ACA-Py instance

esune commented 1 year ago

[Updated this description to clarify the issue...]

We were testing a deployment of 0.10.2, and were getting errors when connections were established using the Indicio Public Mediator. When we switched to use the BC Gov Mediator instance, things worked again.

This was observed using ACA-Py 0.10.2rc0 in a Traction multi-tenant instance, targeting a BC Wallet emulator - @cvarjao please add context if you have more information.

c.c.: @loneil who has been looking into this, @dbluhm based on expressed interest from today's ACA-Pug meeting

  2023-09-18 22:34:53,164 aries_askar.native.aries_askar.backend.db_utils INFO src/backend/db_utils.rs:168 | Dropped pool connection
2023-09-18 22:34:53,166 aries_cloudagent.core.dispatcher ERROR Handler error: BaseConnectionManager.get_connection_targets
Traceback (most recent call last):
File "/home/aries/.venv/lib/python3.9/site-packages/pydid/validation.py", line 13, in wrap_validation_error
yield
File "/home/aries/.venv/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: 4 validation errors for ParsingModel[DIDDocumentRoot]
__root__ -> service -> 0 -> serviceEndpoint
didcomm:transport/queue is not a valid absolute or relative DID URL (type=value_error.invaliddidurl)
__root__ -> service -> 0 -> serviceEndpoint
invalid or missing URL scheme (type=value_error.url.scheme)
__root__ -> service -> 0 -> serviceEndpoint
unexpected value; permitted: '' (type=value_error.const; given=didcomm:transport/queue; permitted=('',))
__root__ -> service -> 0 -> serviceEndpoint
value is not a valid list (type=type_error.list)
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 "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 609, in get_connection_targets
targets = await self.fetch_connection_targets(connection)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 570, in fetch_connection_targets
return await self.resolve_connection_targets(
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 362, in resolve_connection_targets
doc, didcomm_services = await self.resolve_didcomm_services(did)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 269, in resolve_didcomm_services
doc: ResolvedDocument = pydid.deserialize_document(doc_dict, strict=True)
File "/home/aries/.venv/lib/python3.9/site-packages/pydid/__init__.py", line 63, in deserialize_document
return cls.deserialize(value)
File "/home/aries/.venv/lib/python3.9/site-packages/pydid/doc/doc.py", line 171, in deserialize
DIDDocumentRoot.deserialize(value)
File "/home/aries/.venv/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 "/home/aries/.venv/lib/python3.9/site-packages/pydid/validation.py", line 15, in wrap_validation_error
raise error_to_raise(
ValueError: Failed to deserialize DIDDocumentRoot:
4 validation errors for ParsingModel[DIDDocumentRoot]
__root__ -> service -> 0 -> serviceEndpoint
didcomm:transport/queue is not a valid absolute or relative DID URL (type=value_error.invaliddidurl)
__root__ -> service -> 0 -> serviceEndpoint
invalid or missing URL scheme (type=value_error.url.scheme)
__root__ -> service -> 0 -> serviceEndpoint
unexpected value; permitted: '' (type=value_error.const; given=didcomm:transport/queue; permitted=('',))
__root__ -> service -> 0 -> serviceEndpoint
value is not a valid list (type=type_error.list)
2023-09-18 22:34:53,166 traction_plugins.basicmessage_storage.v1_0.routes ERROR Failed to deserialize DIDDocumentRoot:
4 validation errors for ParsingModel[DIDDocumentRoot]
__root__ -> service -> 0 -> serviceEndpoint
didcomm:transport/queue is not a valid absolute or relative DID URL (type=value_error.invaliddidurl)
__root__ -> service -> 0 -> serviceEndpoint
invalid or missing URL scheme (type=value_error.url.scheme)
__root__ -> service -> 0 -> serviceEndpoint
unexpected value; permitted: '' (type=value_error.const; given=didcomm:transport/queue; permitted=('',))
__root__ -> service -> 0 -> serviceEndpoint
value is not a valid list (type=type_error.list)
2023-09-18 22:34:53,167 aries_cloudagent.core.dispatcher ERROR Handler error: plugin_connections_send_message
Traceback (most recent call last):
File "/home/aries/.venv/lib/python3.9/site-packages/pydid/validation.py", line 13, in wrap_validation_error
yield
File "/home/aries/.venv/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: 4 validation errors for ParsingModel[DIDDocumentRoot]
__root__ -> service -> 0 -> serviceEndpoint
didcomm:transport/queue is not a valid absolute or relative DID URL (type=value_error.invaliddidurl)
__root__ -> service -> 0 -> serviceEndpoint
invalid or missing URL scheme (type=value_error.url.scheme)
__root__ -> service -> 0 -> serviceEndpoint
unexpected value; permitted: '' (type=value_error.const; given=didcomm:transport/queue; permitted=('',))
__root__ -> service -> 0 -> serviceEndpoint
value is not a valid list (type=type_error.list)
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 "/home/aries/traction_plugins/basicmessage_storage/v1_0/routes.py", line 47, in wrapper
raise err
File "/home/aries/traction_plugins/basicmessage_storage/v1_0/routes.py", line 37, in wrapper
ret = await func(request)
File "/home/aries/traction_plugins/basicmessage_storage/v1_0/routes.py", line 96, in plugin_connections_send_message
response = await connections_send_message(request)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/protocols/basicmessage/v1_0/routes.py", line 63, in connections_send_message
await outbound_handler(msg, connection_id=connection_id)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/messaging/responder.py", line 101, in send
return await self.send_outbound(
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/admin/server.py", line 147, in send_outbound
return await self._send(profile, message)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/core/conductor.py", line 637, in outbound_message_router
status: OutboundSendStatus = await self._outbound_message_router(
File "/home/aries/.venv/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 "/home/aries/.venv/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 "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 609, in get_connection_targets
targets = await self.fetch_connection_targets(connection)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 570, in fetch_connection_targets
return await self.resolve_connection_targets(
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 362, in resolve_connection_targets
doc, didcomm_services = await self.resolve_didcomm_services(did)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 269, in resolve_didcomm_services
doc: ResolvedDocument = pydid.deserialize_document(doc_dict, strict=True)
File "/home/aries/.venv/lib/python3.9/site-packages/pydid/__init__.py", line 63, in deserialize_document
return cls.deserialize(value)
File "/home/aries/.venv/lib/python3.9/site-packages/pydid/doc/doc.py", line 171, in deserialize
DIDDocumentRoot.deserialize(value)
File "/home/aries/.venv/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 "/home/aries/.venv/lib/python3.9/site-packages/pydid/validation.py", line 15, in wrap_validation_error
raise error_to_raise(
ValueError: Failed to deserialize DIDDocumentRoot:
4 validation errors for ParsingModel[DIDDocumentRoot]
__root__ -> service -> 0 -> serviceEndpoint
didcomm:transport/queue is not a valid absolute or relative DID URL (type=value_error.invaliddidurl)
__root__ -> service -> 0 -> serviceEndpoint
invalid or missing URL scheme (type=value_error.url.scheme)
__root__ -> service -> 0 -> serviceEndpoint
unexpected value; permitted: '' (type=value_error.const; given=didcomm:transport/queue; permitted=('',))
__root__ -> service -> 0 -> serviceEndpoint
value is not a valid list (type=type_error.list)
2023-09-18 22:34:53,167 aries_cloudagent.admin.server ERROR Handler error with exception: Failed to deserialize DIDDocumentRoot:
4 validation errors for ParsingModel[DIDDocumentRoot]
__root__ -> service -> 0 -> serviceEndpoint
didcomm:transport/queue is not a valid absolute or relative DID URL (type=value_error.invaliddidurl)
__root__ -> service -> 0 -> serviceEndpoint
invalid or missing URL scheme (type=value_error.url.scheme)
__root__ -> service -> 0 -> serviceEndpoint
unexpected value; permitted: '' (type=value_error.const; given=didcomm:transport/queue; permitted=('',))
__root__ -> service -> 0 -> serviceEndpoint
value is not a valid list (type=type_error.list)
=================
Traceback (most recent call last):
File "/home/aries/.venv/lib/python3.9/site-packages/pydid/validation.py", line 13, in wrap_validation_error
yield
File "/home/aries/.venv/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: 4 validation errors for ParsingModel[DIDDocumentRoot]
__root__ -> service -> 0 -> serviceEndpoint
didcomm:transport/queue is not a valid absolute or relative DID URL (type=value_error.invaliddidurl)
__root__ -> service -> 0 -> serviceEndpoint
invalid or missing URL scheme (type=value_error.url.scheme)
__root__ -> service -> 0 -> serviceEndpoint
unexpected value; permitted: '' (type=value_error.const; given=didcomm:transport/queue; permitted=('',))
__root__ -> service -> 0 -> serviceEndpoint
value is not a valid list (type=type_error.list)
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/admin/server.py", line 181, in ready_middleware
return await handler(request)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/admin/server.py", line 218, in debug_middleware
return await handler(request)
File "/home/aries/.venv/lib/python3.9/site-packages/aiohttp_apispec/middlewares.py", line 45, in validation_middleware
return await handler(request)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/admin/server.py", line 338, in check_token
return await handler(request)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/admin/server.py", line 387, in check_multitenant_authorization
return await handler(request)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/admin/server.py", line 450, in setup_context
return await 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 258, in __step
result = coro.throw(exc)
File "/home/aries/traction_plugins/basicmessage_storage/v1_0/routes.py", line 47, in wrapper
raise err
File "/home/aries/traction_plugins/basicmessage_storage/v1_0/routes.py", line 37, in wrapper
ret = await func(request)
File "/home/aries/traction_plugins/basicmessage_storage/v1_0/routes.py", line 96, in plugin_connections_send_message
response = await connections_send_message(request)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/protocols/basicmessage/v1_0/routes.py", line 63, in connections_send_message
await outbound_handler(msg, connection_id=connection_id)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/messaging/responder.py", line 101, in send
return await self.send_outbound(
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/admin/server.py", line 147, in send_outbound
return await self._send(profile, message)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/core/conductor.py", line 637, in outbound_message_router
status: OutboundSendStatus = await self._outbound_message_router(
File "/home/aries/.venv/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 "/home/aries/.venv/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 "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 609, in get_connection_targets
targets = await self.fetch_connection_targets(connection)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 570, in fetch_connection_targets
return await self.resolve_connection_targets(
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 362, in resolve_connection_targets
doc, didcomm_services = await self.resolve_didcomm_services(did)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 269, in resolve_didcomm_services
doc: ResolvedDocument = pydid.deserialize_document(doc_dict, strict=True)
File "/home/aries/.venv/lib/python3.9/site-packages/pydid/__init__.py", line 63, in deserialize_document
return cls.deserialize(value)
File "/home/aries/.venv/lib/python3.9/site-packages/pydid/doc/doc.py", line 171, in deserialize
DIDDocumentRoot.deserialize(value)
File "/home/aries/.venv/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 "/home/aries/.venv/lib/python3.9/site-packages/pydid/validation.py", line 15, in wrap_validation_error
raise error_to_raise(
ValueError: Failed to deserialize DIDDocumentRoot:
4 validation errors for ParsingModel[DIDDocumentRoot]
__root__ -> service -> 0 -> serviceEndpoint
didcomm:transport/queue is not a valid absolute or relative DID URL (type=value_error.invaliddidurl)
__root__ -> service -> 0 -> serviceEndpoint
invalid or missing URL scheme (type=value_error.url.scheme)
__root__ -> service -> 0 -> serviceEndpoint
unexpected value; permitted: '' (type=value_error.const; given=didcomm:transport/queue; permitted=('',))
__root__ -> service -> 0 -> serviceEndpoint
value is not a valid list (type=type_error.list)
2023-09-18 22:34:53,168 aiohttp.server ERROR Error handling request
Traceback (most recent call last):
File "/home/aries/.venv/lib/python3.9/site-packages/pydid/validation.py", line 13, in wrap_validation_error
yield
File "/home/aries/.venv/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: 4 validation errors for ParsingModel[DIDDocumentRoot]
__root__ -> service -> 0 -> serviceEndpoint
didcomm:transport/queue is not a valid absolute or relative DID URL (type=value_error.invaliddidurl)
__root__ -> service -> 0 -> serviceEndpoint
invalid or missing URL scheme (type=value_error.url.scheme)
__root__ -> service -> 0 -> serviceEndpoint
unexpected value; permitted: '' (type=value_error.const; given=didcomm:transport/queue; permitted=('',))
__root__ -> service -> 0 -> serviceEndpoint
value is not a valid list (type=type_error.list)
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/home/aries/.venv/lib/python3.9/site-packages/aiohttp/web_protocol.py", line 433, in _handle_request
resp = await request_handler(request)
File "/home/aries/.venv/lib/python3.9/site-packages/aiohttp/web_app.py", line 504, in _handle
resp = await handler(request)
File "/home/aries/.venv/lib/python3.9/site-packages/aiohttp/web_middlewares.py", line 117, in impl
return await handler(request)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/admin/server.py", line 181, in ready_middleware
return await handler(request)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/admin/server.py", line 218, in debug_middleware
return await handler(request)
File "/home/aries/.venv/lib/python3.9/site-packages/aiohttp_apispec/middlewares.py", line 45, in validation_middleware
return await handler(request)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/admin/server.py", line 338, in check_token
return await handler(request)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/admin/server.py", line 387, in check_multitenant_authorization
return await handler(request)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/admin/server.py", line 450, in setup_context
return await 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 258, in __step
result = coro.throw(exc)
File "/home/aries/traction_plugins/basicmessage_storage/v1_0/routes.py", line 47, in wrapper
raise err
File "/home/aries/traction_plugins/basicmessage_storage/v1_0/routes.py", line 37, in wrapper
ret = await func(request)
File "/home/aries/traction_plugins/basicmessage_storage/v1_0/routes.py", line 96, in plugin_connections_send_message
response = await connections_send_message(request)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/protocols/basicmessage/v1_0/routes.py", line 63, in connections_send_message
await outbound_handler(msg, connection_id=connection_id)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/messaging/responder.py", line 101, in send
return await self.send_outbound(
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/admin/server.py", line 147, in send_outbound
return await self._send(profile, message)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/core/conductor.py", line 637, in outbound_message_router
status: OutboundSendStatus = await self._outbound_message_router(
File "/home/aries/.venv/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 "/home/aries/.venv/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 "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 609, in get_connection_targets
targets = await self.fetch_connection_targets(connection)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 570, in fetch_connection_targets
return await self.resolve_connection_targets(
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 362, in resolve_connection_targets
doc, didcomm_services = await self.resolve_didcomm_services(did)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/connections/base_manager.py", line 269, in resolve_didcomm_services
doc: ResolvedDocument = pydid.deserialize_document(doc_dict, strict=True)
File "/home/aries/.venv/lib/python3.9/site-packages/pydid/__init__.py", line 63, in deserialize_document
return cls.deserialize(value)
File "/home/aries/.venv/lib/python3.9/site-packages/pydid/doc/doc.py", line 171, in deserialize
DIDDocumentRoot.deserialize(value)
File "/home/aries/.venv/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 "/home/aries/.venv/lib/python3.9/site-packages/pydid/validation.py", line 15, in wrap_validation_error
raise error_to_raise(
ValueError: Failed to deserialize DIDDocumentRoot:
4 validation errors for ParsingModel[DIDDocumentRoot]
__root__ -> service -> 0 -> serviceEndpoint
didcomm:transport/queue is not a valid absolute or relative DID URL (type=value_error.invaliddidurl)
__root__ -> service -> 0 -> serviceEndpoint
invalid or missing URL scheme (type=value_error.url.scheme)
__root__ -> service -> 0 -> serviceEndpoint
unexpected value; permitted: '' (type=value_error.const; given=didcomm:transport/queue; permitted=('',))
__root__ -> service -> 0 -> serviceEndpoint
value is not a valid list (type=type_error.list)
2023-09-18 22:34:53,168 aiohttp.access INFO 10.97.27.173 [18/Sep/2023:22:34:53 +0000] "POST /connections/b5145176-2b6a-4c76-9042-56c84b67e894/send-message HTTP/1.0" 500 414 "https://traction-tenant-ui-dev.apps.silver.devops.gov.bc.ca/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36"

loneil commented 1 year ago

Can reproduce on the existing problematic connections by just calling /connections/{conn_id}/endpoints Same 500 and pydid error occurs. I don't know exactly what was set as the service endpoint while receiving the invitation in Clecio's test. But he said he was using the Indicio public mediator and then switching to use https://aries-mediator-agent.vonx.io works.

Not sure if possible there was just something formatted bad supplied as the service endpoint in the error case? Something that is allowed in but blows up getting out? I tried a bunch of random things in there doing manual recieve-invitations but can't find something specific.

Looks like this code here only catches ResolverError but something else can bubble up and result in the unhandled maybe?

        try:
            doc_dict: dict = await resolver.resolve(self._profile, did, service_accept)
            doc: ResolvedDocument = pydid.deserialize_document(doc_dict, strict=True)
        except ResolverError as error:
            raise BaseConnectionManagerError(
                "Failed to resolve public DID in invitation"
            ) from error

(resolve_didcomm_services in base_manager.py)

dbluhm commented 1 year ago

To clarify, when you say switching mediators, do you mean that you're establishing a new connection through a different mediator? That seems to be the case based on @loneil 's comment but just to wanted to verify my understanding. What were the did documents received by ACA-Py during connection for both scenarios?

dbluhm commented 1 year ago

If you want to dump the logs, I can also parse that out myself, if that's helpful!

swcurran commented 1 year ago

@dbluhm -- updated the description. We were not switching mediators for existing connections. @cvarjao had been running a script that used the Indicio Mediator and the connections were not usuable, with the error above. After changing the script to use the BC Gov mediator, things started to work again. Does that help at all?

cvarjao commented 1 year ago

1) I've had a fresh install of bifold wallet app with indício mediator. I was not trying to change the mediator midway. It is just the mediator I had setup for using for testing bifold. I did another fresh install with another mediator.

2) my script just interact with traction/aca-py REST API to create a new connection, issue credential, and send a proof request.

loneil commented 1 year ago

If someone knows what the bifold wallet app with indício mediator would be putting as the Service Endpoint (when receiving the invitation) that would be helpful I think. Or know how to check what that would be in an existing connection Since the connections made in that way are breaking even when trying to call /connections/{conn_id}/endpoints due to unhandled pydid validator exception.

swcurran commented 1 year ago

@cvarjao -- could you please rerun the failing test and get a log on your side, and after you run the test, indicate the time so that an ACA-Py instance log can be extracted for the time in question.

cvarjao commented 1 year ago

I don't know if we should investigate this issue more. But it looks like nothing really works with Indicio mediator. I've tried BC Showcase, and Animo Demo, neither of them worked. I think Animo is AFJ-based, BC Showcase is aca-py/traction based.

swcurran commented 1 year ago

@dbluhm — can you respond to @cvarjao note? That seems very odd that the Indicio Mediator is not working.

@cvarjao to confirm, what you did was:

Create a script that uses Bifold on an Android emulator that runs a script to connect to a Mediator and then creates a connection to the BC Showcase to receive a credential.
Running the script to connect to the Indicio Mediator (works), and then to the BC Showcase (works - right?) but then the BC Showcase cannot message back. Perhaps it stops in the middle of establishing the connection?
Running the script to connect to the BC Gov Mediator (works), and then to the BC Showcase (works) and the BC Showcase can message back, successfully running the issue credential protocol.

@loneil is using the same connections that @cvarjao tried to establish to reproduce the error with /connections/{conn_id}. So the connection was at least partially created, but the DIDDoc is unreadable by pydid.

@dbluhm — does that help?

dbluhm commented 1 year ago

Would still appreciate more logs from these interactions but in the absence of more details and with evidence of things working well with other setups, we're probably okay to proceed with a release.

cvarjao commented 1 year ago

Here is a log from the wallet side.

esune commented 1 year ago

Would still appreciate more logs from these interactions but in the absence of more details and with evidence of things working well with other setups, we're probably okay to proceed with a release.

This is the acapy log (keys have been redacted).

dbluhm commented 1 year ago

DID Document received by ACA-Py in Connection Request:

{
  "@type": "https://didcomm.org/connections/1.0/request",
  "@id": "36ebc380-c39a-4e46-bf49-029d6ca0053c",
  "label": "My Wallet - 4985",
  "connection": {
    "DID": "SBV4Dq9TNMZ7ubdjAs3WHK",
    "DIDDoc": {
      "@context": "https://w3id.org/did/v1",
      "publicKey": [
        {
          "id": "SBV4Dq9TNMZ7ubdjAs3WHK#1",
          "controller": "SBV4Dq9TNMZ7ubdjAs3WHK",
          "type": "Ed25519VerificationKey2018",
          "publicKeyBase58": "Ej1mdRCVf5WBpkZSA7W6jgnY5tS2xe6KU6FyUnEQ2Abf"
        }
      ],
      "service": [
        {
          "id": "SBV4Dq9TNMZ7ubdjAs3WHK#IndyAgentService",
          "serviceEndpoint": "didcomm:transport/queue",
          "type": "IndyAgent",
          "priority": 0,
          "recipientKeys": [
            "Ej1mdRCVf5WBpkZSA7W6jgnY5tS2xe6KU6FyUnEQ2Abf"
          ],
          "routingKeys": []
        }
      ],
      "authentication": [
        {
          "publicKey": "SBV4Dq9TNMZ7ubdjAs3WHK#1",
          "type": "Ed25519SignatureAuthentication2018"
        }
      ],
      "id": "SBV4Dq9TNMZ7ubdjAs3WHK"
    }
  },
  "~thread": {
    "thid": "36ebc380-c39a-4e46-bf49-029d6ca0053c",
    "pthid": "434c562c-b483-4cc3-ba34-70fb733f0f9b"
  },
  "~transport": {
    "return_route": "all"
  }
}

The serviceEndpoint is not consistent with one that has correctly established mediation. The didcomm:transport/queue value in the service is not one currently supported by pydid; this should be corrected. I think this actually is enough of an issue to warrant one final commit before a 0.10.2 release, one that locks to a version of pydid that does support this value. cc @swcurran

On the wallet side, the wallet successfully completed a connection with the Indicio Public Mediator but on opening a WS connection and sending a mediation request, no response was received from the mediator. Unclear from the logs how long of a timeout this was after. I'm checking to see if we have any logs for the exchange on the mediator end. The Indicio Public Mediator is not running 0.10.2-rc0 though so any issues there are not a result of any recent changes to ACA-Py.

swcurran commented 1 year ago

Thanks @dbluhm — I’ll hold on the release.

dbluhm commented 1 year ago

I've got the changes in for pydid: https://github.com/Indicio-tech/pydid/pull/75

I'll get this out into a release shortly and then prepare a PR for ACA-Py.

loneil commented 1 year ago

Regardless of finding the underlying issue, I wonder if it's worth tracking (maybe lower priority for later?) that we probably shouldn't be getting a 500 error with the unhandled pydid validation error if calling /connections/{conn_id}/endpoints?

If I'm not misunderstanding, the connection as far as the inviter agent is concerned, was successful, it shows completed and active to the inviter:

But I can't check endpoints on this active completed connection without a 500 error due to an unhandled exception

results in the already-discussed unexpected value; permitted: '' (type=value_error.const; given=didcomm:transport/queue; permitted=('',)) error case.

Feels like we should be able to at least check and see what the service endpoint is on a completed connection no matter what? Even if we're going to fix the underlying pydid validation error for this specific case the error handling seems like an issue?

Or is it an issue here that the connection appears successful and should not be in this case?

Let me know if I'm not mistaken and I could write up that issue.

dbluhm commented 1 year ago

The error on /connections/{connid}/endpoints is indicative of the deeper problem. The inviter will not be able to send a message back to the invitee since it's unable to determine an endpoint by parsing it from the DID Doc. The only reason the inviter can reach an active connection state is because the invitee is the one driving the exchange and the inviter is just responding, first to a connection request, and then to a trust ping. Both the connection response and the trust ping response are sent as "replies" where the message in the active inbound HTTP request is directly responded to in the HTTP response.

swcurran commented 1 year ago

@dbluhm — I see that there is a fix in the pydid library that you are proposing. Could you summarize what occured that triggered the issue, what the fix does, and what is needed in 0.10.2 specifically, and ACA-Py generally to resolve the issue? That would help me understand the issue.

dbluhm commented 1 year ago

The trigger for this issue is that 0.10.1 normalized the handling of DIDs by always "resolving" the recipient DID on sending an outbound message. After resolution, the document is parsed using PyDID to extract DIDComm Service endpoint information. PyDID's serviceEndpoint validation was narrower than appropriate which caused it to reject the didcomm:transport/queue value in the serviceEndpoint. The fix to PyDID ensures that as long as the serviceEndpoint isn't obviously invalid (i.e. being a boolean instead of a string), it will not be overly prescriptive of the expected values. This will enable us to parse out DIDComm service endpoint info, see the didcomm:transport/queue, and treat it the same way as before 0.10.1 (which I believe will be to determine that there's no appropriate outbound handler for the didcomm: "scheme" and queue it in the undelivered queue if configured or log that there was no valid service endpoint and drop the message).

Regardless of this fix, there still would have been issues in the scenario that brought the didcomm:transport/queue issue to our attention. The inviter still would have been unable to send a message to the invitee. But it will be because there was no valid transport rather than because validation of the doc failed, which, in turn, was caused by the wallet never actually properly establishing mediation with the Indicio Mediator before connecting to our inviter ACA-Py instance.

The change needed in 0.10.2 is to pull in the updated PyDID release (working on preparing this now).

Hope that helps clear things up!

swcurran commented 1 year ago

Thanks! Awesome. So we get a double fix for this problem. We do some cleanup in pydid/ACA-Py, but also discovered a problem in Bifold, per “But it will be because there was no valid transport rather than because validation of the doc failed, which, in turn, was caused by the wallet never actually properly establishing mediation with the Indicio Mediator before connecting to our inviter ACA-Py instance.”

@cvarjao — could you please have the Bifold community address this second issue?

dbluhm commented 1 year ago

 DEBUG  DEBUG: Pack outbound message https://didcomm.org/coordinate-mediation/1.0/mediate-request
 DEBUG  DEBUG: Sending outbound message to endpoint 'wss://public.mediator.indiciotech.io' over WebSocket transport. {
  "payload": {
    "protected": "eyJlbmMiOiJ4Y2hhY2hhMjBwb2x5MTMwNV9pZXRmIiwidHlwIjoiSldNLzEuMCIsImFsZyI6IkF1dGhjcnlwdCIsInJlY2lwaWVudHMiOlt7ImVuY3J5cHRlZF9rZXkiOiJSX2p3RzB4MkRHbGVCamZnUVhWZXdTNTZZRnlmSXM0dGlxbE53dm93eGVrU3ZCWHNYT0xTS0ZjY1NFaVowQ3AtIiwiaGVhZGVyIjp7ImtpZCI6InZEYWVpMndXdnBzYldLQ3VoQmNtOHkyNGJnUFRrcFNLREtVRUVYV2hGVHciLCJzZW5kZXIiOiJpM1B4NG9QRGVHa21hcDdPTmFGVEMtODJKUHF3NWQzeDlPYnlTZUhVYUZ3M0tGVGZVZ0ZhOWRhVk5VcnpLWGs0dUE3Q1dybEZNMXNyaTBOa2RGSFhHeElzSTBnbE9WX0pHa1lNTjJrbEFyQlJFcFI3Qzl6clo4RFBGNDQiLCJpdiI6IkZFOUNVaFdmOEJscFAzR1A1WTctTlVXakk1UDlPenRIIn19XX0",
    "ciphertext": "rofYv0HT2caa0zIY7atKPb7CvHSBIs9IS3VcF_b8EuWlWxji9oAhHWpTw1TNiA3xGHgNqe74gLKl_qEXsQ97jkcoL3zaqjGvKjmpTsPRyfIKof8WncR6QAiXfwzZKG5n_oDPyBkPu7593ijNrcT2kW_4o3kSwQuXgpceLUA510hwuvCvj1o16cnUh4DWKziH6xyAhrzyQ69oBlewtJ7CFlQ1VJLbt5wvm9otheeoxSfV",
    "iv": "B3amDEjigeirsSmt",
    "tag": "TMuCR5-cnd3zqCk_RMW9TQ"
  }
}
 DEBUG  DEBUG: Connecting to WebSocket wss://public.mediator.indiciotech.io
 DEBUG  DEBUG: No response received.
 DEBUG  DEBUG: Successfully connected to WebSocket wss://public.mediator.indiciotech.io
 DEBUG  DEBUG: Error while connecting to WebSocket wss://public.mediator.indiciotech.io {
  "error": {
    "isTrusted": false,
    "message": null
  }
}
 DEBUG  DEBUG: WebSocket closing to wss://public.mediator.indiciotech.io
 WARN  WARN: The '@aries-framework/askar' module is experimental and could have unexpected breaking changes. When using this module, make sure to use strict versions for all @aries-framework packages.
 WARN  WARN: The '@aries-framework/anoncreds-rs' module is experimental and could have unexpected breaking changes. When using this module, make sure to use strict versions for all @aries-framework packages.
 WARN  WARN: The '@aries-framework/indy-vdr' module is experimental and could have unexpected breaking changes. When using this module, make sure to use strict versions for all @aries-framework packages.
 INFO  INFO: Creating agent with config {
  "agentConfig": {
    "label": "My Wallet - 4985",
    "walletConfig": {
      "id": "walletId",
      "key": "[*****]",
      "storage": {}
    },
    "logger": 1,
    "mediatorPickupStrategy": "Implicit",
    "autoUpdateStorageOnStartup": true,
    "autoAcceptConnections": true,
    "agentDependencies": true
  }
}

Relevant logs from wallet; when mediation establishment failed, it proceeded to configuration instead of stopping. I'm not sure this is really a misbehavior of bifold or not but I'll leave that up to the bifold developers. Meanwhile, I'll ping Kim about why it might have gotten this back from our mediator:

 DEBUG  DEBUG: Error while connecting to WebSocket wss://public.mediator.indiciotech.io {
  "error": {
    "isTrusted": false,
    "message": null
  }
}

cvarjao commented 1 year ago

AFJ is the component handling mediator and things like that. I will see if we can reproduce in vanilla Node/AFJ environment. We have also found issues related to running on the device itself, as it actually doesn't use the NodeJS engine, but actually Hermes.

swcurran commented 1 year ago

The issuer part was fixed in 0.10.3. The underlying issue requires a fix in AFJ. Closing.

hyperledger / aries-cloudagent-python

Failing to deserialize DIDDocumentRoot error when using the Indicio mediator and 0.10.2 ACA-Py instance #2497