search

openwallet-foundation / acapy

ACA-Py is a foundation for building decentralized identity applications and services running in non-mobile environments.
https://aca-py.org
Apache License 2.0
420 stars 513 forks source link

Issue with public invitations in ACA-Py version 0.9.0 #2406

Closed WadeBarnes closed 1 year ago

WadeBarnes commented 1 year ago

We've run into an issue after upgrading the BC Gov IDIM dev issuer agent to ACA-Py version 0.9.0.

Following an upgrade from 0.8.1 to 0.9.0 the agent does not respond to requests from the BC Wallet when trying to acquire the BC Person credential after tapping on the "Get your Person Credential" button. The IDIM controller is expecting a call from the agent when it receives messages from the BC Wallet, this call is never received.

The communications from the BC Wallet are completely ignored, to the point where there are no logs indicating what is happening. When the logging level is set to debug you can see the agent receives a message and then does nothing about it with no details that help with troubleshooting. If the logging level is set any higher than debug there is no indication the agent ever received a message from the BC Wallet.

The log message:

2023-08-08 22:04:08,481 aries_cloudagent.transport.pack_format DEBUG Expanded message: {'@type': 'https://didcomm.org/connections/1.0/request', '@id': '9d7ae47d-73a4-4660-bd41-8b357efba72e', 'label': 'My Wallet - 0986', 'connection': {'DID': 'LaMFesAuc2nnrnm24oAvv3', 'DIDDoc': {'@context': 'https://w3id.org/did/v1', 'publicKey': [{'id': 'LaMFesAuc2nnrnm24oAvv3#1', 'controller': 'LaMFesAuc2nnrnm24oAvv3', 'type': 'Ed25519VerificationKey2018', 'publicKeyBase58': 'BfodJXHLmG55oHWQyDtKvuod62HsDX7wnp2GecRWy8FN'}], 'service': [{'id': 'LaMFesAuc2nnrnm24oAvv3#IndyAgentService', 'serviceEndpoint': 'https://aries-mediator-agent.vonx.io', 'type': 'IndyAgent', 'priority': 0, 'recipientKeys': ['BfodJXHLmG55oHWQyDtKvuod62HsDX7wnp2GecRWy8FN'], 'routingKeys': ['cK7fwfjpakMuv8QKVv2y6qouZddVw4TxZNQPUs2fFTd']}], 'authentication': [{'publicKey': 'LaMFesAuc2nnrnm24oAvv3#1', 'type': 'Ed25519SignatureAuthentication2018'}], 'id': 'LaMFesAuc2nnrnm24oAvv3'}}, '~thread': {'thid': '9d7ae47d-73a4-4660-bd41-8b357efba72e', 'pthid': 'd475c7f4-14c3-477d-b653-cf903842f4bc'}}

...

2023-08-08 22:04:08,584 aries_cloudagent.messaging.base_handler DEBUG ConnectionRequestHandler called with context <RequestContext(_connection_ready=False, _connection_record=<ConnRecord(_id='78b521d6-0991-4c13-b9d4-d47d1e6289e3', _last_state='invitation', _new_with_id=False, state='invitation', created_at='2022-07-07T22:56:59.083910Z', updated_at='2023-08-01T14:46:23.852676Z', my_did=None, their_did=None, their_label=None, their_role='invitee', invitation_key='2eHpQFonMEhmzoaeEmALKWqdqyRWYfA6LQyjJJtgb2WT', invitation_msg_id=None, request_id=None, error_msg=None, inbound_connection_id=None, routing_state='none', accept='manual', invitation_mode='multi', alias='wallet-iddev-public', their_public_did=None, connection_protocol='connections/1.0')>, _context=<aries_cloudagent.config.injection_context.InjectionContext object at 0x7fb4ec346be0>, _message=<ConnectionRequest(_message_id='9d7ae47d-73a4-4660-bd41-8b357efba72e', _message_new_id=False, _message_decorators=<DecoratorSet{~thread: <ThreadDecorator(_thid='9d7ae47d-73a4-4660-bd41-8b357efba72e', _pthid='d475c7f4-14c3-477d-b653-cf903842f4bc', _sender_order=None, _received_orders=None)>}>, _message_type='connections/1.0/request', connection=<ConnectionDetail(_did='LaMFesAuc2nnrnm24oAvv3', _did_doc=<DIDDoc did=LaMFesAuc2nnrnm24oAvv3>)>, label='My Wallet - 0986', image_url=None)>, _message_receipt=<MessageReceipt(_connection_id=None, _direct_response_mode=None, _in_time='2023-08-08T22:04:08.425342Z', _raw_message='{"@type":"https://didcomm.org/connections/1.0/request","@id":"9d7ae47d-73a4-4660-bd41-8b357efba72e","label":"My Wallet - 0986","connection":{"DID":"LaMFesAuc2nnrnm24oAvv3","DIDDoc":{"@context":"https://w3id.org/did/v1","publicKey":[{"id":"LaMFesAuc2nnrnm24oAvv3#1","controller":"LaMFesAuc2nnrnm24oAvv3","type":"Ed25519VerificationKey2018","publicKeyBase58":"BfodJXHLmG55oHWQyDtKvuod62HsDX7wnp2GecRWy8FN"}],"service":[{"id":"LaMFesAuc2nnrnm24oAvv3#IndyAgentService","serviceEndpoint":"https://aries-mediator-agent.vonx.io","type":"IndyAgent","priority":0,"recipientKeys":["BfodJXHLmG55oHWQyDtKvuod62HsDX7wnp2GecRWy8FN"],"routingKeys":["cK7fwfjpakMuv8QKVv2y6qouZddVw4TxZNQPUs2fFTd"]}],"authentication":[{"publicKey":"LaMFesAuc2nnrnm24oAvv3#1","type":"Ed25519SignatureAuthentication2018"}],"id":"LaMFesAuc2nnrnm24oAvv3"}},"~thread":{"thid":"9d7ae47d-73a4-4660-bd41-8b357efba72e","pthid":"d475c7f4-14c3-477d-b653-cf903842f4bc"}}', _recipient_verkey='2eHpQFonMEhmzoaeEmALKWqdqyRWYfA6LQyjJJtgb2WT', _recipient_did=None, _recipient_did_public=None, _sender_did=None, _sender_verkey='BfodJXHLmG55oHWQyDtKvuod62HsDX7wnp2GecRWy8FN', _thread_id='9d7ae47d-73a4-4660-bd41-8b357efba72e', _parent_thread_id='d475c7f4-14c3-477d-b653-cf903842f4bc')>, _profile=<AskarProfile(backend=askar, name=agent_idim_wallet)>)>

Reviewing the breaking changes included in 0.9.0 we investigated (revisited) https://github.com/hyperledger/aries-cloudagent-python/pull/2034 and set ACAPY_REQUESTS_THROUGH_PUBLIC_DID=true to see if that would change the behavior; it did not.

Rolling the deployment back to 0.8.1 fixes the issue.

The agent configuration settings can be found here; https://github.com/bcgov/trust-over-ip-configurations/blob/main/openshift/templates/issuer-agent/issuer-agent-deploy.idim.dev.param.

cc @swcurran, @marcos-carretero,

WadeBarnes commented 1 year ago

@mepeltier, @dbluhm, Any thoughts on whether this issue is related to https://github.com/hyperledger/aries-cloudagent-python/pull/2034?

dbluhm commented 1 year ago

What type of message is being received (the one after which nothings appears to be done with it and no additional details)? If it was an "unsolicited" connection request, either through connections or DID Exchange, I would expect an error to be raised saying Unsolicited connection requests to public DID is not enabled, when ACAPY_REQUESTS_THROUGH_PUBLIC_DID is not enabled.

WadeBarnes commented 1 year ago

I'll see if I can dig up the log. There was no error message to that affect.

WadeBarnes commented 1 year ago

Updated the description with the log message.

dbluhm commented 1 year ago

A couple more points of clarification:

WadeBarnes commented 1 year ago
  • Do we see ConnectionRequestHandler called with context ... in the logs after the log message you shared?

Yes, added to the log in the description.

  • The request is coming from the BC Wallet to the Issuer Agent; is the BC Wallet using an invitation created by the issuer agent or is it connecting using a known public DID for the agent?

It looks like the BC Wallet uses an invitation from the issuer. @jleach, @amanji, can you confirm?

dbluhm commented 1 year ago

Judging from the logs, it's a multiuse invitation; I think that answers my question :slightly_smiling_face:. I don't immediately see any reason why the changes from #2034 would be impacting the behavior of requests received through an invitation. Certainly isn't intended to impact it, at least :sweat_smile:.

In the message receipt (from the conn req handler called log message), it indicates that the recipient_public_did is None. This should cause the handler to retrieve the connection associated with the invitation and then to create a new connection for the relationship for use thereafter. The saving of the new connection should be triggering a webhook to the controller which I presume is exactly the webhook data that we're not getting right now.

Are there any logs following the messages already shared from aries_cloudagent.core.event_bus? More logs in general might also be helpful.

WadeBarnes commented 1 year ago

We only see logs from aries_cloudagent.core.event_bus when using 0.8.1, nothing from 0.9.0.

mepeltier commented 1 year ago

Also, unless I'm missing something, #2034 was included in 0.8.0: https://github.com/hyperledger/aries-cloudagent-python/releases/tag/0.8.0 So, I don't see why switching between 0.9.0 and 0.8.1 would affect anything related to that PR.

swcurran commented 1 year ago

Looks like i screwed up the changelog. It appears that #2034 was merged in Jan 2023, and was indeed published in 0.8.0. So agree that this is not the issue, and that the changelog entry for it is duplicated in 0.9.0. So lets go through the other PRs to see what the issue is.

My apologies.

WadeBarnes commented 1 year ago

Thanks for eliminating the obvious.

swcurran commented 1 year ago

Wade - would it be easy to deploy and test 0.8.2, just to narrow down the changes?

WadeBarnes commented 1 year ago

Should be easy enough. I'll co-ordinate with Jay.

WadeBarnes commented 1 year ago

Here is the log from an exchange (2 attempts) using v0.8.2. Jay is reporting they are not receiving any callbacks:

2023-08-09 16:24:52,537 aries_cloudagent.transport.pack_format DEBUG Expanded message: {'@type': 'https://didcomm.org/connections/1.0/request', '@id': '99e8f085-e9c8-4144-ae8a-fa22514832b0', 'label': 'My Wallet - 0986', 'connection': {'DID': 'VqsHY8cr99YR4SAqXkPE6a', 'DIDDoc': {'@context': 'https://w3id.org/did/v1', 'publicKey': [{'id': 'VqsHY8cr99YR4SAqXkPE6a#1', 'controller': 'VqsHY8cr99YR4SAqXkPE6a', 'type': 'Ed25519VerificationKey2018', 'publicKeyBase58': 'Gimd9diGGJuqsZGgseDGvVAGxQgvY1Y3MX9J2wATm3ks'}], 'service': [{'id': 'VqsHY8cr99YR4SAqXkPE6a#IndyAgentService', 'serviceEndpoint': 'https://aries-mediator-agent.vonx.io', 'type': 'IndyAgent', 'priority': 0, 'recipientKeys': ['Gimd9diGGJuqsZGgseDGvVAGxQgvY1Y3MX9J2wATm3ks'], 'routingKeys': ['cK7fwfjpakMuv8QKVv2y6qouZddVw4TxZNQPUs2fFTd']}], 'authentication': [{'publicKey': 'VqsHY8cr99YR4SAqXkPE6a#1', 'type': 'Ed25519SignatureAuthentication2018'}], 'id': 'VqsHY8cr99YR4SAqXkPE6a'}}, '~thread': {'thid': '99e8f085-e9c8-4144-ae8a-fa22514832b0', 'pthid': 'd475c7f4-14c3-477d-b653-cf903842f4bc'}}
2023-08-09 16:24:52,538 aiohttp.access INFO 10.97.8.1 [09/Aug/2023:16:24:52 +0000] "POST / HTTP/1.1" 200 149 "-" "okhttp/4.9.1"
2023-08-09 16:24:52,545 aries_cloudagent.connections.base_manager WARNING No corresponding DID found for sender verkey: Gimd9diGGJuqsZGgseDGvVAGxQgvY1Y3MX9J2wATm3ks
2023-08-09 16:24:52,551 aries_cloudagent.connections.base_manager WARNING No corresponding DID found for recipient verkey: 2eHpQFonMEhmzoaeEmALKWqdqyRWYfA6LQyjJJtgb2WT
2023-08-09 16:24:52,561 aries_cloudagent.messaging.base_handler DEBUG ConnectionRequestHandler called with context <RequestContext(_connection_ready=False, _connection_record=<ConnRecord(_id='78b521d6-0991-4c13-b9d4-d47d1e6289e3', _last_state='invitation', _new_with_id=False, state='invitation', created_at='2022-07-07T22:56:59.083910Z', updated_at='2023-08-09T16:16:35.600177Z', my_did=None, their_did=None, their_label=None, their_role='invitee', invitation_key='2eHpQFonMEhmzoaeEmALKWqdqyRWYfA6LQyjJJtgb2WT', invitation_msg_id=None, request_id=None, error_msg=None, inbound_connection_id=None, routing_state='none', accept='manual', invitation_mode='multi', alias='wallet-iddev-public', their_public_did=None, connection_protocol='connections/1.0')>, _context=<aries_cloudagent.config.injection_context.InjectionContext object at 0x7f3905fe6f70>, _message=<ConnectionRequest(_message_id='99e8f085-e9c8-4144-ae8a-fa22514832b0', _message_new_id=False, _message_decorators=<DecoratorSet{~thread: <ThreadDecorator(_thid='99e8f085-e9c8-4144-ae8a-fa22514832b0', _pthid='d475c7f4-14c3-477d-b653-cf903842f4bc', _sender_order=None, _received_orders=None)>}>, _message_type='connections/1.0/request', connection=<ConnectionDetail(_did='VqsHY8cr99YR4SAqXkPE6a', _did_doc=<DIDDoc did=VqsHY8cr99YR4SAqXkPE6a>)>, label='My Wallet - 0986', image_url=None)>, _message_receipt=<MessageReceipt(_connection_id=None, _direct_response_mode=None, _in_time='2023-08-09T16:24:52.528528Z', _raw_message='{"@type":"https://didcomm.org/connections/1.0/request","@id":"99e8f085-e9c8-4144-ae8a-fa22514832b0","label":"My Wallet - 0986","connection":{"DID":"VqsHY8cr99YR4SAqXkPE6a","DIDDoc":{"@context":"https://w3id.org/did/v1","publicKey":[{"id":"VqsHY8cr99YR4SAqXkPE6a#1","controller":"VqsHY8cr99YR4SAqXkPE6a","type":"Ed25519VerificationKey2018","publicKeyBase58":"Gimd9diGGJuqsZGgseDGvVAGxQgvY1Y3MX9J2wATm3ks"}],"service":[{"id":"VqsHY8cr99YR4SAqXkPE6a#IndyAgentService","serviceEndpoint":"https://aries-mediator-agent.vonx.io","type":"IndyAgent","priority":0,"recipientKeys":["Gimd9diGGJuqsZGgseDGvVAGxQgvY1Y3MX9J2wATm3ks"],"routingKeys":["cK7fwfjpakMuv8QKVv2y6qouZddVw4TxZNQPUs2fFTd"]}],"authentication":[{"publicKey":"VqsHY8cr99YR4SAqXkPE6a#1","type":"Ed25519SignatureAuthentication2018"}],"id":"VqsHY8cr99YR4SAqXkPE6a"}},"~thread":{"thid":"99e8f085-e9c8-4144-ae8a-fa22514832b0","pthid":"d475c7f4-14c3-477d-b653-cf903842f4bc"}}', _recipient_verkey='2eHpQFonMEhmzoaeEmALKWqdqyRWYfA6LQyjJJtgb2WT', _recipient_did=None, _recipient_did_public=None, _sender_did=None, _sender_verkey='Gimd9diGGJuqsZGgseDGvVAGxQgvY1Y3MX9J2wATm3ks', _thread_id='99e8f085-e9c8-4144-ae8a-fa22514832b0', _parent_thread_id='d475c7f4-14c3-477d-b653-cf903842f4bc')>, _profile=<AskarProfile(backend=askar, name=agent_idim_wallet)>)>
2023-08-09 16:24:52,737 aries_cloudagent.messaging.base_handler DEBUG Connection request will await acceptance
2023-08-09 16:24:56,609 aries_cloudagent.admin.server DEBUG Incoming request: GET /status/ready
2023-08-09 16:24:56,609 aries_cloudagent.admin.server DEBUG Match info: <MatchInfo {}: <ResourceRoute [GET] <PlainResource  /status/ready> -> <bound method AdminServer.readiness_handler of <aries_cloudagent.admin.server.AdminServer object at 0x7f3907bfb610>>>
2023-08-09 16:24:56,609 aries_cloudagent.admin.server DEBUG Body: None
2023-08-09 16:24:56,610 aiohttp.access INFO 127.0.0.1 [09/Aug/2023:16:24:56 +0000] "GET /status/ready HTTP/1.1" 200 172 "-" "curl/7.74.0"
2023-08-09 16:24:56,612 aries_cloudagent.admin.server DEBUG Incoming request: GET /status/live
2023-08-09 16:24:56,612 aries_cloudagent.admin.server DEBUG Match info: <MatchInfo {}: <ResourceRoute [GET] <PlainResource  /status/live> -> <bound method AdminServer.liveliness_handler of <aries_cloudagent.admin.server.AdminServer object at 0x7f3907bfb610>>>
2023-08-09 16:24:56,612 aries_cloudagent.admin.server DEBUG Body: None
2023-08-09 16:24:56,613 aiohttp.access INFO 127.0.0.1 [09/Aug/2023:16:24:56 +0000] "GET /status/live HTTP/1.1" 200 172 "-" "curl/7.74.0"
2023-08-09 16:24:59,575 aries_cloudagent.admin.server DEBUG Incoming request: GET /status/ready
2023-08-09 16:24:59,575 aries_cloudagent.admin.server DEBUG Match info: <MatchInfo {}: <ResourceRoute [GET] <PlainResource  /status/ready> -> <bound method AdminServer.readiness_handler of <aries_cloudagent.admin.server.AdminServer object at 0x7f3907bfb610>>>
2023-08-09 16:24:59,575 aries_cloudagent.admin.server DEBUG Body: None
2023-08-09 16:24:59,575 aiohttp.access INFO 10.97.6.1 [09/Aug/2023:16:24:59 +0000] "GET /status/ready HTTP/1.1" 200 172 "-" "synthetic-monitoring-agent/v0.16.3-0-gde4721a (linux amd64; de4721a49e0e051c31da23de1d50464e6b74687b; 2023-06-13 15:22:55+00:00; +https://github.com/grafana/synthetic-monitoring-agent)"
2023-08-09 16:25:06,800 aries_cloudagent.admin.server DEBUG Incoming request: GET /status/ready
2023-08-09 16:25:06,800 aries_cloudagent.admin.server DEBUG Match info: <MatchInfo {}: <ResourceRoute [GET] <PlainResource  /status/ready> -> <bound method AdminServer.readiness_handler of <aries_cloudagent.admin.server.AdminServer object at 0x7f3907bfb610>>>
2023-08-09 16:25:06,800 aries_cloudagent.admin.server DEBUG Body: None
2023-08-09 16:25:06,801 aiohttp.access INFO 10.97.6.1 [09/Aug/2023:16:25:06 +0000] "GET /status/ready HTTP/1.1" 200 172 "-" "synthetic-monitoring-agent/v0.16.3-0-gde4721a (linux amd64; de4721a49e0e051c31da23de1d50464e6b74687b; 2023-06-13 15:22:55+00:00; +https://github.com/grafana/synthetic-monitoring-agent)"
2023-08-09 16:25:07,832 aries_cloudagent.transport.pack_format DEBUG Expanded message: {'@type': 'https://didcomm.org/connections/1.0/request', '@id': 'ebe50d5f-dc84-4289-a1cc-b5ec24e35802', 'label': 'My Wallet - 0986', 'connection': {'DID': 'LiUcXtDnWaJCi5xFYqnqnc', 'DIDDoc': {'@context': 'https://w3id.org/did/v1', 'publicKey': [{'id': 'LiUcXtDnWaJCi5xFYqnqnc#1', 'controller': 'LiUcXtDnWaJCi5xFYqnqnc', 'type': 'Ed25519VerificationKey2018', 'publicKeyBase58': 'BkEXvQLtChEb7rgTUYC9CjNYupSnWD7XgZvV5RaF6bUM'}], 'service': [{'id': 'LiUcXtDnWaJCi5xFYqnqnc#IndyAgentService', 'serviceEndpoint': 'https://aries-mediator-agent.vonx.io', 'type': 'IndyAgent', 'priority': 0, 'recipientKeys': ['BkEXvQLtChEb7rgTUYC9CjNYupSnWD7XgZvV5RaF6bUM'], 'routingKeys': ['cK7fwfjpakMuv8QKVv2y6qouZddVw4TxZNQPUs2fFTd']}], 'authentication': [{'publicKey': 'LiUcXtDnWaJCi5xFYqnqnc#1', 'type': 'Ed25519SignatureAuthentication2018'}], 'id': 'LiUcXtDnWaJCi5xFYqnqnc'}}, '~thread': {'thid': 'ebe50d5f-dc84-4289-a1cc-b5ec24e35802', 'pthid': 'd475c7f4-14c3-477d-b653-cf903842f4bc'}}
2023-08-09 16:25:07,833 aiohttp.access INFO 10.97.8.1 [09/Aug/2023:16:25:07 +0000] "POST / HTTP/1.1" 200 168 "-" "okhttp/4.9.1"
2023-08-09 16:25:07,837 aries_cloudagent.connections.base_manager WARNING No corresponding DID found for sender verkey: BkEXvQLtChEb7rgTUYC9CjNYupSnWD7XgZvV5RaF6bUM
2023-08-09 16:25:07,839 aries_cloudagent.connections.base_manager WARNING No corresponding DID found for recipient verkey: 2eHpQFonMEhmzoaeEmALKWqdqyRWYfA6LQyjJJtgb2WT
2023-08-09 16:25:07,845 aries_cloudagent.messaging.base_handler DEBUG ConnectionRequestHandler called with context <RequestContext(_connection_ready=False, _connection_record=<ConnRecord(_id='78b521d6-0991-4c13-b9d4-d47d1e6289e3', _last_state='invitation', _new_with_id=False, state='invitation', created_at='2022-07-07T22:56:59.083910Z', updated_at='2023-08-09T16:16:35.600177Z', my_did=None, their_did=None, their_label=None, their_role='invitee', invitation_key='2eHpQFonMEhmzoaeEmALKWqdqyRWYfA6LQyjJJtgb2WT', invitation_msg_id=None, request_id=None, error_msg=None, inbound_connection_id=None, routing_state='none', accept='manual', invitation_mode='multi', alias='wallet-iddev-public', their_public_did=None, connection_protocol='connections/1.0')>, _context=<aries_cloudagent.config.injection_context.InjectionContext object at 0x7f3906010f10>, _message=<ConnectionRequest(_message_id='ebe50d5f-dc84-4289-a1cc-b5ec24e35802', _message_new_id=False, _message_decorators=<DecoratorSet{~thread: <ThreadDecorator(_thid='ebe50d5f-dc84-4289-a1cc-b5ec24e35802', _pthid='d475c7f4-14c3-477d-b653-cf903842f4bc', _sender_order=None, _received_orders=None)>}>, _message_type='connections/1.0/request', connection=<ConnectionDetail(_did='LiUcXtDnWaJCi5xFYqnqnc', _did_doc=<DIDDoc did=LiUcXtDnWaJCi5xFYqnqnc>)>, label='My Wallet - 0986', image_url=None)>, _message_receipt=<MessageReceipt(_connection_id=None, _direct_response_mode=None, _in_time='2023-08-09T16:25:07.825625Z', _raw_message='{"@type":"https://didcomm.org/connections/1.0/request","@id":"ebe50d5f-dc84-4289-a1cc-b5ec24e35802","label":"My Wallet - 0986","connection":{"DID":"LiUcXtDnWaJCi5xFYqnqnc","DIDDoc":{"@context":"https://w3id.org/did/v1","publicKey":[{"id":"LiUcXtDnWaJCi5xFYqnqnc#1","controller":"LiUcXtDnWaJCi5xFYqnqnc","type":"Ed25519VerificationKey2018","publicKeyBase58":"BkEXvQLtChEb7rgTUYC9CjNYupSnWD7XgZvV5RaF6bUM"}],"service":[{"id":"LiUcXtDnWaJCi5xFYqnqnc#IndyAgentService","serviceEndpoint":"https://aries-mediator-agent.vonx.io","type":"IndyAgent","priority":0,"recipientKeys":["BkEXvQLtChEb7rgTUYC9CjNYupSnWD7XgZvV5RaF6bUM"],"routingKeys":["cK7fwfjpakMuv8QKVv2y6qouZddVw4TxZNQPUs2fFTd"]}],"authentication":[{"publicKey":"LiUcXtDnWaJCi5xFYqnqnc#1","type":"Ed25519SignatureAuthentication2018"}],"id":"LiUcXtDnWaJCi5xFYqnqnc"}},"~thread":{"thid":"ebe50d5f-dc84-4289-a1cc-b5ec24e35802","pthid":"d475c7f4-14c3-477d-b653-cf903842f4bc"}}', _recipient_verkey='2eHpQFonMEhmzoaeEmALKWqdqyRWYfA6LQyjJJtgb2WT', _recipient_did=None, _recipient_did_public=None, _sender_did=None, _sender_verkey='BkEXvQLtChEb7rgTUYC9CjNYupSnWD7XgZvV5RaF6bUM', _thread_id='ebe50d5f-dc84-4289-a1cc-b5ec24e35802', _parent_thread_id='d475c7f4-14c3-477d-b653-cf903842f4bc')>, _profile=<AskarProfile(backend=askar, name=agent_idim_wallet)>)>
2023-08-09 16:25:07,962 aries_cloudagent.messaging.base_handler DEBUG Connection request will await acceptance
WadeBarnes commented 1 year ago

Same behavior with v0.9.0:

2023-08-09 16:34:49,519 aiohttp.access INFO 10.97.8.1 [09/Aug/2023:16:34:49 +0000] "GET /status/ready HTTP/1.1" 200 172 "-" "Mozilla/5.0 (compatible; Uptime/1.0; http://uptime.com)"
2023-08-09 16:34:54,537 aries_cloudagent.transport.pack_format DEBUG Expanded message: {'@type': 'https://didcomm.org/connections/1.0/request', '@id': '764d7a48-d2b8-4a63-b3e6-d668d8ac3025', 'label': 'My Wallet - 0986', 'connection': {'DID': 'GUezib8PKrosYc8xrMnGX4', 'DIDDoc': {'@context': 'https://w3id.org/did/v1', 'publicKey': [{'id': 'GUezib8PKrosYc8xrMnGX4#1', 'controller': 'GUezib8PKrosYc8xrMnGX4', 'type': 'Ed25519VerificationKey2018', 'publicKeyBase58': '9SFeXPuG5Q1XFS6ZH24jHVSAw8F9LFRr8KFnHGzHQcPL'}], 'service': [{'id': 'GUezib8PKrosYc8xrMnGX4#IndyAgentService', 'serviceEndpoint': 'https://aries-mediator-agent.vonx.io', 'type': 'IndyAgent', 'priority': 0, 'recipientKeys': ['9SFeXPuG5Q1XFS6ZH24jHVSAw8F9LFRr8KFnHGzHQcPL'], 'routingKeys': ['cK7fwfjpakMuv8QKVv2y6qouZddVw4TxZNQPUs2fFTd']}], 'authentication': [{'publicKey': 'GUezib8PKrosYc8xrMnGX4#1', 'type': 'Ed25519SignatureAuthentication2018'}], 'id': 'GUezib8PKrosYc8xrMnGX4'}}, '~thread': {'thid': '764d7a48-d2b8-4a63-b3e6-d668d8ac3025', 'pthid': 'd475c7f4-14c3-477d-b653-cf903842f4bc'}}
2023-08-09 16:34:54,538 aiohttp.access INFO 10.97.8.1 [09/Aug/2023:16:34:54 +0000] "POST / HTTP/1.1" 200 149 "-" "okhttp/4.9.1"
2023-08-09 16:34:54,547 aries_cloudagent.connections.base_manager WARNING No corresponding DID found for sender verkey: 9SFeXPuG5Q1XFS6ZH24jHVSAw8F9LFRr8KFnHGzHQcPL
2023-08-09 16:34:54,550 aries_cloudagent.connections.base_manager WARNING No corresponding DID found for recipient verkey: 2eHpQFonMEhmzoaeEmALKWqdqyRWYfA6LQyjJJtgb2WT
2023-08-09 16:34:54,561 aries_cloudagent.messaging.base_handler DEBUG ConnectionRequestHandler called with context <RequestContext(_connection_ready=False, _connection_record=<ConnRecord(_id='78b521d6-0991-4c13-b9d4-d47d1e6289e3', _last_state='invitation', _new_with_id=False, state='invitation', created_at='2022-07-07T22:56:59.083910Z', updated_at='2023-08-09T16:16:35.600177Z', my_did=None, their_did=None, their_label=None, their_role='invitee', invitation_key='2eHpQFonMEhmzoaeEmALKWqdqyRWYfA6LQyjJJtgb2WT', invitation_msg_id=None, request_id=None, error_msg=None, inbound_connection_id=None, routing_state='none', accept='manual', invitation_mode='multi', alias='wallet-iddev-public', their_public_did=None, connection_protocol='connections/1.0')>, _context=<aries_cloudagent.config.injection_context.InjectionContext object at 0x7f35d62029d0>, _message=<ConnectionRequest(_message_id='764d7a48-d2b8-4a63-b3e6-d668d8ac3025', _message_new_id=False, _message_decorators=<DecoratorSet{~thread: <ThreadDecorator(_thid='764d7a48-d2b8-4a63-b3e6-d668d8ac3025', _pthid='d475c7f4-14c3-477d-b653-cf903842f4bc', _sender_order=None, _received_orders=None)>}>, _message_type='connections/1.0/request', connection=<ConnectionDetail(_did='GUezib8PKrosYc8xrMnGX4', _did_doc=<DIDDoc did=GUezib8PKrosYc8xrMnGX4>)>, label='My Wallet - 0986', image_url=None)>, _message_receipt=<MessageReceipt(_connection_id=None, _direct_response_mode=None, _in_time='2023-08-09T16:34:54.515331Z', _raw_message='{"@type":"https://didcomm.org/connections/1.0/request","@id":"764d7a48-d2b8-4a63-b3e6-d668d8ac3025","label":"My Wallet - 0986","connection":{"DID":"GUezib8PKrosYc8xrMnGX4","DIDDoc":{"@context":"https://w3id.org/did/v1","publicKey":[{"id":"GUezib8PKrosYc8xrMnGX4#1","controller":"GUezib8PKrosYc8xrMnGX4","type":"Ed25519VerificationKey2018","publicKeyBase58":"9SFeXPuG5Q1XFS6ZH24jHVSAw8F9LFRr8KFnHGzHQcPL"}],"service":[{"id":"GUezib8PKrosYc8xrMnGX4#IndyAgentService","serviceEndpoint":"https://aries-mediator-agent.vonx.io","type":"IndyAgent","priority":0,"recipientKeys":["9SFeXPuG5Q1XFS6ZH24jHVSAw8F9LFRr8KFnHGzHQcPL"],"routingKeys":["cK7fwfjpakMuv8QKVv2y6qouZddVw4TxZNQPUs2fFTd"]}],"authentication":[{"publicKey":"GUezib8PKrosYc8xrMnGX4#1","type":"Ed25519SignatureAuthentication2018"}],"id":"GUezib8PKrosYc8xrMnGX4"}},"~thread":{"thid":"764d7a48-d2b8-4a63-b3e6-d668d8ac3025","pthid":"d475c7f4-14c3-477d-b653-cf903842f4bc"}}', _recipient_verkey='2eHpQFonMEhmzoaeEmALKWqdqyRWYfA6LQyjJJtgb2WT', _recipient_did=None, _recipient_did_public=None, _sender_did=None, _sender_verkey='9SFeXPuG5Q1XFS6ZH24jHVSAw8F9LFRr8KFnHGzHQcPL', _thread_id='764d7a48-d2b8-4a63-b3e6-d668d8ac3025', _parent_thread_id='d475c7f4-14c3-477d-b653-cf903842f4bc')>, _profile=<AskarProfile(backend=askar, name=agent_idim_wallet)>)>
2023-08-09 16:34:54,711 aries_cloudagent.messaging.base_handler DEBUG Connection request will await acceptance
WadeBarnes commented 1 year ago

The logs of a successful exchange using v0.8.1: v0.8.1-exchange-logs.txt

WadeBarnes commented 1 year ago

So, the issue was introduced in v0.8.2.

swcurran commented 1 year ago

Idea — recall that when we upgraded to 0.8.1, IDIM did some sort of compensation for an extra webhook that was sent from ACA-Py as the result of a change to eliminate a slow down underload when dealing with multi-use invitations. In 0.8.2, @esune found a way to eliminate the extra webhook, as it was not needed — #2223 . Perhaps that compensation that IDIM is using is preventing the flow.

loneil commented 1 year ago

Not sure if helpful or already discussed but I can still connect to my BC Wallet via a multi-use invitation with Traction using 0.9.0.

Tenant UI might be able to be used for troubleshooting to try out invitations and see expanded details about resultant connections https://tenant-ui-dev.apps.silver.devops.gov.bc.ca/connections/invitations

Can set a webhook listener in the Tenant settings through that UI to see what events are propagating. I use something like https://webhook.site/ and the Tenant UI to follow through things like that.

image

esune commented 1 year ago

I was able to complete a full connection/issuing cycle using issuer-kit and 0.9.0, the webhooks for connection and credential offer seem to be working as they are handled in the controller.

swcurran commented 1 year ago

Looks like this might be specific to the IDIM setup, as things are working elsewhere. How do we get access to the IDIM code to run through what is happening?

Looking at the logs, we see that things flow the same, but it looks like the message being forwarded to the controller is not received by the IDIM controller, so things stop. So either the webhook is not fired, or the webhook path is not working.

Super high priority to get this understood, so lets see what we can do today to figure this out.

esune commented 1 year ago

The invite used to connect with the IDIM agent in dev is here: https://github.com/bcgov/bc-wallet-mobile/blob/330c2d78b0106a9d9d659a2b57003989fefc0fc6/app/src/store.tsx#L53

This is the base64-decoded payload:

{
    "@type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/connections/1.0/invitation",
    "@id": "d475c7f4-14c3-477d-b653-cf903842f4bc",
    "recipientKeys": ["2eHpQFonMEhmzoaeEmALKWqdqyRWYfA6LQyjJJtgb2WT"],
    "label": "IDIM (Dev)",
    "serviceEndpoint": "https://idim-agent-dev.apps.silver.devops.gov.bc.ca",
    "imageUrl": "https://id.gov.bc.ca/static/Gov-2.0/images/favicon.ico"
}

It doesn't look like it is using a public DID invitation.

swcurran commented 1 year ago

Correct — it is using a multi-use invitation.

esune commented 1 year ago

I think @swcurran is right about this being a consequence #2223, the payload of the webhook that is "missing" is as follows:

2023-08-09 16:41:28,312 aries_cloudagent.core.event_bus DEBUG Notifying subscribers: <Event topic=acapy::record::connections::request, payload={'accept': 'manual', 'created_at': '2023-08-09T16:41:28.304383Z', 'invitation_key': '2eHpQFonMEhmzoaeEmALKWqdqyRWYfA6LQyjJJtgb2WT', 'connection_id': 'b8d33c22-38a1-4764-9fe8-c11f701080fc', 'invitation_mode': 'once', 'rfc23_state': 'request-received', 'connection_protocol': 'connections/1.0', 'updated_at': '2023-08-09T16:41:28.304383Z', 'my_did': 'LLxwrXzSgyfmitRHnXgthJ', 'routing_state': 'none', 'their_role': 'invitee', 'state': 'request'}>

We determined that the initial webhook was overhead since it was being fired twice (upon creation of the multi-use invitation AND every time a new connection was being "cloned". The first webhook was being fired when the connection record was cloned and it is now gone, the following steps in the protocol should fire a webhook though (i.e.: the connection moving from request to response and then active). Will have to review the agent setup again and step through the code to understand better where things are tripping, it does make sense to me to not expect that webhook and expect the following ones since the connection, technically, was initiated by the IDIM agent with the multi-use invite. 🤔

swcurran commented 1 year ago

@WadeBarnes — can you help get us able to see the code from IDIM so we can investigate this further? Per Jay/IDIM in RocketChat:

I believe the only change we did is to make their_did optional on the connection callbacks except when the connection status is completed. This does not seem to be related to the issue we have with 0.9.0 as we're not getting any connection callbacks at all.

We need to sort this out.

esune commented 1 year ago

I was able to reproduce the behaviour, I am stepping through the code and debugging. Some webhooks are indeed not being fired, and I am trying to understand why and how to fix it.

A mitigation step could be turning ACAPY_AUTO_ACCEPT_REQUESTS to true - it is set to false in the IDIM agents - as this would cause the connection to become active and fire the appropriate webhook.

esune commented 1 year ago

Opened PR with fix.

swcurran commented 1 year ago

Let’s figure out how to do a new release for this. If only we had nightly builds… :-)

Awesome work!

WadeBarnes commented 1 year ago

Let’s figure out how to do a new release for this. If only we had nightly builds… :-)

We can build pre-release images at any time. The image publish workflow supports the workflow_dispatch trigger and you can specify the tag and even the git ref you want to build from.

image