Closed esune closed 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)
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?
If you want to dump the logs, I can also parse that out myself, if that's helpful!
@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?
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.
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.
@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.
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.
@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:
@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?
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.
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).
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.
Thanks @dbluhm — I’ll hold on the release.
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.
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.
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.
@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.
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!
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?
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
}
}
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.
The issuer part was fixed in 0.10.3. The underlying issue requires a fix in AFJ. Closing.
[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