Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Issue receiving credentials with 0.7.4rc0 of aca-py #1724

Closed
etschelp opened this issue Apr 8, 2022 · 19 comments
Closed

Issue receiving credentials with 0.7.4rc0 of aca-py #1724

etschelp opened this issue Apr 8, 2022 · 19 comments
Assignees

Comments

@etschelp
Copy link
Contributor

etschelp commented Apr 8, 2022

I'm experiencing issues receiving credentials while testing with the 0.7.4 release candidate.

I was testing with the following setup:

agent1:

  • running 0.7.4rc0
  • wallet type does not matter
  • single or multi ledger does not matter
  • credential definition with revocation enabled
  • Credential Exchange Version 1

agent2:

  • running previous version 0.7.3
  • wallet type is askar
  • single ledger
  • credential definition with revocation enabled
  • Credential Exchange Version 1

agent 2 sends credential offer to agent 1. and if agent 1 wants to accept the offer the exchange gets stuck on agent 1 with:

 2022-04-08 15:31:22,008 aries_cloudagent.core.conductor ERROR Exception in message handler:
 Traceback (most recent call last):
   File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/core/dispatcher.py", line 197, in handle_message
     await handler(context, responder)
   File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_issue_handler.py", line 42, in handle
     context.message, context.connection_record.connection_id
   File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/protocols/issue_credential/v1_0/manager.py", line 784, in receive_credential
     f"Credential exchange {cred_ex_record.credential_exchange_id} "
 aries_cloudagent.protocols.issue_credential.v1_0.manager.CredentialManagerError: Credential exchange e2b9d7b3-6ef5-4562-b662-55984a853bb0 in abandoned state (must be request_sent)
 2022-04-08 15:31:22,008 aries_askar.native.aries_askar.ffi.store INFO 	src/ffi/store.rs:1007 | Closed session SessionHandle(60)
 2022-04-08 15:31:22,012 aries_cloudagent.core.conductor ERROR DON'T shutdown on CredentialManagerError Credential exchange e2b9d7b3-6ef5-4562-b662-55984a853bb0 in abandoned state (must be request_sent)
 2022-04-08 15:31:22,014 aries_cloudagent.core.dispatcher ERROR Handler error: Dispatcher.handle_message
 Traceback (most recent call last):
   File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/core/dispatcher.py", line 197, in handle_message
     await handler(context, responder)
   File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_issue_handler.py", line 42, in handle
     context.message, context.connection_record.connection_id
   File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/protocols/issue_credential/v1_0/manager.py", line 784, in receive_credential
     f"Credential exchange {cred_ex_record.credential_exchange_id} "
 aries_cloudagent.protocols.issue_credential.v1_0.manager.CredentialManagerError: Credential exchange e2b9d7b3-6ef5-4562-b662-55984a853bb0 in abandoned state (must be request_sent)

If agent 1 sends a credential proposal to agent 2 and agent 2 accepts the proposal the exchange gets stuck on agent2 with:

2022-04-08 16:52:03,746 aries_cloudagent.admin.server ERROR Handler error with exception: Record not found: credential_exchange_v10/459076ac-8dba-48a5-b7a6-28d8c08ea832.

2022-04-08 16:52:03,746 aries_askar.native.aries_askar.ffi.store INFO 	src/ffi/store.rs:1007 | Closed session SessionHandle(698)
2022-04-08 16:52:03,746 aries_askar.native.aries_askar.backend.db_utils INFO 	src/backend/db_utils.rs:168 | Dropped pool connection
=================
Traceback (most recent call last):
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/protocols/issue_credential/v1_0/routes.py", line 885, in credential_exchange_send_bound_offer
    session, credential_exchange_id
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/messaging/models/base_record.py", line 233, in retrieve_by_id
    cls.RECORD_TYPE, record_id, {"retrieveTags": False}
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/storage/askar.py", line 94, in get_record
    raise StorageNotFoundError(f"Record not found: {record_type}/{record_id}")
aries_cloudagent.storage.error.StorageNotFoundError: Record not found: credential_exchange_v10/459076ac-8dba-48a5-b7a6-28d8c08ea832

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

Traceback (most recent call last):
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/admin/server.py", line 163, in ready_middleware
    return await handler(request)
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/admin/server.py", line 200, in debug_middleware
    return await handler(request)
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aiohttp_apispec/middlewares.py", line 45, in validation_middleware
    return await handler(request)
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/admin/server.py", line 301, in check_token
    return await handler(request)
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/admin/server.py", line 391, in setup_context
    return await task
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/protocols/issue_credential/v1_0/routes.py", line 888, in credential_exchange_send_bound_offer
    raise web.HTTPNotFound(reason=err.roll_up) from err
aiohttp.web_exceptions.HTTPNotFound: Record not found: credential_exchange_v10/459076ac-8dba-48a5-b7a6-28d8c08ea832.
2022-04-08 16:52:03,746 aiohttp.access INFO 10.42.0.138 [08/Apr/2022:16:52:03 +0000] "POST /issue-credential/records/459076ac-8dba-48a5-b7a6-28d8c08ea832/send-offer HTTP/1.1" 404 318 "-" "okhttp/4.9.3"
```
@shaangill025
Copy link
Contributor

@etschelp What --wallet-storage-type option are you using?

I tested with the following configuration and steps. I was able to issue to and issue from 0.7.3 agent and also store credentials without any issues.

v0.7.4rc0
PORTS="5002 8002" ./scripts/run_docker start --admin 0.0.0.0 5002 --inbound-transport http 0.0.0.0 8002 --outbound-transport http -e http://host.docker.internal:8002 --admin-insecure-mode --public-invites --auto-ping-connection --auto-accept-invites --auto-accept-requests --auto-respond-presentation-proposal --auto-verify-presentation --genesis-url http://host.docker.internal:9000/genesis --seed 00000000000000000000000000000008 --auto-provision --wallet-type askar --wallet-name issuer --wallet-key mykey --tails-server-base-url http://host.docker.internal:6543

v7.3.0
PORTS="5001 8001" ./scripts/run_docker start --admin 0.0.0.0 5001 --inbound-transport http 0.0.0.0 8001 --outbound-transport http -e http://host.docker.internal:8001 --admin-insecure-mode --public-invites --auto-ping-connection --auto-accept-invites --auto-accept-requests --auto-respond-presentation-proposal --auto-verify-presentation --genesis-url http://host.docker.internal:9000/genesis --seed 00000000000000000000000000000009 --auto-provision --wallet-type askar --wallet-name issuer --wallet-key mykey --tails-server-base-url http://host.docker.internal:6543

Steps:

  • Establish connection b/w [0.7.3 agent] and [0.7.4rc0 agent]
  • [0.7.3 agent]: POST /schemas
  • [0.7.3 agent]: POST /credential-definitions - with support_revocation: true
  • [0.7.3 agent]: POST /issue-credential/send-offer
  • [0.7.4rc0 agent]: POST /issue-credential/records/{cred_ex_id}/send-request
  • [0.7.3 agent]: POST /issue-credential/records/{cred_ex_id}/issue
    And the same steps as above but the other way around. Also, tested starting from send-proposal

@etschelp
Copy link
Contributor Author

This happens if one of the wallets is of type askar. It does not happen every time, sometimes like every 5th time, sometimes sooner. On one machine running arm aca-py runs emulated and is very slow this happens nearly every time. On other machines it's more randomly. So this looks like a synchronisation issue I guess. Also it happens more often if the auto flags are disabled.

@etschelp
Copy link
Contributor Author

Even easier, if both agents are running 0.7.4rc0 and use wallet type askar this happens nearly every time. Previously this was only true for the V1 protocol, if I switch to V2 with indy payload it breaks every time with:

  Traceback (most recent call last):
   File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/core/dispatcher.py", line 197, in handle_message
     await handler(context, responder)
   File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_issue_handler.py", line 43, in handle
     context.message, context.connection_record.connection_id
   File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/protocols/issue_credential/v2_0/manager.py", line 555, in receive_credential
     for fmt in cred_request_message.formats
 AttributeError: 'NoneType' object has no attribute 'formats'
 2022-04-11 09:53:28,658 aries_cloudagent.core.conductor ERROR DON'T shutdown on AttributeError 'NoneType' object has no attribute 'formats'
 2022-04-11 09:53:28,658 aries_cloudagent.core.dispatcher ERROR Handler error: Dispatcher.handle_message
 Traceback (most recent call last):
   File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/core/dispatcher.py", line 197, in handle_message
     await handler(context, responder)
   File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_issue_handler.py", line 43, in handle
     context.message, context.connection_record.connection_id
   File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/protocols/issue_credential/v2_0/manager.py", line 555, in receive_credential
     for fmt in cred_request_message.formats

@shaangill025
Copy link
Contributor

shaangill025 commented Apr 13, 2022

I wasn't able to trigger any error [within ACA-Py w/ askar --wallet-type] in the following scenarios:

  • from 0.7.4-rc0 to 0.7.3 tagged ACA-Py [/issue-credential/send-offer]
  • from 0.7.4-rc0 to 0.7.3 tagged ACA-Py [/issue-credential-2.0/send-offer]
  • from 0.7.4-rc0 to 0.7.4-rc0 tagged ACA-Py [/issue-credential/send-offer]
  • from 0.7.4-rc0 to 0.7.4-rc0 tagged ACA-Py [/issue-credential-2.0/send-offer]
    I repeated send-offer workflow in each of the above multiple times [15-20] within a short period. I also tested this on mac m1 without issues.

I tried to test this in aries-cloudagent-loadgenerator but was unable to as issuer agents just sent connection invitations and did not proceed with other flows.

I also tested this using ./run_demo performance [0.7.4-rc0]:

  • v1
    • --wallet-type indy works
    • askar error - I am looking into this
      Faber      | 2022-04-13 15:56:06,981 aries_cloudagent.messaging.base_handler ERROR Error responding to credential request
      Faber      | Traceback (most recent call last):
      Faber      |   File "/home/indy/aries_cloudagent/storage/askar.py", line 90, in get_record
      Faber      |     record_type, record_id, for_update=for_update
      Faber      |   File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_askar/store.py", line 408, in fetch
      Faber      |     self._handle, category, name, for_update
      Faber      |   File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_askar/bindings.py", line 782, in session_fetch
      Faber      |     return_type=EntryListHandle,
      Faber      | aries_askar.error.AskarError: Backend error
      Faber      | Caused by: error returned from database: database is locked
      Faber      |
      Faber      | The above exception was the direct cause of the following exception:
      Faber      |
      Faber      | Traceback (most recent call last):
      Faber      |   File "/home/indy/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_request_handler.py", line 67, in handle
      Faber      | Task raised exception: Error: 400: Error when adding storage record. Backend error. Caused by: error returned from database: no such savepoint: _sqlx_savepoint_6.
      Faber      |     comment=context.message.comment,
      Faber      |   File "/home/indy/aries_cloudagent/protocols/issue_credential/v1_0/manager.py", line 724, in issue_credential
      Faber      |     txn, cred_ex_record.credential_exchange_id, for_update=True
      Faber      |   File "/home/indy/aries_cloudagent/messaging/models/base_record.py", line 239, in retrieve_by_id
      Faber      |     cls.RECORD_TYPE, record_id, {"forUpdate": for_update, "retrieveTags": False}
      Faber      |   File "/home/indy/aries_cloudagent/storage/askar.py", line 93, in get_record
      Faber      |     raise StorageError("Error when fetching storage record") from err
      Faber      | aries_cloudagent.storage.error.StorageError: Error when fetching storage record
      Faber      | thread 'tokio-runtime-worker' panicked at 'error occurred while dropping a transaction: no such savepoint: _sqlx_savepoint_1', /github/home/.cargo/registry/src/github.com-1ecc6299db9ec823/sqlx-core-0.5.9/src/sqlite/transaction.rs:78:21
      Faber      | note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
      Faber      | 2022-04-13 15:56:07,091 aries_cloudagent.core.conductor ERROR Exception in message handler:
      Faber      | Traceback (most recent call last):
      Faber      |   File "/home/indy/aries_cloudagent/askar/profile.py", line 213, in _teardown
      Faber      |     await self._handle.commit()
      Faber      |   File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_askar/store.py", line 557, in commit
      Faber      |     await self._handle.close(commit=True)
      Faber      |   File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_askar/bindings.py", line 74, in close
      Faber      |     c_int8(commit),
      Faber      | aries_askar.error.AskarError: Unexpected error
      
  • v2
    • indy works
    • askar works

@etschelp
Copy link
Contributor Author

Thats weird. I can still confirm that I can not issue a credential anymore when running 0.7.4-rc0 with askar wallets. The exchange gets stuck on the issuer side when the holder requests the credential after the offer with:

bpa-agent1_1      | 2022-04-14 15:50:28,555 aries_cloudagent.messaging.base_handler ERROR Error responding to credential request
bpa-agent1_1      | Traceback (most recent call last):
bpa-agent1_1      |   File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_request_handler.py", line 67, in handle
bpa-agent1_1      |     comment=context.message.comment,
bpa-agent1_1      |   File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/protocols/issue_credential/v1_0/manager.py", line 677, in issue_credential
bpa-agent1_1      |     tails_path,
bpa-agent1_1      |   File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/indy/credx/issuer.py", line 296, in create_credential
bpa-agent1_1      |     raise IndyIssuerError("Revocation registry metadata not found")

The wrong state exception that I mentioned above is the result of that. I tested this on different machines and different setups and everywhere it is the same.

@swcurran swcurran added the 0.7.4 label Apr 19, 2022
@shaangill025
Copy link
Contributor

@etschelp Did you test it today after the new aries-askar release? If still not working, can you share your ACA-Py startup command with arguments?

@etschelp
Copy link
Contributor Author

etschelp commented Apr 20, 2022

@shaangill025 no changes with the new version still seeing aries_cloudagent.indy.issuer.IndyIssuerError: Revocation registry metadata not found, my build output:

Collecting aries-askar~=0.2.4
  Downloading aries_askar-0.2.5-py3-none-manylinux2014_x86_64.whl (4.8 MB)

Output of the config endpoint:

{
  "config": {
    "admin.admin_insecure_mode": true,
    "admin.enabled": true,
    "admin.host": "0.0.0.0",
    "admin.port": "8031",
    "admin.webhook_urls": [
      "http://localhost:8080/log"
    ],
    "admin.admin_client_max_request_size": 1,
    "debug.auto_respond_presentation_proposal": true,
    "debug.auto_store_credential": true,
    "debug.auto_verify_presentation": true,
    "auto_disclose_features": true,
    "external_plugins": [
      "aries_cloudagent.messaging.jsonld"
    ],
    "default_endpoint": "http://x.x.x.x:8888",
    "additional_endpoints": [],
    "tails_server_base_url": "https://tails.bosch-digital.co",
    "tails_server_upload_url": "https://tails.bosch-digital.co",
    "revocation.notify": true,
    "revocation.monitor_notification": true,
    "ledger.genesis_url": "https://indy-test.bosch-digital.de/genesis",
    "ledger.keepalive": 5,
    "log.level": "info",
    "auto_ping_connection": true,
    "debug.monitor_ping": true,
    "public_invites": true,
    "trace.target": "log",
    "trace.tag": "",
    "trace.label": "Dummy Agent",
    "emit_new_didcomm_prefix": true,
    "emit_new_didcomm_mime_type": true,
    "exch_use_unencrypted_tags": true,
    "auto_provision": true,
    "transport.inbound_configs": [
      [
        "http",
        "0.0.0.0",
        "8030"
      ]
    ],
    "transport.outbound_configs": [
      "http"
    ],
    "transport.enable_undelivered_queue": true,
    "default_label": "Dummy Agent",
    "transport.max_message_size": 2097152,
    "transport.max_outbound_retry": 4,
    "transport.ws.heartbeat_interval": 3,
    "transport.ws.timeout_interval": 15,
    "wallet.name": "wallet_db",
    "wallet.storage_type": "postgres_storage",
    "wallet.type": "askar",
    "wallet.storage_config": "{\"url\":\"bpa-wallet-db1:5432\",\"max_connections\":5}",
    "endorser.author": false,
    "endorser.endorser": false,
    "endorser.auto_endorse": false,
    "endorser.auto_write": false,
    "endorser.auto_create_rev_reg": false,
    "endorser.auto_promote_author_did": false,
    "ledger.read_only": false,
    "ledger.genesis_transactions": "..."
  }
}

@shaangill025
Copy link
Contributor

@etschelp Based upon the provided config, I tried with the following startup arguments [v0.7.4-rc0, same network and tails server] and was able to issue multiple indy credentials [v1 and v2] without any errors. Also tested issuing with cred-def created and stored using v0.7.3. Can you test with the same config as earlier but with local postgres storage. I have requested @ianco if he could help by confirming this.

PORTS="5001 8001" ./scripts/run_docker start --admin 0.0.0.0 5001 --inbound-transport http 0.0.0.0 8001 --outbound-transport http -e http://host.docker.internal:8001 --admin-insecure-mode --public-invites --auto-ping-connection --auto-accept-invites --auto-accept-requests --auto-respond-presentation-proposal --auto-store-credential --auto-verify-presentation --genesis-url https://indy-test.bosch-digital.de/genesis --seed 00000000000000000000000000000009 --auto-provision --wallet-type askar --wallet-name issuer --wallet-key mykey --wallet-storage-type postgres_storage --wallet-storage-config "{\"url\":\"host.docker.internal:5432\",\"max_connections\":5}" --wallet-storage-creds "{\"account\":\"postgres\",\"password\":\"mysecretpassword\",\"admin_account\":\"postgres\",\"admin_password\":\"mysecretpassword\"}" --tails-server-base-url https://tails.bosch-digital.co --tails-server-upload-url https://tails.bosch-digital.co --notify-revocation --monitor-revocation-notification --emit-new-didcomm-prefix --emit-new-didcomm-mime-type --exch-use-unencrypted-tags

PORTS="5002 8002" ./scripts/run_docker start --admin 0.0.0.0 5002 --inbound-transport http 0.0.0.0 8002 --outbound-transport http -e http://host.docker.internal:8002 --admin-insecure-mode --public-invites --auto-ping-connection --auto-accept-invites --auto-accept-requests --auto-respond-presentation-proposal --auto-store-credential --auto-verify-presentation --genesis-url https://indy-test.bosch-digital.de/genesis --seed 00000000000000000000000000000007 --auto-provision --wallet-type askar --wallet-name holder --wallet-key mykey --wallet-storage-type postgres_storage --wallet-storage-config "{\"url\":\"host.docker.internal:5432\",\"max_connections\":5}" --wallet-storage-creds "{\"account\":\"postgres\",\"password\":\"mysecretpassword\",\"admin_account\":\"postgres\",\"admin_password\":\"mysecretpassword\"}" --tails-server-base-url https://tails.bosch-digital.co --tails-server-upload-url https://tails.bosch-digital.co --notify-revocation --monitor-revocation-notification --emit-new-didcomm-prefix --emit-new-didcomm-mime-type --exch-use-unencrypted-tags

@etschelp
Copy link
Contributor Author

@shaangill025 I will look into this next week. I just tested this with the latest state from main, and there it behaves slightly different. Nevertheless I have the impression that this is related to a synch issue between multiple processes in aca-py. When the holder requests the credential I can see in the issuer logs that the exchange goes through and even changes to credential_issued. But it does not stop there after that I see further error logs saying first "wrong state, expected request received but was credential issued", and after that "wrong state expected request_received but was abandoned".

@etschelp
Copy link
Contributor Author

@shaangill025 I have tested this some more and long story short as soon as the 0.7.4rc0 image is started with the askar profile this happens. And I think I have figured out why you can not reproduce this. To reproduce you have to check the events that are fired against the webhook of the controller, and check the exchange state on the issuer side, because the credential appears in the wallet of the holder as issued.

What happens is:

  1. Credential exchange goes through, credential exchange in state issued on both sides
  2. A second thread on the issuer side tries to load the metadata and fails : https://github.com/hyperledger/aries-cloudagent-python/blob/0c695cf8d572f730029a708417c863093437efda/aries_cloudagent/indy/credx/issuer.py#L284
  3. The issuer sets the exchange state to abandoned and sends two problem report messages to the holder
  4. The holder aca-py changes the state of the exchange to abandoned, but the credential stays in the wallet
  5. Optional: The controller reacts on the event and fails the exchange

I have not found the root cause, but it is somewhere inside askar.

@ianco
Copy link
Contributor

ianco commented May 31, 2022

@etschelp as you mentioned on the aca-pug call this morning, I suspect this is related to BPA is responding to web hooks, and some kind of synchronization issue between BPA's response to web hooks, BPA -> Aca-py admin api calls, and stuff aca-py is doing on its own. To solve this we're going to first need to reproduce the exact situation that you're seeing, which means (I think) we're going to have to start up a BPA environment and give it a run.

Can you provide some info about your BPA setup? Are you just running with the standard config that's in the BPA repo?

We may need to schedule a call where you can walk us through your setup and demo the scenario that is generating these issues ...

@etschelp
Copy link
Contributor Author

etschelp commented Jun 1, 2022

@ianco One very simple way to test this is to use GitPod. I have prepared a branch that uses the rc2 with askar you can open it via:

https://gitpod.io/#https://github.com/hyperledger-labs/business-partner-agent/pull/755

Apart from that it uses exactly the configuration from the main branch. Mainly:

It takes a while to start up, once its up you can open the remote explorer on the left hand side (second to last icon):

Screenshot 2022-06-01 at 11 55 28

Clicking on open browser, for ports 8081 and 8090 gives you two empty bpa's. The terminal in the original window gives you all the logs.

If you are not familiar with the BPA here are all the steps to reproduce:

  1. Go the first bpa, open 'settings' and copy the did
  2. Go to the second bpa, open 'secure connections', hit the plus icon and paste the did, click 'search organisation' wait a couple of seconds, and then hit 'connect'
  3. Go to the first bpa, open 'secure connections', you should see a new connection, open it, and 'accept' it
  4. Open the bpa running on port 8090, go to schemas, click on 'bank account', then 'add credential definition' and create a new cred def with revocation enabled, hit the save icon and wait like 20 seconds until the cred def is created
  5. Open the bpa running on port 8090, go to 'secure connections, open the connection and click on the 'issue credential' button on the bottom of the screen, enter some data and hit 'issue'
  6. Go to the other bpa, open 'secure connections', open the connection, you should see a credential offer from the other bpa, open it and hit 'accept'
  7. Now the exchange will fail with all the described logs

I hope this helps, if you have more questions we can schedule a call any time this week.

@swcurran
Copy link
Contributor

swcurran commented Jun 2, 2022

I'm not able to run this. The GitPod instance starts up fine, but the 8090 port toggles between "open (public)" and "not served", until it stops at the latter. As such, I can't do anything with the instances. Am I missing something?

The one at 8081 starts up properly.

Very cool, BTW!

@etschelp
Copy link
Contributor Author

etschelp commented Jun 3, 2022

Thats weird, I recreated the environment several times and every time it comes up nicely. It takes a while for everything to be fully up, and during startup not all ports are available.

Anyhow, it was just an idea to make debugging easier. Ianco's comment got me thinking ,so I started playing around with the endpoints and the auto flags. For credential issuance the bpa was using /issue-credential/send I switched that one to /issue-credential/send-offer and voila it works. I believe at least for the v1 api the issue was that the /send endpoint at some point always needed another call to the /issue endpoint otherwise the flow would not run completely, this behaviour has now changed and the additional call is not needed any more hence the state exception. It is strange though that aca-py fails the exchange if the /issue endpoint is called and the exchange state is already on issued. The v2 endpoints still behave the old way, meaning calling /issue after issuance wont fail the exchange. Also what is the difference between those two endpoints? As send-offer with auto_issue=true also would automate the whole flow.

I will test this some more and then close the ticket as the other issue with the askar exception mentioned above seems to be fixed with the new version in the rc2.

@etschelp etschelp closed this as completed Jun 3, 2022
etschelp added a commit to boschresearch/business-partner-agent that referenced this issue Jun 3, 2022
Signed-off-by: Philipp Etschel <philipp.etschel@ch.bosch.com>
@swcurran
Copy link
Contributor

swcurran commented Jun 3, 2022

Bummer about GitPod not working. Very weird -- I'd love to see this working. I'll see if I can delete the workspace and try it again.

Is there anything in the /send handling that we need to add to detect this situation and give a better error message? Is this a combination of using "/send" (which requires --auto... handling) and the --auto... flags not being set?

@etschelp
Copy link
Contributor Author

etschelp commented Jun 3, 2022

In this case it is more an issue with any combination of either --auto flags set, or using autoXXX=true parameters, or the automated rest endpoints and then calling the respective none automated rest endpoint again from the controller. e.g. using /issue-credential/send and then calling /issue manually in the automated flow again. Before 0.7.4 that resulted in an exception and nothing more, now the exchange also fails with an webhook event, which was unexpected. Of course such a combination is 100% a controller issue, but on the other hand the manual call should not change the exchange state. Here the auto flow was already successful and calling /issue resulted in an abandoned state. I have to retest this in other combinations to see if this was triggered by a race condition in the exchange, or a failure in the exchanges state machine, which would be bad.

Generally I'm tending to move away from any auto flag/parameter combination anyway as this often yields in unexpected results, mostly between the v1 and v2 api's where they sometimes work and sometimes do not. Basically the issue above was because of such a workaround leftover in the code where I had to add a manual step in an auto flow, because it was not fully auto. Current example is the --auto-verify-presentation flag which stopped working for me with 0.7.4 where I should probably open another ticket :)

@swcurran
Copy link
Contributor

swcurran commented Jun 3, 2022

Sounds good -- thanks. I'm also a believer in getting rid of the "--auto..." flags as well. I prefer to see generic controllers that implement the "--auto" flows, and that also identify where to add custom business logic to override default processing.

@ianco
Copy link
Contributor

ianco commented Jun 3, 2022

Just my $0.02 on this issue - I feel that --auto-* flags are very useful setting up a development instance or POC because it's one less process to worry about - you can run a stand-alone aca-py and automatically run full protocols (connections, cred exchange, proof exchange, etc) without any additional intervention.

However I agree with @swcurran that for a production application it's better to have all the --auto-* flags OFF and deal with the exchanges using a combination of webhooks and admin api endpoints.

In any case, the credential/send endpoint automatically sets all the auto steps for the exchange, and with each admin endpoint to can turn on auto via an api parameter, so removing the auto functionality is a bit more complicated than just getting rid of all the --auto-* startup parameters.

Regarding the state checking in each endpoint - and creating problem report messages and putting the exchange into abandoned mode - this was updated across all the exchanges at some point for some reason that I don't recall offhand, however I think it may have been done a bit over-zealously. If you call one of the admin endpoints and the exchange is in the wrong state (e.g. calling the /issue endpoint and the credential is already issued) it should just throw an exception but not change the credential state (which it sounds like is what is happening). This is independent of whether the auto flags are set, because it's easy to accidentally call an endpoint more than once ...

So maybe the exception handling needs to be reviewed across all of the credential and proof exchange endpoints?

@etschelp
Copy link
Contributor Author

etschelp commented Jun 7, 2022

@ianco Concerning the state checking I notice two things:

  1. v1 and v2 api's now behave different. If I issue a credential with credential/send, set autoRemove=false, successfully issue a credential, and try to use the issue endpoint again, v1 gives me 200 (but does not fail the exchange) v2 will throw an exception - 400: Credential exchange 123 in done state (must be request-received)
  2. Provoking the abandoned state by manually calling issue during an exchange seems to be a race condition as I can only reproduce it when the call happens very fast, if I delay it for just a second I get the behaviour described in 1. So my guess is that this only happens if issue is called and aca-py is not 100% done yet with the exchange. But I think this makes sense now, because this either triggers a record not found or a wrong state exception which then probably triggers the newly introduced exception handling.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants