search

hyperledger / aries-cloudagent-python

Hyperledger Aries Cloud Agent Python (ACA-Py) is a foundation for building decentralized identity applications and services running in non-mobile environments.
https://wiki.hyperledger.org/display/aries
Apache License 2.0
404 stars 511 forks source link

Basic message does not return response beside {} #1311

Closed phearaeun closed 3 years ago

phearaeun commented 3 years ago

I followed This thread and everything works very well but the last suggestion to send basic message in order to change status from sent to active does not work. The basic message returns only {} (200 status code).

Any help is appreciated.

Thanks

phearaeun commented 3 years ago

Updated: Even the state has not been updated to active, but we can still issue credentials based on the generated connection id. Is it the intended behavior?

Fethbita commented 3 years ago

If you have used out-of-band and did-exchange to create a connection, the state should automatically change to active once the establishment is completed. However if you use the older connections endpoints to create a connection, sending either a trust ping or basic message should set the state to active. The return code aside, if you check your connections after sending a basic-message, what is the rfc23_state and the state of the connection?

phearaeun commented 3 years ago

I used old connections with auto-accept not oob. Once invited and accepted automatically, I tried to send basic message. After the message is sent, the state is not updated but I can still issue credentials. Here is the connection status:

Issuer: { "results": [ { "their_label": "yy", "invitation_mode": "once", "invitation_key": "ZUeZ9aXeNodBiZ3BMDLdkB5MVzfEoBjcaxi85DFzhjh", "connection_protocol": "connections/1.0", "updated_at": "2021-07-16 03:23:04.295995Z", "my_did": "NUgGMRXMJfNhCmwiJsH5ib", "state": "response", "created_at": "2021-07-16 03:11:59.270842Z", "their_did": "HcPDtTYAx7WHjNj1vxpYpf", "their_role": "invitee", "routing_state": "none", "connection_id": "dcde2da1-8121-42f4-a82e-8f0ba97b8fb7", "accept": "auto", "rfc23_state": "response-sent" } ] }

Holder: { "results": [ { "state": "request", "routing_state": "none", "invitation_key": "ZUeZ9aXeNodBiZ3BMDLdkB5MVzfEoBjcaxi85DFzhjh", "rfc23_state": "request-sent", "connection_protocol": "connections/1.0", "their_role": "inviter", "connection_id": "522c4561-d4a2-4222-a910-c5f22d12a18e", "request_id": "b5951ff0-2302-4fe5-9e2a-82fc8c19263f", "invitation_msg_id": "4e7f0f12-53c9-420d-b886-d3b8b28dd317", "my_did": "HcPDtTYAx7WHjNj1vxpYpf", "their_label": "zz", "invitation_mode": "once", "accept": "auto", "updated_at": "2021-07-16 03:14:52.245804Z", "created_at": "2021-07-16 03:14:51.221431Z" } ] }

swcurran commented 3 years ago

@ianco can you please take a look at this? Thanks!

ianco commented 3 years ago

I tried running with the latest version of aca-py in the main branch and everything seems to work.

I ran a local von-network with ./manage start 192.168.0.22 --logs (runs a network on my local IP)

I started the alice and faber agents using the following scripts in the aries-cloudagent-python/demo directory (note I ran these in 2 separate shells):

./faber-local.sh
./alice-local.sh

These start up with the connection "auto" flags (auto accept invitations and connection requests)

I generated an invitation with faber and accepted it with alice, and the connection was in active status in both agents.

ianco commented 3 years ago

OK I noticed that the two scripts above included --auto-ping-connections, which explains why they went into active status.

So I removed this flag, tried again, and now the connections ended up in response status

However when I send a basic message from faber to alice then it bumped the connections into active status

ianco commented 3 years ago

@phearaeun can you confirm exactly what you're doing? What version of aca-py, how are you starting the agents, which agent is initiating the connection invitation and basic message?

phearaeun commented 3 years ago

Thank you for the follow-up.

I read the demo code to understand how it works and then I started to create my own controller. I run everything locally. No docker used.

I pulled the latest update from aries_cloudagent repo (main branch).

I have created my own controller to manage the agents. The controller creates agent service by python -m aries_cloudagent <args>. This controller is executed from web interface. It creates a new subprocess for each agent.

My general commands to execute:

commands: list = [
        '--label %s' % agent.agent,
        '--endpoint %s' % agent.endpoint,
        '--admin %s' % agent.admin_url,
        '--admin-insecure-mode',
        '--wallet-name %s' % agent.agent,
        '--wallet-key %s' % agent.key,
        '--wallet-type indy',
        '--seed %s' % seed,
        '--auto-provision',
        '--trace',
        '--inbound-transport %s' % agent.inbound_transport,
        '--outbound-transport http',
        '--public-invites',
        '--genesis-url %s' % agent.genesis,
        '--auto-ping-connection',
        '--auto-respond-messages',
        '--auto-accept-invites',
        '--auto-accept-requests',
        '--auto-store-credential',
        '--webhook-url %s' % agent.webhook_url,
        '--monitor-ping',
        '--debug-connection'
    ]

The two agents below use the same commands above but only issuer has to register DID.

Here what I have:

  1. Agent 1 created as issuer
ython3 -m aries_cloudagent start --label Issuer --endpoint http://localhost:8020 --admin 0.0.0.0 8030 --admin-insecure-mode --wallet-name Issuer --wallet-key issuer --wallet-type indy --seed issuer00000000000000000000000000 --auto-provision --trace --inbound-transport http 0.0.0.0 8031 --outbound-transport http --public-invites --genesis-url http://localhost:9000/genesis --auto-ping-connection --auto-respond-messages --auto-accept-invites --auto-accept-requests --auto-store-credential --webhook-url http://08cdb0922cf7.ngrok.io --monitor-ping --debug-connection
  1. Agent 2 created as holder
python3 -m aries_cloudagent start --label holder --endpoint http://localhost:9020 --admin 0.0.0.0 9030 --admin-insecure-mode --wallet-name holder --wallet-key holder --wallet-type indy --seed holder00000000000000000000000000 --auto-provision --trace --inbound-transport http 0.0.0.0 9031 --outbound-transport http --public-invites --genesis-url http://localhost:9000/genesis --auto-ping-connection --auto-respond-messages --auto-accept-invites --auto-accept-requests --auto-store-credential --webhook-url http://08cdb0922cf7.ngrok.io --monitor-ping --debug-connection
  1. Agent 1 creates an invitation (auto accept) --> POST /connections/create-invitation
{
  "connection_id": "9189f124-f6c4-4564-a3b5-2072499ada67",
  "invitation": {
    "@type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/connections/1.0/invitation",
    "@id": "c85aa6b6-8437-4cd1-b092-9458e60cfdec",
    "recipientKeys": [
      "DfH7YsPbBMnEthgRyTu39XXpRBgSDXNZkD9cnvH2z6xZ"
    ],
    "serviceEndpoint": "http://localhost:8031",
    "label": "Issuer"
  },
  "invitation_url": "http://localhost:8031?c_i=eyJAdHlwZSI6ICJkaWQ6c292OkJ6Q2JzTlloTXJqSGlxWkRUVUFTSGc7c3BlYy9jb25uZWN0aW9ucy8xLjAvaW52aXRhdGlvbiIsICJAaWQiOiAiYzg1YWE2YjYtODQzNy00Y2QxLWIwOTItOTQ1OGU2MGNmZGVjIiwgInJlY2lwaWVudEtleXMiOiBbIkRmSDdZc1BiQk1uRXRoZ1J5VHUzOVhYcFJCZ1NEWE5aa0Q5Y252SDJ6NnhaIl0sICJzZXJ2aWNlRW5kcG9pbnQiOiAiaHR0cDovL2xvY2FsaG9zdDo4MDMxIiwgImxhYmVsIjogIklzc3VlciJ9"
}
{
  "results": [
    {
      "state": "invitation",
      "created_at": "2021-07-17 04:21:29.624956Z",
      "rfc23_state": "invitation-sent",
      "connection_protocol": "connections/1.0",
      "connection_id": "9189f124-f6c4-4564-a3b5-2072499ada67",
      "accept": "auto",
      "their_role": "invitee",
      "invitation_mode": "once",
      "updated_at": "2021-07-17 04:21:29.624956Z",
      "routing_state": "none",
      "invitation_key": "DfH7YsPbBMnEthgRyTu39XXpRBgSDXNZkD9cnvH2z6xZ"
    }
  ]
}

After invitation accepted:

  "results": [
    {
      "state": "response",
      "created_at": "2021-07-17 04:21:29.624956Z",
      "their_label": "holder",
      "rfc23_state": "response-sent",
      "connection_protocol": "connections/1.0",
      "my_did": "P1A6y9tTPP2BuPrt7KvnpB",
      "connection_id": "9189f124-f6c4-4564-a3b5-2072499ada67",
      "accept": "auto",
      "their_role": "invitee",
      "invitation_mode": "once",
      "updated_at": "2021-07-17 04:25:49.731053Z",
      "their_did": "7EbqewJQsLUWfSQtunjUfv",
      "routing_state": "none",
      "invitation_key": "DfH7YsPbBMnEthgRyTu39XXpRBgSDXNZkD9cnvH2z6xZ"
    }
  ]
}
  1. Agent 2 accepts invitation --> POST /connections/receive-invitation --> POST /connections/{connection_id}/accept-invitation?my_endpoint={endpoint}

{
  "results": [
    {
      "request_id": "2c78cece-1dca-44f1-b4f1-4cfb68a983a6",
      "invitation_key": "DfH7YsPbBMnEthgRyTu39XXpRBgSDXNZkD9cnvH2z6xZ",
      "connection_protocol": "connections/1.0",
      "state": "request",
      "my_did": "7EbqewJQsLUWfSQtunjUfv",
      "updated_at": "2021-07-17 04:25:48.927946Z",
      "their_label": "Issuer",
      "rfc23_state": "request-sent",
      "their_role": "inviter",
      "invitation_msg_id": "c85aa6b6-8437-4cd1-b092-9458e60cfdec",
      "created_at": "2021-07-17 04:25:47.901979Z",
      "accept": "auto",
      "routing_state": "none",
      "invitation_mode": "once",
      "connection_id": "e427f8f0-fff7-494c-909c-7700b700c4f8"
    }
  ]
}

  1. The new connection id created, which can be found at webhook or /connections (But the rfc23_state is still reponse-sent)

  2. Agent 1 tries to send basicmessage (But the status never changes)

    curl -X POST "http://localhost:8030/connections/9189f124-f6c4-4564-a3b5-2072499ada67/send-message" -H "accept: application/json" -H "Content-Type: application/json" -d "{ \"content\": \"Hello\"}"

  3. Agent 1 trying to issue credentials

    POST /issue-credential-2.0/send-offer

Default test schema

schema_name: str = 'Profile'
schema_attrs: list = ['name', 'sex', 'age']

Results:

{
    "state": "offer-sent",
    "created_at": "2021-07-17 04:31:41.588649Z",
    "cred_preview": {
        "@type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/issue-credential/2.0/credential-preview",
        "attributes": [
            {
                "name": "age",
                "value": "30"
            },
            {
                "name": "name",
                "value": "XYZ"
            },
            {
                "name": "sex",
                "value": "M"
            }
        ]
    },
    "role": "issuer",
    "thread_id": "19b852b2-933b-475e-ac64-0af3e4ea85c3",
    "by_format": {
        "cred_offer": {
            "indy": {
                "schema_id": "VV9pK5ZrLPRwYmotgACPkC:2:Profile:0.0.1",
                "cred_def_id": "VV9pK5ZrLPRwYmotgACPkC:3:CL:8:Profile",
                "key_correctness_proof": {
                    "c": "9797095960454107816335946691171839201930521428662368870925007397056576763947",
                    "xz_cap": "94930498043564657283145881368929934726908865852052399744283262868710328094394318909850607648179691996455895412991438553872010363606380190274036515138894648078351550615146714047664303706338118392911900969235462396863227899352414314981948859624642035462717268410617056153271247794363875589339579434919890099868518822528610925791447056682527205721377687040481026919828375915082493705456394155391111960965441541946664125617873587573222938057117254216207219808649632505820055367906607565989840818359682235518340500556435199553237118303235976759866438522196501640000951297063803562021895646654698242610201168334293223718601264140545171566863188123307510138837191766519452697279653670486474035837779",
                    "xr_cap": [
                        [
                            "master_secret",
                            "216716631696238677578246678664204949511439558623466634081159088404511038116790964151973322753257060510371428642877956243907335939613728898847705211246401787185184431619608266070244553013313156366628402213651607738798443504979259514969288592758213923600827751358062840047772564228764256868044530386095256780797844489143646162220734288818207200166996775671005166809022010931228034531996382504078875717784894432495105410372799754865758026258020581853708152512699201756034083994249073324494983770325464800626391556448807588909837609290591572687951456144146637598234462149287972674359878502363821718717273957641920909888374597256328500207062130767807565948176146650779569747659732036950114222946734"
                        ],
                        [
                            "name",
                            "55920697357525940687636141567730147581561548298999038955861030721292200174575107835483081978852240461628699552697882877007241241445731050461777162274102864815125483511137189222741943889803795495324913102424747025847882025771144410368650452857395466150518085902745589221794226230554232430712034618545847239987742712036335757599712410803446050905227698275381985128096492394502810455308164755113371959459149301186836200872917889177564954562033580977379639566660587285468419436842204709129206963385355253126952339444769821537936646809772493475717070669667533577168515636760858965635878984380641138546061060637703203452617967782189562697855994352411978856124442589563140195993457856927955050975796"
                        ],
                        [
                            "sex",
                            "47440099660929398240233951004340668615101025752300749705845002839156171480943341619790831965057653230406914014097436108223916693905031564757510029911069639553021540644582437685341699379441503868408219612899468765560391736524422786561062207278448029283249871581603731810651827151733066256689734843886926982725972139005130873170760103971145570613001201158223104698908083511654942808690858535287126319946346563617021009220085438306447749507257296430919791627349680770508404106734469127472153784887108401221970874766778023466828348165731730967378206399570593420950075520564678351556474911219270275873232924908864224687934296145834257438020004985798917314105006504188048319779806792669300347668245"
                        ],
                        [
                            "age",
                            "81073182757215974621067855747156245145681128310370484524364530301641831738885671483090023771550584448643281523530659750887835283467133556010453278654165845116134625844723326138996803008832157241734138927179059350118790869415024353537507528808842856946587006260005432506849407362402554116026705601485302370281879048094545449286023180506855086332635794242688243382421270324365901575794767260244115361465722982397414570158015508851114982551712711248608318270965038355938404538817448289101533544767569286680055650583933700173249253216021251050450595471007806956532469160653392022116742668531150930417448579634505308553209257264312587012135932700411659480845169608505582579276745134777986728487210"
                        ]
                    ]
                },
                "nonce": "411363169912772414298065"
            }
        },
        "cred_proposal": {
            "indy": {
                "cred_def_id": "VV9pK5ZrLPRwYmotgACPkC:3:CL:8:Profile"
            }
        }
    },
    "connection_id": "9189f124-f6c4-4564-a3b5-2072499ada67",
    "cred_offer": {
        "@type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/issue-credential/2.0/offer-credential",
        "@id": "19b852b2-933b-475e-ac64-0af3e4ea85c3",
        "~thread": {},
        "comment": "Test issue credential",
        "formats": [
            {
                "attach_id": "indy",
                "format": "hlindy/cred-abstract@v2.0"
            }
        ],
        "offers~attach": [
            {
                "@id": "indy",
                "mime-type": "application/json",
                "data": {
                    "base64": "eyJzY2hlbWFfaWQiOiAiVlY5cEs1WnJMUFJ3WW1vdGdBQ1BrQzoyOlByb2ZpbGU6MC4wLjEiLCAiY3JlZF9kZWZfaWQiOiAiVlY5cEs1WnJMUFJ3WW1vdGdBQ1BrQzozOkNMOjg6UHJvZmlsZSIsICJrZXlfY29ycmVjdG5lc3NfcHJvb2YiOiB7ImMiOiAiOTc5NzA5NTk2MDQ1NDEwNzgxNjMzNTk0NjY5MTE3MTgzOTIwMTkzMDUyMTQyODY2MjM2ODg3MDkyNTAwNzM5NzA1NjU3Njc2Mzk0NyIsICJ4el9jYXAiOiAiOTQ5MzA0OTgwNDM1NjQ2NTcyODMxNDU4ODEzNjg5Mjk5MzQ3MjY5MDg4NjU4NTIwNTIzOTk3NDQyODMyNjI4Njg3MTAzMjgwOTQzOTQzMTg5MDk4NTA2MDc2NDgxNzk2OTE5OTY0NTU4OTU0MTI5OTE0Mzg1NTM4NzIwMTAzNjM2MDYzODAxOTAyNzQwMzY1MTUxMzg4OTQ2NDgwNzgzNTE1NTA2MTUxNDY3MTQwNDc2NjQzMDM3MDYzMzgxMTgzOTI5MTE5MDA5NjkyMzU0NjIzOTY4NjMyMjc4OTkzNTI0MTQzMTQ5ODE5NDg4NTk2MjQ2NDIwMzU0NjI3MTcyNjg0MTA2MTcwNTYxNTMyNzEyNDc3OTQzNjM4NzU1ODkzMzk1Nzk0MzQ5MTk4OTAwOTk4Njg1MTg4MjI1Mjg2MTA5MjU3OTE0NDcwNTY2ODI1MjcyMDU3MjEzNzc2ODcwNDA0ODEwMjY5MTk4MjgzNzU5MTUwODI0OTM3MDU0NTYzOTQxNTUzOTExMTE5NjA5NjU0NDE1NDE5NDY2NjQxMjU2MTc4NzM1ODc1NzMyMjI5MzgwNTcxMTcyNTQyMTYyMDcyMTk4MDg2NDk2MzI1MDU4MjAwNTUzNjc5MDY2MDc1NjU5ODk4NDA4MTgzNTk2ODIyMzU1MTgzNDA1MDA1NTY0MzUxOTk1NTMyMzcxMTgzMDMyMzU5NzY3NTk4NjY0Mzg1MjIxOTY1MDE2NDAwMDA5NTEyOTcwNjM4MDM1NjIwMjE4OTU2NDY2NTQ2OTgyNDI2MTAyMDExNjgzMzQyOTMyMjM3MTg2MDEyNjQxNDA1NDUxNzE1NjY4NjMxODgxMjMzMDc1MTAxMzg4MzcxOTE3NjY1MTk0NTI2OTcyNzk2NTM2NzA0ODY0NzQwMzU4Mzc3NzkiLCAieHJfY2FwIjogW1sibWFzdGVyX3NlY3JldCIsICIyMTY3MTY2MzE2OTYyMzg2Nzc1NzgyNDY2Nzg2NjQyMDQ5NDk1MTE0Mzk1NTg2MjM0NjY2MzQwODExNTkwODg0MDQ1MTEwMzgxMTY3OTA5NjQxNTE5NzMzMjI3NTMyNTcwNjA1MTAzNzE0Mjg2NDI4Nzc5NTYyNDM5MDczMzU5Mzk2MTM3Mjg4OTg4NDc3MDUyMTEyNDY0MDE3ODcxODUxODQ0MzE2MTk2MDgyNjYwNzAyNDQ1NTMwMTMzMTMxNTYzNjY2Mjg0MDIyMTM2NTE2MDc3Mzg3OTg0NDM1MDQ5NzkyNTk1MTQ5NjkyODg1OTI3NTgyMTM5MjM2MDA4Mjc3NTEzNTgwNjI4NDAwNDc3NzI1NjQyMjg3NjQyNTY4NjgwNDQ1MzAzODYwOTUyNTY3ODA3OTc4NDQ0ODkxNDM2NDYxNjIyMjA3MzQyODg4MTgyMDcyMDAxNjY5OTY3NzU2NzEwMDUxNjY4MDkwMjIwMTA5MzEyMjgwMzQ1MzE5OTYzODI1MDQwNzg4NzU3MTc3ODQ4OTQ0MzI0OTUxMDU0MTAzNzI3OTk3NTQ4NjU3NTgwMjYyNTgwMjA1ODE4NTM3MDgxNTI1MTI2OTkyMDE3NTYwMzQwODM5OTQyNDkwNzMzMjQ0OTQ5ODM3NzAzMjU0NjQ4MDA2MjYzOTE1NTY0NDg4MDc1ODg5MDk4Mzc2MDkyOTA1OTE1NzI2ODc5NTE0NTYxNDQxNDY2Mzc1OTgyMzQ0NjIxNDkyODc5NzI2NzQzNTk4Nzg1MDIzNjM4MjE3MTg3MTcyNzM5NTc2NDE5MjA5MDk4ODgzNzQ1OTcyNTYzMjg1MDAyMDcwNjIxMzA3Njc4MDc1NjU5NDgxNzYxNDY2NTA3Nzk1Njk3NDc2NTk3MzIwMzY5NTAxMTQyMjI5NDY3MzQiXSwgWyJuYW1lIiwgIjU1OTIwNjk3MzU3NTI1OTQwNjg3NjM2MTQxNTY3NzMwMTQ3NTgxNTYxNTQ4Mjk4OTk5MDM4OTU1ODYxMDMwNzIxMjkyMjAwMTc0NTc1MTA3ODM1NDgzMDgxOTc4ODUyMjQwNDYxNjI4Njk5NTUyNjk3ODgyODc3MDA3MjQxMjQxNDQ1NzMxMDUwNDYxNzc3MTYyMjc0MTAyODY0ODE1MTI1NDgzNTExMTM3MTg5MjIyNzQxOTQzODg5ODAzNzk1NDk1MzI0OTEzMTAyNDI0NzQ3MDI1ODQ3ODgyMDI1NzcxMTQ0NDEwMzY4NjUwNDUyODU3Mzk1NDY2MTUwNTE4MDg1OTAyNzQ1NTg5MjIxNzk0MjI2MjMwNTU0MjMyNDMwNzEyMDM0NjE4NTQ1ODQ3MjM5OTg3NzQyNzEyMDM2MzM1NzU3NTk5NzEyNDEwODAzNDQ2MDUwOTA1MjI3Njk4Mjc1MzgxOTg1MTI4MDk2NDkyMzk0NTAyODEwNDU1MzA4MTY0NzU1MTEzMzcxOTU5NDU5MTQ5MzAxMTg2ODM2MjAwODcyOTE3ODg5MTc3NTY0OTU0NTYyMDMzNTgwOTc3Mzc5NjM5NTY2NjYwNTg3Mjg1NDY4NDE5NDM2ODQyMjA0NzA5MTI5MjA2OTYzMzg1MzU1MjUzMTI2OTUyMzM5NDQ0NzY5ODIxNTM3OTM2NjQ2ODA5NzcyNDkzNDc1NzE3MDcwNjY5NjY3NTMzNTc3MTY4NTE1NjM2NzYwODU4OTY1NjM1ODc4OTg0MzgwNjQxMTM4NTQ2MDYxMDYwNjM3NzAzMjAzNDUyNjE3OTY3NzgyMTg5NTYyNjk3ODU1OTk0MzUyNDExOTc4ODU2MTI0NDQyNTg5NTYzMTQwMTk1OTkzNDU3ODU2OTI3OTU1MDUwOTc1Nzk2Il0sIFsic2V4IiwgIjQ3NDQwMDk5NjYwOTI5Mzk4MjQwMjMzOTUxMDA0MzQwNjY4NjE1MTAxMDI1NzUyMzAwNzQ5NzA1ODQ1MDAyODM5MTU2MTcxNDgwOTQzMzQxNjE5NzkwODMxOTY1MDU3NjUzMjMwNDA2OTE0MDE0MDk3NDM2MTA4MjIzOTE2NjkzOTA1MDMxNTY0NzU3NTEwMDI5OTExMDY5NjM5NTUzMDIxNTQwNjQ0NTgyNDM3Njg1MzQxNjk5Mzc5NDQxNTAzODY4NDA4MjE5NjEyODk5NDY4NzY1NTYwMzkxNzM2NTI0NDIyNzg2NTYxMDYyMjA3Mjc4NDQ4MDI5MjgzMjQ5ODcxNTgxNjAzNzMxODEwNjUxODI3MTUxNzMzMDY2MjU2Njg5NzM0ODQzODg2OTI2OTgyNzI1OTcyMTM5MDA1MTMwODczMTcwNzYwMTAzOTcxMTQ1NTcwNjEzMDAxMjAxMTU4MjIzMTA0Njk4OTA4MDgzNTExNjU0OTQyODA4NjkwODU4NTM1Mjg3MTI2MzE5OTQ2MzQ2NTYzNjE3MDIxMDA5MjIwMDg1NDM4MzA2NDQ3NzQ5NTA3MjU3Mjk2NDMwOTE5NzkxNjI3MzQ5NjgwNzcwNTA4NDA0MTA2NzM0NDY5MTI3NDcyMTUzNzg0ODg3MTA4NDAxMjIxOTcwODc0NzY2Nzc4MDIzNDY2ODI4MzQ4MTY1NzMxNzMwOTY3Mzc4MjA2Mzk5NTcwNTkzNDIwOTUwMDc1NTIwNTY0Njc4MzUxNTU2NDc0OTExMjE5MjcwMjc1ODczMjMyOTI0OTA4ODY0MjI0Njg3OTM0Mjk2MTQ1ODM0MjU3NDM4MDIwMDA0OTg1Nzk4OTE3MzE0MTA1MDA2NTA0MTg4MDQ4MzE5Nzc5ODA2NzkyNjY5MzAwMzQ3NjY4MjQ1Il0sIFsiYWdlIiwgIjgxMDczMTgyNzU3MjE1OTc0NjIxMDY3ODU1NzQ3MTU2MjQ1MTQ1NjgxMTI4MzEwMzcwNDg0NTI0MzY0NTMwMzAxNjQxODMxNzM4ODg1NjcxNDgzMDkwMDIzNzcxNTUwNTg0NDQ4NjQzMjgxNTIzNTMwNjU5NzUwODg3ODM1MjgzNDY3MTMzNTU2MDEwNDUzMjc4NjU0MTY1ODQ1MTE2MTM0NjI1ODQ0NzIzMzI2MTM4OTk2ODAzMDA4ODMyMTU3MjQxNzM0MTM4OTI3MTc5MDU5MzUwMTE4NzkwODY5NDE1MDI0MzUzNTM3NTA3NTI4ODA4ODQyODU2OTQ2NTg3MDA2MjYwMDA1NDMyNTA2ODQ5NDA3MzYyNDAyNTU0MTE2MDI2NzA1NjAxNDg1MzAyMzcwMjgxODc5MDQ4MDk0NTQ1NDQ5Mjg2MDIzMTgwNTA2ODU1MDg2MzMyNjM1Nzk0MjQyNjg4MjQzMzgyNDIxMjcwMzI0MzY1OTAxNTc1Nzk0NzY3MjYwMjQ0MTE1MzYxNDY1NzIyOTgyMzk3NDE0NTcwMTU4MDE1NTA4ODUxMTE0OTgyNTUxNzEyNzExMjQ4NjA4MzE4MjcwOTY1MDM4MzU1OTM4NDA0NTM4ODE3NDQ4Mjg5MTAxNTMzNTQ0NzY3NTY5Mjg2NjgwMDU1NjUwNTgzOTMzNzAwMTczMjQ5MjUzMjE2MDIxMjUxMDUwNDUwNTk1NDcxMDA3ODA2OTU2NTMyNDY5MTYwNjUzMzkyMDIyMTE2NzQyNjY4NTMxMTUwOTMwNDE3NDQ4NTc5NjM0NTA1MzA4NTUzMjA5MjU3MjY0MzEyNTg3MDEyMTM1OTMyNzAwNDExNjU5NDgwODQ1MTY5NjA4NTA1NTgyNTc5Mjc2NzQ1MTM0Nzc3OTg2NzI4NDg3MjEwIl1dfSwgIm5vbmNlIjogIjQxMTM2MzE2OTkxMjc3MjQxNDI5ODA2NSJ9"
                }
            }
        ],
        "credential_preview": {
            "@type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/issue-credential/2.0/credential-preview",
            "attributes": [
                {
                    "name": "age",
                    "value": "30"
                },
                {
                    "name": "name",
                    "value": "XYZ"
                },
                {
                    "name": "sex",
                    "value": "M"
                }
            ]
        }
    },
    "auto_offer": false,
    "cred_proposal": {
        "@type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/issue-credential/2.0/propose-credential",
        "@id": "676b4328-ce7d-420b-bf5d-ba6d1bddb59f",
        "comment": "Test issue credential",
        "filters~attach": [
            {
                "@id": "indy",
                "mime-type": "application/json",
                "data": {
                    "base64": "eyJjcmVkX2RlZl9pZCI6ICJWVjlwSzVackxQUndZbW90Z0FDUGtDOjM6Q0w6ODpQcm9maWxlIn0="
                }
            }
        ],
        "formats": [
            {
                "attach_id": "indy",
                "format": "hlindy/cred-filter@v2.0"
            }
        ],
        "credential_preview": {
            "@type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/issue-credential/2.0/credential-preview",
            "attributes": [
                {
                    "name": "age",
                    "value": "30"
                },
                {
                    "name": "name",
                    "value": "XYZ"
                },
                {
                    "name": "sex",
                    "value": "M"
                }
            ]
        }
    },
    "updated_at": "2021-07-17 04:31:41.588649Z",
    "cred_ex_id": "01337755-c5b4-4a6e-99d8-33f85447f397",
    "auto_remove": true,
    "initiator": "self"
}

I am not sure what I did wrong.

Fethbita commented 3 years ago

You forgot to accept_request from the inviter agent. connections/{con_id}/accept-request endpoint

phearaeun commented 3 years ago

@Fethbita, You are right but even I accept the request, the issue is still the same. And I think this is already auto-accept

phearaeun commented 3 years ago

From the demo in agent_container.py Line: 108 - 115

...
if conn_id == self.connection_id:
            # inviter or invitee:
            if (
                message["rfc23_state"] in ["completed", "response-sent"]
                and not self._connection_ready.done()
            ):
                self.log("Connected")
                self._connection_ready.set_result(True)
...

I think it behaves same as the codes above. If you see the results from the above thread, Sent invitation and the result received after invitation accepted are in this check. This means response-sent rfc23_state is no need to be active but response-sent to be connected.

ianco commented 3 years ago

@phearaeun after you accept the invitation your connection is "state": "request", which means that you have sent the connection request but it has not been accepted.

Not sure why, if you have the auto flags set.

(In fact if you have --auto-accept-invites set then you shouldn't need to call the /accept-invitation endpoint, and in fact this should result in an error as the connection will be in the wrong state if it is auto-accepted.)

Maybe your settings aren't getting set as you expect? Try calling the /status/config endpoint to verify the runtime configuration of each agent, and try fetching the connection after each step (give the agent a couple of seconds to execute any auto steps) to confirm the connection state.

phearaeun commented 3 years ago

@ianco I've sent two requests for accepting the invitation

--> POST /connections/receive-invitation
--> POST /connections/{connection_id}/accept-invitation?my_endpoint={endpoint}

I've no idea why it doesn't produce an error while setting --auto-accept-invites and calling /accept-invitation. It's just working fine.

I tried to do it step by step including checking results in /connections.

I haven't checked at status/config before but recently I checked it and it looked fine. Could you tell me how it looks for status/config to be good?

A recent status/config:

{
  "config": {
    "admin.admin_insecure_mode": true,
    "admin.enabled": true,
    "admin.host": "0.0.0.0",
    "admin.port": "8030",
    "admin.webhook_urls": [
      "http://localhost:5000/webhooks"
    ],
    "admin.admin_client_max_request_size": 1,
    "debug.connections": true,
    "debug.auto_store_credential": true,
    "debug.auto_accept_invites": true,
    "debug.auto_accept_requests": true,
    "debug.auto_respond_messages": true,
    "default_endpoint": "http://localhost:8020",
    "additional_endpoints": [

    ],
    "ledger.genesis_url": "http://localhost:9000/genesis",
    "ledger.keepalive": 5,
    "auto_ping_connection": true,
    "debug.monitor_ping": true,
    "public_invites": true,
    "trace.target": "log",
    "trace.tag": "",
    "trace.enabled": true,
    "trace.label": "Bank",
    "auto_provision": true,
    "transport.inbound_configs": [
      [
        "http",
        "0.0.0.0",
        "8031"
      ]
    ],
    "transport.outbound_configs": [
      "http"
    ],
    "transport.outbound_queue_prefix": "acapy",
    "transport.outbound_queue_class": "aries_cloudagent.transport.outbound.queue.redis:RedisOutboundQueue",
    "transport.enable_undelivered_queue": false,
    "default_label": "Bank",
    "transport.max_message_size": 2097152,
    "transport.max_outbound_retry": 4,
    "wallet.name": "Bank",
    "wallet.storage_type": "default",
    "wallet.type": "indy",
    "ledger.read_only": false,
    "ledger.genesis_transactions": "{\"reqSignature\":{},\"txn\":{\"data\":{\"data\":{\"alias\":\"Node1\",\"blskey\":\"4N8aUNHSgjQVgkpm8nhNEfDf6txHznoYREg9kirmJrkivgL4oSEimFF6nsQ6M41QvhM2Z33nves5vfSn9n1UwNFJBYtWVnHYMATn76vLuL3zU88KyeAYcHfsih3He6UHcXDxcaecHVz6jhCYz1P2UZn2bDVruL5wXpehgBfBaLKm3Ba\",\"blskey_pop\":\"RahHYiCvoNCtPTrVtP7nMC5eTYrsUA8WjXbdhNc8debh1agE9bGiJxWBXYNFbnJXoXhWFMvyqhqhRoq737YQemH5ik9oL7R4NTTCz2LEZhkgLJzB3QRQqJyBNyv7acbdHrAT8nQ9UkLbaVL9NBpnWXBTw4LEMePaSHEw66RzPNdAX1\",\"client_ip\":\"172.17.0.1\",\"client_port\":9702,\"node_ip\":\"172.17.0.1\",\"node_port\":9701,\"services\":[\"VALIDATOR\"]},\"dest\":\"Gw6pDLhcBcoQesN72qfotTgFa7cbuqZpkX3Xo6pLhPhv\"},\"metadata\":{\"from\":\"Th7MpTaRZVRYnPiabds81Y\"},\"type\":\"0\"},\"txnMetadata\":{\"seqNo\":1,\"txnId\":\"fea82e10e894419fe2bea7d96296a6d46f50f93f9eeda954ec461b2ed2950b62\"},\"ver\":\"1\"}\n{\"reqSignature\":{},\"txn\":{\"data\":{\"data\":{\"alias\":\"Node2\",\"blskey\":\"37rAPpXVoxzKhz7d9gkUe52XuXryuLXoM6P6LbWDB7LSbG62Lsb33sfG7zqS8TK1MXwuCHj1FKNzVpsnafmqLG1vXN88rt38mNFs9TENzm4QHdBzsvCuoBnPH7rpYYDo9DZNJePaDvRvqJKByCabubJz3XXKbEeshzpz4Ma5QYpJqjk\",\"blskey_pop\":\"Qr658mWZ2YC8JXGXwMDQTzuZCWF7NK9EwxphGmcBvCh6ybUuLxbG65nsX4JvD4SPNtkJ2w9ug1yLTj6fgmuDg41TgECXjLCij3RMsV8CwewBVgVN67wsA45DFWvqvLtu4rjNnE9JbdFTc1Z4WCPA3Xan44K1HoHAq9EVeaRYs8zoF5\",\"client_ip\":\"172.17.0.1\",\"client_port\":9704,\"node_ip\":\"172.17.0.1\",\"node_port\":9703,\"services\":[\"VALIDATOR\"]},\"dest\":\"8ECVSk179mjsjKRLWiQtssMLgp6EPhWXtaYyStWPSGAb\"},\"metadata\":{\"from\":\"EbP4aYNeTHL6q385GuVpRV\"},\"type\":\"0\"},\"txnMetadata\":{\"seqNo\":2,\"txnId\":\"1ac8aece2a18ced660fef8694b61aac3af08ba875ce3026a160acbc3a3af35fc\"},\"ver\":\"1\"}\n{\"reqSignature\":{},\"txn\":{\"data\":{\"data\":{\"alias\":\"Node3\",\"blskey\":\"3WFpdbg7C5cnLYZwFZevJqhubkFALBfCBBok15GdrKMUhUjGsk3jV6QKj6MZgEubF7oqCafxNdkm7eswgA4sdKTRc82tLGzZBd6vNqU8dupzup6uYUf32KTHTPQbuUM8Yk4QFXjEf2Usu2TJcNkdgpyeUSX42u5LqdDDpNSWUK5deC5\",\"blskey_pop\":\"QwDeb2CkNSx6r8QC8vGQK3GRv7Yndn84TGNijX8YXHPiagXajyfTjoR87rXUu4G4QLk2cF8NNyqWiYMus1623dELWwx57rLCFqGh7N4ZRbGDRP4fnVcaKg1BcUxQ866Ven4gw8y4N56S5HzxXNBZtLYmhGHvDtk6PFkFwCvxYrNYjh\",\"client_ip\":\"172.17.0.1\",\"client_port\":9706,\"node_ip\":\"172.17.0.1\",\"node_port\":9705,\"services\":[\"VALIDATOR\"]},\"dest\":\"DKVxG2fXXTU8yT5N7hGEbXB3dfdAnYv1JczDUHpmDxya\"},\"metadata\":{\"from\":\"4cU41vWW82ArfxJxHkzXPG\"},\"type\":\"0\"},\"txnMetadata\":{\"seqNo\":3,\"txnId\":\"7e9f355dffa78ed24668f0e0e369fd8c224076571c51e2ea8be5f26479edebe4\"},\"ver\":\"1\"}\n{\"reqSignature\":{},\"txn\":{\"data\":{\"data\":{\"alias\":\"Node4\",\"blskey\":\"2zN3bHM1m4rLz54MJHYSwvqzPchYp8jkHswveCLAEJVcX6Mm1wHQD1SkPYMzUDTZvWvhuE6VNAkK3KxVeEmsanSmvjVkReDeBEMxeDaayjcZjFGPydyey1qxBHmTvAnBKoPydvuTAqx5f7YNNRAdeLmUi99gERUU7TD8KfAa6MpQ9bw\",\"blskey_pop\":\"RPLagxaR5xdimFzwmzYnz4ZhWtYQEj8iR5ZU53T2gitPCyCHQneUn2Huc4oeLd2B2HzkGnjAff4hWTJT6C7qHYB1Mv2wU5iHHGFWkhnTX9WsEAbunJCV2qcaXScKj4tTfvdDKfLiVuU2av6hbsMztirRze7LvYBkRHV3tGwyCptsrP\",\"client_ip\":\"172.17.0.1\",\"client_port\":9708,\"node_ip\":\"172.17.0.1\",\"node_port\":9707,\"services\":[\"VALIDATOR\"]},\"dest\":\"4PS3EDQ3dW1tci1Bp6543CfuuebjFrg36kLAUcskGfaA\"},\"metadata\":{\"from\":\"TWwCRQRZ2ZHMJFn9TzLp7W\"},\"type\":\"0\"},\"txnMetadata\":{\"seqNo\":4,\"txnId\":\"aa5e817d7cc626170eca175822029339a444eb0ee8f0bd20d3b0b76e566fb008\"},\"ver\":\"1\"}\n"
  }
}
ianco commented 3 years ago

The /system/config just reflects the aca-py startup settings, and it looks like your does (i.e. all your auto flags seem to be set)

You should just need 1 call to each agent:

  1. The inviter calls /connections/create-invitation
  2. The invitee calls /connections/receive-invitation

Everything else should happen automatically (since you have auto accept invites, auto accept requests, and auto ping connections)

If your connections do not automatically go into active state, then there is something wrong with your config.

Possibly your endpoints are wrong and your agents are not actually able to communicate.

ianco commented 3 years ago

Going through this ticket again I'm pretty sure the endpoints are the issue.

I notice both agents have endpoints using localhost - are you running these agents locally, in docker images, on a platform such as AWS, or ... ?

The endpoints need to be something meaningful to the agents, for example of they are running in separate docker containers the endpoint should use the docker IP or docker image name (if using docker-compose).

phearaeun commented 3 years ago

I am running all instances on localhost, No docker or any vps involved. Yes, I think it is an issue as well but all my endpoints are accessible. At the moment, I am testing with auto-accept/request and it produces the same result but a few second or after I go to /connections, there is one error coming:


Traceback (most recent call last):
  File "/home/phearaeun/tuts/blockchain/digital-identity/AgentController/aries_cloudagent/admin/server.py", line 162, in ready_middleware
    return await handler(request)
  File "/home/phearaeun/tuts/blockchain/digital-identity/AgentController/aries_cloudagent/admin/server.py", line 199, in debug_middleware
    return await handler(request)
  File "/home/phearaeun/.pyenv/versions/hyperledger/lib/python3.9/site-packages/aiohttp_apispec/middlewares.py", line 22, in validation_middleware
    return await handler(request)
  File "/home/phearaeun/tuts/blockchain/digital-identity/AgentController/aries_cloudagent/admin/server.py", line 366, in setup_context
    return await task
  File "/home/phearaeun/.pyenv/versions/hyperledger/lib/python3.9/site-packages/aiohttp/web_urldispatcher.py", line 927, in _handle
    raise self._http_exception
aiohttp.web_exceptions.HTTPNotFound: Not Found

I am still looking into this.

ianco commented 3 years ago

Try setting the logger to debug to get more info about what the agent is trying to do.

This is the method that is throwing the error (server.py line 199):

async def debug_middleware(request: web.BaseRequest, handler: Coroutine):
    """Show request detail in debug log."""

    if LOGGER.isEnabledFor(logging.DEBUG):
        LOGGER.debug(f"Incoming request: {request.method} {request.path_qs}")
        LOGGER.debug(f"Match info: {request.match_info}")
        body = await request.text() if request.body_exists else None
        LOGGER.debug(f"Body: {body}")

    return await handler(request)
phearaeun commented 3 years ago

It happens only when hard refresh on agent hosts (Both issuer and holder)

phearaeun commented 3 years ago

Here is the logs for the connection process:

Created new invitation
    connection: {'rfc23_state': 'invitation-sent', 'created_at': '2021-07-19 14:30:48.985287Z', 'routing_state': 'none', 'accept': 'auto', 'connection_protocol': 'connections/1.0', 'their_role': 'invitee', 'updated_at': '2021-07-19 14:30:48.985287Z', 'invitation_mode': 'once', 'connection_id': '33efc3e1-5392-42a5-a5ba-e293c4ca88ab', 'state': 'invitation', 'invitation_key': '3RHUikfeNT2bSZnWQFAkvVvWwiYKkM3HMiTXis7Vk9fs'}

2021-07-19 21:30:49,028 aries_cloudagent.utils.tracing INFO   {"msg_id": "N/A", "thread_id": "N/A", "traced_type": "dict", "timestamp": 1626705049.0278144, "str_time": "2021-07-19 14:30:49.027814", "handler": "Bank", "ellapsed_milli": 0, "outcome": "OutboundTransportManager.DELIVER.START.http://localhost:5000/webhooks/topic/connections/"}
2021-07-19 21:30:49,029 aries_cloudagent.utils.tracing INFO   {"msg_id": "N/A", "thread_id": "N/A", "traced_type": "dict", "timestamp": 1626705049.0291715, "str_time": "2021-07-19 14:30:49.029171", "handler": "Bank", "ellapsed_milli": 1, "outcome": "OutboundTransportManager.DELIVER.END.http://localhost:5000/webhooks/topic/connections/"}
handle_connections called
invitation
INFO:     127.0.0.1:49972 - "POST /webhooks/topic/connections/ HTTP/1.1" 200 OK
INFO:     127.0.0.1:49968 - "POST /controllers/agents/invitations HTTP/1.1" 200 OK
Created new connection record from invitation
    connection: {'created_at': '2021-07-19 14:31:21.942088Z', 'invitation_key': '3RHUikfeNT2bSZnWQFAkvVvWwiYKkM3HMiTXis7Vk9fs', 'invitation_mode': 'once', 'updated_at': '2021-07-19 14:31:21.942088Z', 'state': 'invitation', 'invitation_msg_id': 'c730406b-5728-4eff-9dd0-ce76b7e67d29', 'connection_id': 'ba6eccab-2349-4f92-baae-8472bd811f60', 'rfc23_state': 'invitation-received', 'routing_state': 'none', 'accept': 'auto', 'connection_protocol': 'connections/1.0', 'their_label': 'Bank', 'their_role': 'inviter'}
    invitation: <ConnectionInvitation(_message_id='c730406b-5728-4eff-9dd0-ce76b7e67d29', _message_new_id=False, _message_decorators=<DecoratorSet{}>, label='Bank', did=None, recipient_keys=['3RHUikfeNT2bSZnWQFAkvVvWwiYKkM3HMiTXis7Vk9fs'], endpoint='http://localhost:8031', routing_keys=None, image_url=None)>
    their_label: Bank

2021-07-19 21:31:22,031 aries_cloudagent.utils.tracing INFO   {"msg_id": "N/A", "thread_id": "N/A", "traced_type": "dict", "timestamp": 1626705082.0306227, "str_time": "2021-07-19 14:31:22.030623", "handler": "Mediator", "ellapsed_milli": 0, "outcome": "OutboundTransportManager.DELIVER.START.http://localhost:5000/webhooks/topic/connections/"}
2021-07-19 21:31:22,033 aries_cloudagent.utils.tracing INFO   {"msg_id": "N/A", "thread_id": "N/A", "traced_type": "dict", "timestamp": 1626705082.0326707, "str_time": "2021-07-19 14:31:22.032671", "handler": "Mediator", "ellapsed_milli": 2, "outcome": "OutboundTransportManager.DELIVER.END.http://localhost:5000/webhooks/topic/connections/"}
handle_connections called
invitation
INFO:     127.0.0.1:50014 - "POST /webhooks/topic/connections/ HTTP/1.1" 200 OK
Created connection request
    connection: {'created_at': '2021-07-19 14:31:21.942088Z', 'invitation_key': '3RHUikfeNT2bSZnWQFAkvVvWwiYKkM3HMiTXis7Vk9fs', 'invitation_mode': 'once', 'updated_at': '2021-07-19 14:31:22.173433Z', 'state': 'request', 'invitation_msg_id': 'c730406b-5728-4eff-9dd0-ce76b7e67d29', 'connection_id': 'ba6eccab-2349-4f92-baae-8472bd811f60', 'rfc23_state': 'request-sent', 'routing_state': 'none', 'my_did': 'HYqbDdEDoo8qNz6nYXrwEQ', 'request_id': '4b269546-eebd-48fe-aca1-14627694532b', 'accept': 'auto', 'connection_protocol': 'connections/1.0', 'their_label': 'Bank', 'their_role': 'inviter'}

2021-07-19 21:31:22,254 aries_cloudagent.utils.tracing INFO   {"msg_id": "N/A", "thread_id": "N/A", "traced_type": "dict", "timestamp": 1626705082.253993, "str_time": "2021-07-19 14:31:22.253993", "handler": "Mediator", "ellapsed_milli": 0, "outcome": "OutboundTransportManager.DELIVER.START.http://localhost:5000/webhooks/topic/connections/"}
2021-07-19 21:31:22,255 aries_cloudagent.utils.tracing INFO   {"msg_id": "N/A", "thread_id": "N/A", "traced_type": "dict", "timestamp": 1626705082.2551992, "str_time": "2021-07-19 14:31:22.255199", "handler": "Mediator", "ellapsed_milli": 1, "outcome": "OutboundTransportManager.DELIVER.END.http://localhost:5000/webhooks/topic/connections/"}
handle_connections called
request
INFO:     127.0.0.1:50014 - "POST /webhooks/topic/connections/ HTTP/1.1" 200 OK
2021-07-19 21:31:22,278 aries_cloudagent.utils.tracing INFO   {"msg_id": "4b269546-eebd-48fe-aca1-14627694532b", "thread_id": "4b269546-eebd-48fe-aca1-14627694532b", "traced_type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/connections/1.0/request", "timestamp": 1626705082.2781014, "str_time": "2021-07-19 14:31:22.278101", "handler": "Mediator", "ellapsed_milli": 0, "outcome": "OutboundTransportManager.ENCODE.START"}
2021-07-19 21:31:22,279 aries_cloudagent.utils.tracing INFO   {"msg_id": "4b269546-eebd-48fe-aca1-14627694532b", "thread_id": "4b269546-eebd-48fe-aca1-14627694532b", "traced_type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/connections/1.0/request", "timestamp": 1626705082.279382, "str_time": "2021-07-19 14:31:22.279382", "handler": "Mediator", "ellapsed_milli": 1, "outcome": "OutboundTransportManager.ENCODE.END"}
2021-07-19 21:31:22,290 aries_cloudagent.utils.tracing INFO   {"msg_id": "4b269546-eebd-48fe-aca1-14627694532b", "thread_id": "4b269546-eebd-48fe-aca1-14627694532b", "traced_type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/connections/1.0/request", "timestamp": 1626705082.2900848, "str_time": "2021-07-19 14:31:22.290085", "handler": "Mediator", "ellapsed_milli": 0, "outcome": "OutboundTransportManager.DELIVER.START.http://localhost:8031"}
INFO:     127.0.0.1:50010 - "POST /controllers/agents/invitations/accept HTTP/1.1" 200 OK
2021-07-19 21:31:22,291 aries_cloudagent.utils.tracing INFO   {"msg_id": "4b269546-eebd-48fe-aca1-14627694532b", "thread_id": "4b269546-eebd-48fe-aca1-14627694532b", "traced_type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/connections/1.0/request", "timestamp": 1626705082.291158, "str_time": "2021-07-19 14:31:22.291158", "handler": "Mediator", "ellapsed_milli": 1, "outcome": "OutboundTransportManager.DELIVER.END.http://localhost:8031"}
2021-07-19 21:31:22,317 aries_cloudagent.utils.tracing INFO   {"msg_id": "4b269546-eebd-48fe-aca1-14627694532b", "thread_id": "4b269546-eebd-48fe-aca1-14627694532b", "traced_type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/connections/1.0/request", "timestamp": 1626705082.317211, "str_time": "2021-07-19 14:31:22.317211", "handler": "Bank", "ellapsed_milli": 0, "outcome": "Dispatcher.handle_message.START"}
Receiving connection request
    request: <ConnectionRequest(_message_id='4b269546-eebd-48fe-aca1-14627694532b', _message_new_id=False, _message_decorators=<DecoratorSet{}>, connection=<ConnectionDetail(_did='HYqbDdEDoo8qNz6nYXrwEQ', _did_doc=<DIDDoc did=HYqbDdEDoo8qNz6nYXrwEQ>)>, label='Mediator', image_url=None)>

Found invitation
    invitation: <ConnectionInvitation(_message_id='c730406b-5728-4eff-9dd0-ce76b7e67d29', _message_new_id=False, _message_decorators=<DecoratorSet{}>, label='Bank', did=None, recipient_keys=['3RHUikfeNT2bSZnWQFAkvVvWwiYKkM3HMiTXis7Vk9fs'], endpoint='http://localhost:8031', routing_keys=None, image_url=None)>

Received connection request from invitation
    connection: {'rfc23_state': 'request-received', 'created_at': '2021-07-19 14:30:48.985287Z', 'routing_state': 'none', 'accept': 'auto', 'their_did': 'HYqbDdEDoo8qNz6nYXrwEQ', 'connection_protocol': 'connections/1.0', 'their_role': 'invitee', 'updated_at': '2021-07-19 14:31:22.400910Z', 'their_label': 'Mediator', 'invitation_mode': 'once', 'connection_id': '33efc3e1-5392-42a5-a5ba-e293c4ca88ab', 'state': 'request', 'invitation_key': '3RHUikfeNT2bSZnWQFAkvVvWwiYKkM3HMiTXis7Vk9fs'}

2021-07-19 21:31:22,473 aries_cloudagent.utils.tracing INFO   {"msg_id": "N/A", "thread_id": "N/A", "traced_type": "dict", "timestamp": 1626705082.4732397, "str_time": "2021-07-19 14:31:22.473240", "handler": "Bank", "ellapsed_milli": 0, "outcome": "OutboundTransportManager.DELIVER.START.http://localhost:5000/webhooks/topic/connections/"}
2021-07-19 21:31:22,474 aries_cloudagent.utils.tracing INFO   {"msg_id": "N/A", "thread_id": "N/A", "traced_type": "dict", "timestamp": 1626705082.474279, "str_time": "2021-07-19 14:31:22.474279", "handler": "Bank", "ellapsed_milli": 1, "outcome": "OutboundTransportManager.DELIVER.END.http://localhost:5000/webhooks/topic/connections/"}
handle_connections called
request
INFO:     127.0.0.1:50018 - "POST /webhooks/topic/connections/ HTTP/1.1" 200 OK
Creating connection response
    connection_id: 33efc3e1-5392-42a5-a5ba-e293c4ca88ab

Created connection response
    connection: {'rfc23_state': 'response-sent', 'created_at': '2021-07-19 14:30:48.985287Z', 'routing_state': 'none', 'accept': 'auto', 'their_did': 'HYqbDdEDoo8qNz6nYXrwEQ', 'connection_protocol': 'connections/1.0', 'their_role': 'invitee', 'updated_at': '2021-07-19 14:31:22.614335Z', 'their_label': 'Mediator', 'invitation_mode': 'once', 'connection_id': '33efc3e1-5392-42a5-a5ba-e293c4ca88ab', 'my_did': '7XdLE38exWA6RV7cgAFP4C', 'state': 'response', 'invitation_key': '3RHUikfeNT2bSZnWQFAkvVvWwiYKkM3HMiTXis7Vk9fs'}
    response: <ConnectionResponse(_message_id='5269520e-c354-41e9-a832-49e2b5cd69a8', _message_new_id=True, _message_decorators=<DecoratorSet{~thread: <ThreadDecorator(_thid='4b269546-eebd-48fe-aca1-14627694532b', _pthid=None, _sender_order=None, _received_orders=None)>}>, connection=<ConnectionDetail(_did='7XdLE38exWA6RV7cgAFP4C', _did_doc=<DIDDoc did=7XdLE38exWA6RV7cgAFP4C>)>)>

2021-07-19 21:31:22,700 aries_cloudagent.utils.tracing INFO   {"msg_id": "N/A", "thread_id": "N/A", "traced_type": "dict", "timestamp": 1626705082.6997604, "str_time": "2021-07-19 14:31:22.699760", "handler": "Bank", "ellapsed_milli": 0, "outcome": "OutboundTransportManager.DELIVER.START.http://localhost:5000/webhooks/topic/connections/"}
2021-07-19 21:31:22,701 aries_cloudagent.utils.tracing INFO   {"msg_id": "N/A", "thread_id": "N/A", "traced_type": "dict", "timestamp": 1626705082.7011518, "str_time": "2021-07-19 14:31:22.701152", "handler": "Bank", "ellapsed_milli": 1, "outcome": "OutboundTransportManager.DELIVER.END.http://localhost:5000/webhooks/topic/connections/"}
handle_connections called
response
INFO:     127.0.0.1:50018 - "POST /webhooks/topic/connections/ HTTP/1.1" 200 OK
2021-07-19 21:31:22,737 aries_cloudagent.utils.tracing INFO   {"msg_id": "5269520e-c354-41e9-a832-49e2b5cd69a8", "thread_id": "4b269546-eebd-48fe-aca1-14627694532b", "traced_type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/connections/1.0/response", "timestamp": 1626705082.7369993, "str_time": "2021-07-19 14:31:22.736999", "handler": "Bank", "ellapsed_milli": 0, "outcome": "OutboundTransportManager.ENCODE.START"}
2021-07-19 21:31:22,738 aries_cloudagent.utils.tracing INFO   {"msg_id": "5269520e-c354-41e9-a832-49e2b5cd69a8", "thread_id": "4b269546-eebd-48fe-aca1-14627694532b", "traced_type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/connections/1.0/response", "timestamp": 1626705082.7380943, "str_time": "2021-07-19 14:31:22.738094", "handler": "Bank", "ellapsed_milli": 1, "outcome": "OutboundTransportManager.ENCODE.END"}
2021-07-19 21:31:22,741 aries_cloudagent.utils.tracing INFO   {"msg_id": "4b269546-eebd-48fe-aca1-14627694532b", "thread_id": "4b269546-eebd-48fe-aca1-14627694532b", "traced_type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/connections/1.0/request", "timestamp": 1626705082.741067, "str_time": "2021-07-19 14:31:22.741067", "handler": "Bank", "ellapsed_milli": 428, "outcome": "Dispatcher.handle_message.END"}
2021-07-19 21:31:22,743 aries_cloudagent.utils.tracing INFO   {"msg_id": "5269520e-c354-41e9-a832-49e2b5cd69a8", "thread_id": "4b269546-eebd-48fe-aca1-14627694532b", "traced_type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/connections/1.0/response", "timestamp": 1626705082.7433622, "str_time": "2021-07-19 14:31:22.743362", "handler": "Bank", "ellapsed_milli": 0, "outcome": "OutboundTransportManager.DELIVER.START.http://localhost:5000/endpoints/holder"}
2021-07-19 21:31:22,745 aries_cloudagent.utils.tracing INFO   {"msg_id": "5269520e-c354-41e9-a832-49e2b5cd69a8", "thread_id": "4b269546-eebd-48fe-aca1-14627694532b", "traced_type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/connections/1.0/response", "timestamp": 1626705082.7446065, "str_time": "2021-07-19 14:31:22.744606", "handler": "Bank", "ellapsed_milli": 1, "outcome": "OutboundTransportManager.DELIVER.END.http://localhost:5000/endpoints/holder"}
Holder endpoint {'protected': 'eyJlbmMiOiJ4Y2hhY2hhMjBwb2x5MTMwNV9pZXRmIiwidHlwIjoiSldNLzEuMCIsImFsZyI6IkF1dGhjcnlwdCIsInJlY2lwaWVudHMiOlt7ImVuY3J5cHRlZF9rZXkiOiIzcmE2MTAtcXFWZXcyc0VBMnlwczB2dXo3VlJzYkVrM00yNnk5VE5VLVh3Z3FzQU9UakNxc3daS1Q5UUt5LXhGIiwiaGVhZGVyIjp7ImtpZCI6IkEyOU42Y3VyUWVFODZpdkxVM1RQZnNwVEQzM1F0d2p5NlJGOXZHTUVBR0xFIiwiaXYiOiJlSC1JQWhSN1VaUDh2Tmx1MzJHREgxeV9pVWFYcHg2dyIsInNlbmRlciI6IllzZVdUa1cxZFdEbEpzVzlPMmMzcWplQUhIMnNXa1JpdWhtQUdrMEtlU0JqQ2wtdGNRMkFKdVJ5LTNWQVNlT1RycHA4SENWQXkwZFVzNEpCUS1NYmtDZG5IbTJ1Uzg5RzdPMmtBT0tCYTRudE5ueTByLXEwem41aGVrMD0ifX1dfQ==', 'iv': 'JqvG6sxbvJPz_YzP', 'ciphertext': '9dR-Xu3BLPh15R5W7pkc3S0LY3UEmj9vdVgHwZ9vipy_zqoScUqvimG9u7zj6d5AUOtDQmX2xUJkenDR9692LJVtwWsdqVZOaR-c6HcuaitRnJu9P9aQukvSELUqDyoWci331jI6SwnPn8L3EFn3Cj2MnYpQlwMPK9s_wCz9T8dXWxzXSGqKb0WbQaNuN0kq3gwcicuGHwsns0X4MBJJcSECwulzgWwtCcJdkFSBjnKzEPvCz_FfqImJ0_YrEpZt79ruCinosZTE8RkRRR9c4wTdkcTv5Pf9P2V8Ni4VYpyfQMv5-GAIbNPHu_1UgJuRquGa5S765gRvSUGNBLJ-JnJ1zrDmk3Pc4ynOjRCKiQ3KuVtAOqNNVZGC_VcV_Jaa3jcrkAmiflWe_9v8iAhiynehzLCnmL1fKAiH3C1g_iDiCjFQ9Fv1oX0TY9TKE7VYmC5FVv6MJlhmSm8zOVUWAtee0htzIEqQKH1tBm5hU-OZyeQqJIcTmoqmux1V3JwnihBMmUB85qFZnEsLZ-222yBamc1w7CHgVXT5G7QGLqFBRjPaOTt-8oa0Jl8V8uC9g02fw2m7J__mudRvzcANNFqeiEad86bohaXr7d2tNnbOpj1BmRxhnmebDNqBcZMWu9NYT7nXIrfBoIoBgVU0fvzZ66ldGjXXbqmJe_qjupQ-2MM82pvthzPCxvZ5rKl8lkzQww8eOQXJ9zLuzlDNkWavtVgafmyStAWl5ldzmXjOV3Dj8AW7j0NX6IoY53mkFTwyMXaTWfBN1nmeiokOzfFjIeoMoP0YeeAdW7d3KLWxxTbyOpnmYi23CcxJyqb7YNFZYXGgdgvOg8Hk2fPJZIM043e5ZO-dBzI3lSomqfnEVaRMUWd_e1r33oYHPqTSZoIt-fLdqtj5E5oy9EgN2llHJ75BbRFnHooJYv5hM2iqvJ2JiER8AkNnqdcF1d4Z30GuAJ3rcQEiQjKmMhLzotbB14Waa-DW55iLTuw0uZMmsdWemV5zgR1k9bJbtK6ngNelcrVs2kTfh5CwZWxMfWZn0zxB5Dl5vK1cingAqc8c7BF0EWvdTGt9OBfmLxhLWKr9WXI1sIlyJQRH8v5WT0ipEH1qX8StPxU2UneJD9Ngq9uUe2ZiJiDdG2ZFBjBcduNqDXrrUwywpVCF-DKE8CTz-WUowFCf1mJ1Aky25_pNAv6yuKNEMHKxYk7PqHcHsGlM6fZW_67j9fkPFFvRFXHmbg_5t3rV1-jz25oxKMB-u00T5vIhsbOv0ii9YIpXqo5y1PNh1nXukiyhhyhgD13G7RXgCWeZqE-KimWyhf3m2f4yF-WMFJyRoalUQ0pZWcZmlJ-3WHToWcK2SjQ18u-uF1jBLiWlbDfen02uZSKx6yEcYbvGEd8_svGx4H8ZuRiSFxTPJH8O0mJ-hdv-QKV3_YQC50_pcVuAmO3skKamO1tYMsIit3QROZ6T429VXnBw0-TOwW5jNbMoUjgwjqGfVBF33DJpUK7sRQ7gJMvHEwkGJ_q9C01r62KwHJ_uLBA6mx6fKBr0PgwSedhcIelJyTrifVeYyho5tKHRuX_Ew950IbqDUaZAUdeQ5raqkSyS__eeBDy8M5iHO5c4835mBFcekD-cy-16lwOQ2u6-8vUeo3J8wIZv2kYeKkwasZXILz9l5qAIikTVd3VG9GhevN81EuDYkp8tz9UgyZaqZWSNAhC9Ca42J_v9DrX3SSO-K__CHh-pqTorAz3f7wDYjA3goPo2wnejg678CPN-41HvEcgUwmSVCgAHYmJGOxBvpDR1n9oFBYt2Aj4UllKLIyHQj0UdqXq1SxJaVzaRX3g=', 'tag': '0YKPmUtUHYbzmIBE5Mk7sA=='}
INFO:     127.0.0.1:50018 - "POST /endpoints/holder HTTP/1.1" 200 OK
2021-07-19 21:33:34,398 aries_cloudagent.utils.tracing INFO   {"msg_id": "8b26ee63-6965-4206-8d51-f456b56b8e05", "thread_id": "8b26ee63-6965-4206-8d51-f456b56b8e05", "traced_type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/basicmessage/1.0/message", "timestamp": 1626705214.398689, "str_time": "2021-07-19 14:33:34.398689", "handler": "Bank", "ellapsed_milli": 0, "outcome": "OutboundTransportManager.ENCODE.START"}
2021-07-19 21:33:34,399 aries_cloudagent.utils.tracing INFO   {"msg_id": "8b26ee63-6965-4206-8d51-f456b56b8e05", "thread_id": "8b26ee63-6965-4206-8d51-f456b56b8e05", "traced_type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/basicmessage/1.0/message", "timestamp": 1626705214.39903, "str_time": "2021-07-19 14:33:34.399030", "handler": "Bank", "ellapsed_milli": 0, "outcome": "OutboundTransportManager.ENCODE.END"}
2021-07-19 21:33:34,401 aries_cloudagent.utils.tracing INFO   {"msg_id": "8b26ee63-6965-4206-8d51-f456b56b8e05", "thread_id": "8b26ee63-6965-4206-8d51-f456b56b8e05", "traced_type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/basicmessage/1.0/message", "timestamp": 1626705214.401372, "str_time": "2021-07-19 14:33:34.401372", "handler": "Bank", "ellapsed_milli": 0, "outcome": "OutboundTransportManager.DELIVER.START.http://localhost:5000/endpoints/holder"}
2021-07-19 21:33:34,401 aries_cloudagent.utils.tracing INFO   {"msg_id": "8b26ee63-6965-4206-8d51-f456b56b8e05", "thread_id": "8b26ee63-6965-4206-8d51-f456b56b8e05", "traced_type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/basicmessage/1.0/message", "timestamp": 1626705214.4018052, "str_time": "2021-07-19 14:33:34.401805", "handler": "Bank", "ellapsed_milli": 0, "outcome": "OutboundTransportManager.DELIVER.END.http://localhost:5000/endpoints/holder"}
Holder endpoint {'protected': 'eyJlbmMiOiJ4Y2hhY2hhMjBwb2x5MTMwNV9pZXRmIiwidHlwIjoiSldNLzEuMCIsImFsZyI6IkF1dGhjcnlwdCIsInJlY2lwaWVudHMiOlt7ImVuY3J5cHRlZF9rZXkiOiJTRzRsQzFCTzJPSmRjWmk4MjJucjBfTnpuRHBFZHM2SGpibXNpTVVvUXNPT1VPY1lINTVMVnhmRmZxM21qUmVEIiwiaGVhZGVyIjp7ImtpZCI6IkEyOU42Y3VyUWVFODZpdkxVM1RQZnNwVEQzM1F0d2p5NlJGOXZHTUVBR0xFIiwiaXYiOiJuLXlIZFlTZVR6bXFLRHViZmhHZ244TE8yM3dJV2Y4dSIsInNlbmRlciI6Ikl5VzV6MlUzTzR4RWhhQ2dUdHdTODFCbUdBaFpVRmdMTzhIUTBRM0dRbk5iYTZXSXh1NmtRYzZ6NU95dlJMeTFnSy1fekkyVWxTWVYtN1hkTHJGMENPX1JXUUdWaFN2cU9nNVYtbUloXzg1U2NjanU1RHowQ1ZscC1Pbz0ifX1dfQ==', 'iv': 'E8BafIT5V6BeVx-N', 'ciphertext': 'Bewx6m7O8yM-sWU6cZb8fwrVHBHz81k7dhVxICHqTUfg9H5igWWclPVB-AKVschqU6sZ70G6mhjQ4esS0we0NqwaJjHV7GKpX1XkEfPOUqQ7hIvZ4ZcpdQ1T9E3siGu9GOHlPQaZzwNsPp6vyx_F5KTuEZad7_juUdnHfxtYAtGddk8Q9WPATb9lGeo0Z9L2sKJJiHtM682RJbhgjIPhsDHurjnWVl0lxPpkKWsRkmV5WiNbhIQVcw==', 'tag': 'AIYwWJh9jfygSVd59aRHdQ=='}
INFO:     127.0.0.1:50080 - "POST /endpoints/holder HTTP/1.1" 200 OK
phearaeun commented 3 years ago

I think the error HTTP Not found is not related to the connection process. It's probably a bug on the web access. You can test with hard refresh (shift+refresh(F5) for my case) at /connections

ianco commented 3 years ago

From the logs it looks like everything is working

phearaeun commented 3 years ago

You are right. It's working. I can even call /issue-credential-2.0/send-offer after the invitation accepted. The only concern is that the state is not updated. You can see from the above comments.

Could you also explain the reason from agent_container.py, line: 108 - 115? From Alice and Faber demo

As I see that condition is very similar to my case.

ianco commented 3 years ago

When the connection request is accepted the state goes to response-sent

If "auto ping" is enabled then that will put the connection in completed state

In either case the connection can issue credentials and ask for proofs

phearaeun commented 3 years ago

That means it doesn't need to be active to be connected? So in my case response-sent is enough or is there anything else requires the state to be active?

phearaeun commented 3 years ago

Here is the last update from the successful test result. I removed:

--auto-ping-connection
--auto-accept-invites
--auto-accept-requests

Changed --genesis-url to --genesis-transactions to load response text instead of url. I did everything manually. It WORKS!. However, the auto option still doesn't work.

{
  "results": [
    {
      "their_role": "inviter",
      "rfc23_state": "completed",
      "my_did": "M3fx6qMsAWSRHKwtUBbEb9",
      "created_at": "2021-07-20 09:14:33.233415Z",
      "invitation_msg_id": "32dcfb25-7fba-4587-aaa6-55c6b18e0b14",
      "routing_state": "none",
      "state": "active",
      "request_id": "04fbbb13-2acd-483b-bcce-5c222a07d39a",
      "connection_id": "70bb96df-7c31-4f24-a1c5-7da70c9c443b",
      "connection_protocol": "connections/1.0",
      "accept": "manual",
      "invitation_key": "hFkGknNEaWsnQCrBNe96tcvLS34LjEwHAYBVdLbsKuA",
      "their_did": "LLZ5XEqSzq1AtNzEHZ7X7E",
      "their_label": "bank",
      "updated_at": "2021-07-20 09:19:22.126974Z",
      "invitation_mode": "once"
    }
  ]
}