search

openwallet-foundation / owl-agent-test-harness

Aries agent test framework, with agent backchannel support
https://aries-interop.info
Apache License 2.0
60 stars 66 forks source link

ACAPy reliably fails locally in scenario T001-RFC0025 #575

Closed tdiesler closed 2 years ago

tdiesler commented 2 years ago

However, the allure report suggest that this should be working

Is there perhaps some special local setup needed to reproduce what Allure is doing?

$ ./manage test -d acapy -b acapy -t T001-RFC0025
Tags:  --tags=T001-RFC0025

WARNING: The requested image's platform (linux/amd64) does not match the detected host platform (linux/arm64/v8) and no specific platform was requested
@RFC0025 @UsesCustomParameters @AIP10 @AIP20
Feature: RFC 0025 DIDComm Transports # features/0025-didcomm-transports.feature:2
  In order to communicate with other agents,
  As an Agent
  I want to create connections using different transport protocols.
  @T001-RFC0025 @AcceptanceTest @DIDExchangeConnection @Transport_Http @critical
  Scenario Outline: Create DIDExchange connection between two agents with overlapping transports -- @1.1 DIDExchange connection with both agents using HTTP for inbound and outbound transport  # features/0025-didcomm-transports.feature:23
    Given we have "2" agents                                                                                                                                                                    # features/steps/0160-connection.py:22 0.001s
      | name | role      |
      | Acme | responder |
      | Bob  | requester |
    And "Acme" is running with parameters "{"inbound_transports": ["http"], "outbound_transports": ["http"] }"                                                                                  # features/steps/0044-mime-types.py:12 7.795s
    And "Bob" is running with parameters "{"inbound_transports": ["http"], "outbound_transports": ["http"] }"                                                                                   # features/steps/0044-mime-types.py:12 7.783s
    When "Acme" and "Bob" create a new connection                                                                                                                                               # features/steps/0160-connection.py:360 1.990s
      Assertion Failed: FAILED SUB-STEP: When "Acme" and "Bob" create a new didexchange connection
      Substep info: Assertion Failed: FAILED SUB-STEP: And "Acme" sends a response to "Bob"
      Substep info: Assertion Failed: resp_status 400 is not 200; 400: Connection not in state request.
      Traceback (of failed substep):
        File "/usr/local/lib/python3.7/site-packages/behave/model.py", line 1329, in run
          match.run(runner.context)
        File "/usr/local/lib/python3.7/site-packages/behave/matchers.py", line 98, in run
          self.func(context, *args, **kwargs)
        File "features/steps/0023-did-exchange.py", line 351, in step_impl
          assert resp_status == 200, f"resp_status {resp_status} is not 200; {resp_text}"

      Traceback (of failed substep):
        File "/usr/local/lib/python3.7/site-packages/behave/model.py", line 1329, in run
          match.run(runner.context)
        File "/usr/local/lib/python3.7/site-packages/behave/matchers.py", line 98, in run
          self.func(context, *args, **kwargs)
        File "features/steps/0023-did-exchange.py", line 37, in step_impl
          """
        File "/usr/local/lib/python3.7/site-packages/behave/runner.py", line 404, in execute_steps
          assert False, message
swcurran commented 2 years ago

That test runs fine on my local system (Ubuntu). A later testing in the set, "ws" to "ws", fails for a different reason, but not the one you mention above.

tdiesler commented 2 years ago

For my record ... tags can be specified multiple times. 

./manage test -d acapy -t @T001-RFC0025 -t ~@Transport_Ws

Tags:  --tags=@T001-RFC0025 --tags=~@Transport_Ws

WARNING: The requested image's platform (linux/amd64) does not match the detected host platform (linux/arm64/v8) and no specific platform was requested
@RFC0025 @UsesCustomParameters @AIP10 @AIP20
Feature: RFC 0025 DIDComm Transports # features/0025-didcomm-transports.feature:2
  In order to communicate with other agents,
  As an Agent
  I want to create connections using different transport protocols.
  @T001-RFC0025 @AcceptanceTest @DIDExchangeConnection @Transport_Http @critical
  Scenario Outline: Create DIDExchange connection between two agents with overlapping transports -- @1.1 DIDExchange connection with both agents using HTTP for inbound and outbound transport  # features/0025-didcomm-transports.feature:23
    Given we have "2" agents                                                                                                                                                                    # features/steps/0160-connection.py:22 0.001s
      | name | role      |
      | Acme | responder |
      | Bob  | requester |
    And "Acme" is running with parameters "{"inbound_transports": ["http"], "outbound_transports": ["http"] }"                                                                                  # features/steps/0044-mime-types.py:12 7.832s
    And "Bob" is running with parameters "{"inbound_transports": ["http"], "outbound_transports": ["http"] }"                                                                                   # features/steps/0044-mime-types.py:12 7.751s
    When "Acme" and "Bob" create a new connection                                                                                                                                               # features/steps/0160-connection.py:360 1.883s
      Assertion Failed: FAILED SUB-STEP: When "Acme" and "Bob" create a new didexchange connection
      Substep info: Assertion Failed: FAILED SUB-STEP: And "Acme" sends a response to "Bob"
      Substep info: Assertion Failed: resp_status 400 is not 200; 400: Connection not in state request.
...

Failing scenarios:
  features/0025-didcomm-transports.feature:23  Create DIDExchange connection between two agents with overlapping transports -- @1.1 DIDExchange connection with both agents using HTTP for inbound and outbound transport

0 features passed, 1 failed, 13 skipped
0 scenarios passed, 1 failed, 152 skipped
3 steps passed, 1 failed, 1316 skipped, 0 undefined
Took 0m17.468s
tdiesler commented 2 years ago

In .logs/acme_agent.log I see ...

./manage test -d acapy -t @T001-RFC0025 -t ~@Transport_Ws

[?7hData passed to backchannel by test for operation: /out-of-band/ {'use_public_did': False}
[?7hData translated by backchannel to send to agent for operation: /out-of-band/create-invitation?multi_use=false {'use_public_did': False, 'attachments': [], 'handshake_protocols': ['did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/didexchange/1.0']}
[?7hPassing webhook payload to handler handle_connections
[?7hReceived a Connection Webhook message: {"rfc23_state": "invitation-sent", "connection_id": "dde4de20-201a-4da9-9e6d-ae485caca5ed", "connection_protocol": "didexchange/1.0", "updated_at": "2022-10-27T12:12:07.891487Z", "invitation_mode": "once", "invitation_msg_id": "e2aa9744-787e-47e2-83b8-ea9265b456fa", "created_at": "2022-10-27T12:12:07.891487Z", "their_role": "invitee", "accept": "manual", "routing_state": "none", "invitation_key": "McQZ1rAWpx5GbsgfLNcfU6gcfKYHjSiThut8xAyKCRb", "state": "invitation"}
[?7h200 {"invi_msg_id": "e2aa9744-787e-47e2-83b8-ea9265b456fa", "oob_id": "8f275646-70f4-4de7-994b-ee63570b427a", "invitation": {"@type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/out-of-band/1.0/invitation", "@id": "e2aa9744-787e-47e2-83b8-ea9265b456fa", "handshake_protocols": ["did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/didexchange/1.0"], "label": "aca-py.Acme", "services": [{"id": "#inline", "type": "did-communication", "recipientKeys": ["did:key:z6MkeosT9G6brNSYP6iPLuLTWZegSEbPhch59ipoyE8zERCy"], "serviceEndpoint": "http://host.docker.internal:9021"}]}, "trace": false, "invitation_url": "http://host.docker.internal:9021?oob=eyJAdHlwZSI6ICJkaWQ6c292OkJ6Q2JzTlloTXJqSGlxWkRUVUFTSGc7c3BlYy9vdXQtb2YtYmFuZC8xLjAvaW52aXRhdGlvbiIsICJAaWQiOiAiZTJhYTk3NDQtNzg3ZS00N2UyLTgzYjgtZWE5MjY1YjQ1NmZhIiwgImhhbmRzaGFrZV9wcm90b2NvbHMiOiBbImRpZDpzb3Y6QnpDYnNOWWhNcmpIaXFaRFRVQVNIZztzcGVjL2RpZGV4Y2hhbmdlLzEuMCJdLCAibGFiZWwiOiAiYWNhLXB5LkFjbWUiLCAic2VydmljZXMiOiBbeyJpZCI6ICIjaW5saW5lIiwgInR5cGUiOiAiZGlkLWNvbW11bmljYXRpb24iLCAicmVjaXBpZW50S2V5cyI6IFsiZGlkOmtleTp6Nk1rZW9zVDlHNmJyTlNZUDZpUEx1TFRXWmVnU0ViUGhjaDU5aXBveUU4ekVSQ3kiXSwgInNlcnZpY2VFbmRwb2ludCI6ICJodHRwOi8vaG9zdC5kb2NrZXIuaW50ZXJuYWw6OTAyMSJ9XX0=", "state": "initial"}
[?7hPassing webhook payload to handler handle_out_of_band
[?7hError: agent aca-py.Acme has no method handle_out_of_band to handle webhook on topic out_of_band
[?7hPassing webhook payload to handler handle_out_of_band
[?7hError: agent aca-py.Acme has no method handle_out_of_band to handle webhook on topic out_of_band
2022-10-27 12:12:09,600 aries_cloudagent.admin.server ERROR Handler error with exception: Connection not in state request.

=================
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/aries_cloudagent/protocols/didexchange/v1_0/routes.py", line 292, in didx_accept_request
    mediation_id=mediation_id,
  File "/usr/local/lib/python3.7/site-packages/aries_cloudagent/protocols/didexchange/v1_0/manager.py", line 604, in create_response
    f"Connection not in state {ConnRecord.State.REQUEST.rfc23}"
aries_cloudagent.protocols.didexchange.v1_0.manager.DIDXManagerError: Connection not in state request

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

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/aries_cloudagent/admin/server.py", line 170, in ready_middleware
    return await handler(request)
  File "/usr/local/lib/python3.7/site-packages/aries_cloudagent/admin/server.py", line 207, in debug_middleware
    return await handler(request)
  File "/usr/local/lib/python3.7/site-packages/aiohttp_apispec/middlewares.py", line 45, in validation_middleware
    return await handler(request)
  File "/usr/local/lib/python3.7/site-packages/aries_cloudagent/admin/server.py", line 395, in setup_context
    return await task
  File "/usr/local/lib/python3.7/asyncio/futures.py", line 263, in __await__
    yield self  # This tells Task to wait for completion.
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 318, in __wakeup
    future.result()
  File "/usr/local/lib/python3.7/asyncio/futures.py", line 181, in result
    raise self._exception
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 249, in __step
    result = coro.send(None)
  File "/usr/local/lib/python3.7/site-packages/aries_cloudagent/protocols/didexchange/v1_0/routes.py", line 298, in didx_accept_request
    raise web.HTTPBadRequest(reason=err.roll_up) from err
aiohttp.web_exceptions.HTTPBadRequest: Connection not in state request.

and in .logs/request.log

Req: POST http://0.0.0.0:9020/agent/command/out-of-band/send-invitation-message/ {"data": {"use_public_did": false}}
Res: 200 {"invi_msg_id": "e2aa9744-787e-47e2-83b8-ea9265b456fa", "invitation": {"@id": "e2aa9744-787e-47e2-83b8-ea9265b456fa", "@type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/out-of-band/1.0/invitation", "handshake_protocols": ["did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/didexchange/1.0"], "label": "aca-py.Acme", "services": [{"id": "#inline", "type": "did-communication", "recipientKeys": ["did:key:z6MkeosT9G6brNSYP6iPLuLTWZegSEbPhch59ipoyE8zERCy"], "serviceEndpoint": "http://host.docker.internal:9021"}]}, "invitation_url": "http://host.docker.internal:9021?oob=eyJAdHlwZSI6ICJkaWQ6c292OkJ6Q2JzTlloTXJqSGlxWkRUVUFTSGc7c3BlYy9vdXQtb2YtYmFuZC8xLjAvaW52aXRhdGlvbiIsICJAaWQiOiAiZTJhYTk3NDQtNzg3ZS00N2UyLTgzYjgtZWE5MjY1YjQ1NmZhIiwgImhhbmRzaGFrZV9wcm90b2NvbHMiOiBbImRpZDpzb3Y6QnpDYnNOWWhNcmpIaXFaRFRVQVNIZztzcGVjL2RpZGV4Y2hhbmdlLzEuMCJdLCAibGFiZWwiOiAiYWNhLXB5LkFjbWUiLCAic2VydmljZXMiOiBbeyJpZCI6ICIjaW5saW5lIiwgInR5cGUiOiAiZGlkLWNvbW11bmljYXRpb24iLCAicmVjaXBpZW50S2V5cyI6IFsiZGlkOmtleTp6Nk1rZW9zVDlHNmJyTlNZUDZpUEx1TFRXWmVnU0ViUGhjaDU5aXBveUU4ekVSQ3kiXSwgInNlcnZpY2VFbmRwb2ludCI6ICJodHRwOi8vaG9zdC5kb2NrZXIuaW50ZXJuYWw6OTAyMSJ9XX0=", "oob_id": "8f275646-70f4-4de7-994b-ee63570b427a", "state": "invitation-sent", "trace": false}
-----
Req: GET http://0.0.0.0:9020/agent/response/did-exchange/e2aa9744-787e-47e2-83b8-ea9265b456fa 
Res: 200 {"accept": "manual", "connection_id": "dde4de20-201a-4da9-9e6d-ae485caca5ed", "connection_protocol": "didexchange/1.0", "created_at": "2022-10-27T12:12:07.891487Z", "invitation_key": "McQZ1rAWpx5GbsgfLNcfU6gcfKYHjSiThut8xAyKCRb", "invitation_mode": "once", "invitation_msg_id": "e2aa9744-787e-47e2-83b8-ea9265b456fa", "rfc23_state": "invitation-sent", "routing_state": "none", "state": "invitation-sent", "their_role": "invitee", "updated_at": "2022-10-27T12:12:07.891487Z"}
-----
Req: POST http://0.0.0.0:9030/agent/command/out-of-band/receive-invitation/ {"data": {"@id": "e2aa9744-787e-47e2-83b8-ea9265b456fa", "@type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/out-of-band/1.0/invitation", "handshake_protocols": ["did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/didexchange/1.0"], "label": "aca-py.Acme", "services": [{"id": "#inline", "type": "did-communication", "recipientKeys": ["did:key:z6MkeosT9G6brNSYP6iPLuLTWZegSEbPhch59ipoyE8zERCy"], "serviceEndpoint": "http://host.docker.internal:9021"}], "use_existing_connection": false}}
Res: 200 {"accept": "manual", "connection_id": "b9a538b9-5148-4a90-b4c6-0619867f8f10", "connection_protocol": "didexchange/1.0", "created_at": "2022-10-27T12:12:08.170364Z", "invitation_key": "McQZ1rAWpx5GbsgfLNcfU6gcfKYHjSiThut8xAyKCRb", "invitation_mode": "once", "invitation_msg_id": "e2aa9744-787e-47e2-83b8-ea9265b456fa", "rfc23_state": "invitation-received", "routing_state": "none", "state": "invitation-received", "their_label": "aca-py.Acme", "their_role": "inviter", "updated_at": "2022-10-27T12:12:08.170364Z"}
-----
Req: POST http://0.0.0.0:9030/agent/command/did-exchange/send-request/ {"id": "b9a538b9-5148-4a90-b4c6-0619867f8f10"}
Res: 200 {"accept": "manual", "connection_id": "b9a538b9-5148-4a90-b4c6-0619867f8f10", "connection_protocol": "didexchange/1.0", "created_at": "2022-10-27T12:12:08.170364Z", "invitation_key": "McQZ1rAWpx5GbsgfLNcfU6gcfKYHjSiThut8xAyKCRb", "invitation_mode": "once", "invitation_msg_id": "e2aa9744-787e-47e2-83b8-ea9265b456fa", "my_did": "2uFcSCfcBLFKfChBpCuFrX", "request_id": "fbaed7e1-c561-42e7-81b3-b181ab60abce", "rfc23_state": "request-sent", "routing_state": "none", "state": "request-sent", "their_label": "aca-py.Acme", "their_role": "inviter", "updated_at": "2022-10-27T12:12:08.478410Z"}
-----
Req: POST http://0.0.0.0:9020/agent/command/did-exchange/send-response/ {"id": "dde4de20-201a-4da9-9e6d-ae485caca5ed"}
Res: 400 400: Connection not in state request.

Could you please share your log output? Is this perhaps a timing issue? It's a blocker for me, because if it doesn't work with acapy I can't get it to work with camel either.

tdiesler commented 2 years ago

Indeed, this works on Rocky9 Linux

tdiesler commented 2 years ago

... and now on MacOS M2 with DockerDesktop 4.13.1 as well. Perhaps it was caused by the deprecated usage of docker-compose V1. Anyway, with docker compose V2 it works - closing for now

swcurran commented 2 years ago

Sorry for the lack of response -- I missed the request for logs.