search

hyperledger-archives / aries-framework-go

Hyperledger Aries Framework Go provides packages for building Agent / DIDComm services.
https://wiki.hyperledger.org/display/ARIES/aries-framework-go
Apache License 2.0
240 stars 161 forks source link

BDD tests failures in CI #2178

Closed llorllale closed 4 years ago

llorllale commented 4 years ago

This bug is a bit hard to reproduce on my local setup.. however, it's ocurring in CI relatively frequently.

See this build log: https://github.com/hyperledger/aries-framework-go/runs/1101967510

Notes:

llorllale commented 4 years ago

I declared some dependencies on the fixtures (set dependency on the relevant storage container for each agent) and also increased the Go BDD test timeout to 30... still sometimes seeing this error:

  Scenario: did exchange e2e flow using controller api # features/didexchange_e2e_controller.feature:12
    Given "Alice" agent is running on "localhost" port "8081" with controller "https://localhost:8082" # features/didexchange_e2e_controller.feature:13
      Error: Get "https://localhost:8082": dial tcp 127.0.0.1:8082: connect: connection refused

And yet:

$ docker ps | grep alice.agent.example.com
$
$ docker logs alice.agent.example.com
Error: No such container: alice.agent.example.com
$
llorllale commented 4 years ago

Ah - the container does exist - I need to search with the container_name:

$ docker logs -f alice.aries.example.com
WARNING: ca-certificates.crt does not contain exactly one certificate or CRL: skipping
WARNING: ca-cert-ec-key.csr.pem does not contain exactly one certificate or CRL: skipping
WARNING: ca-cert-ec-cacert.srl.pem does not contain exactly one certificate or CRL: skipping
Error: failed to start aries agent rest on port [0.0.0.0:8082], failed to initialize framework :  default option initialization failed: can't initialize verifaible store : failed to open vc store: failed to create db: Unauthorized: You are not a server admin.
....
llorllale commented 4 years ago

excerpt from couchdb logs:

View ``` [info] 2020-09-11T18:56:05.873319Z nonode@nohost <0.11.0> -------- Application mem3 started on node nonode@nohost [info] 2020-09-11T18:56:05.873603Z nonode@nohost <0.11.0> -------- Application fabric started on node nonode@nohost [info] 2020-09-11T18:56:05.924190Z nonode@nohost <0.11.0> -------- Application chttpd started on node nonode@nohost [info] 2020-09-11T18:56:05.964180Z nonode@nohost <0.11.0> -------- Application couch_index started on node nonode@nohost [info] 2020-09-11T18:56:05.964253Z nonode@nohost <0.11.0> -------- Application couch_mrview started on node nonode@nohost [info] 2020-09-11T18:56:05.964320Z nonode@nohost <0.11.0> -------- Application couch_plugins started on node nonode@nohost [notice] 2020-09-11T18:56:05.969539Z nonode@nohost <0.326.0> -------- chttpd_auth_cache changes listener died because the _users database does not exist. Create the database to silence this notice. [error] 2020-09-11T18:56:05.969709Z nonode@nohost emulator -------- Error in process <0.327.0> with exit value: {database_does_not_exist,[{mem3_shards,load_shards_from_db,"_users",[{file,"src/mem3_shards.erl"},{line,399}]},{mem3_shards,load_shards_from_disk,1,[{file,"src/mem3_shards.erl"},{line,374}]},{mem3_shards,load_shards_from_disk,2,[{file,"src/mem3_shards.erl"},{line,403}]},{mem3_shards,for_docid,3,[{file,"src/mem3_shards.erl"},{line,96}]},{fabric_doc_open,go,3,[{file,"src/fabric_doc_open.erl"},{line,39}]},{chttpd_auth_cache,ensure_auth_ddoc_exists,2,[{file,"src/chttpd_auth_cache.erl"},{line,198}]},{chttpd_auth_cache,listen_for_changes,1,[{file,"src/chttpd_auth_cache.erl"},{line,145}]}]} [notice] 2020-09-11T18:56:06.059788Z nonode@nohost <0.82.0> -------- config: [couch_httpd_auth] secret set to 44117e3e0a1d7b7b65002e9ab87903ae for reason nil [notice] 2020-09-11T18:56:06.060396Z nonode@nohost <0.82.0> -------- config: [couch_httpd_auth] secret set to f244a16201dafa6b3cd27c39491fa629 for reason nil [info] 2020-09-11T18:56:06.066711Z nonode@nohost <0.11.0> -------- Application couch_replicator started on node nonode@nohost [info] 2020-09-11T18:56:06.094945Z nonode@nohost <0.11.0> -------- Application couch_peruser started on node nonode@nohost [notice] 2020-09-11T18:56:06.130826Z nonode@nohost <0.308.0> 77e9f629ee couchdb.example.com:5984 192.168.16.16 undefined POST /_session 200 ok 182 [notice] 2020-09-11T18:56:06.131231Z nonode@nohost <0.309.0> 1207332a92 couchdb.example.com:5984 192.168.16.17 undefined POST /_session 200 ok 183 [info] 2020-09-11T18:56:06.137224Z nonode@nohost <0.11.0> -------- Application ddoc_cache started on node nonode@nohost [notice] 2020-09-11T18:56:06.146340Z nonode@nohost <0.311.0> ed31e4f7df couchdb.example.com:5984 192.168.16.16 admin HEAD /_up 200 ok 14 [notice] 2020-09-11T18:56:06.146544Z nonode@nohost <0.310.0> 9748e557b4 couchdb.example.com:5984 192.168.16.17 undefined HEAD /_up 200 ok 14 [notice] 2020-09-11T18:56:06.148517Z nonode@nohost <0.310.0> fa6dc4068e couchdb.example.com:5984 192.168.16.17 undefined PUT /alice_verifiable 401 ok 1 [error] 2020-09-11T18:56:06.170129Z nonode@nohost <0.311.0> 92629fa8f7 Request to create N=3 DB but only 1 node(s) [info] 2020-09-11T18:56:06.175613Z nonode@nohost <0.11.0> -------- Application dreyfus started on node nonode@nohost [notice] 2020-09-11T18:56:06.239619Z nonode@nohost <0.311.0> 92629fa8f7 couchdb.example.com:5984 192.168.16.16 admin PUT /erin_verifiable 201 ok 92 [error] 2020-09-11T18:56:06.241762Z nonode@nohost <0.312.0> 7adb09d71a Request to create N=3 DB but only 1 node(s) [info] 2020-09-11T18:56:06.251640Z nonode@nohost <0.11.0> -------- Application global_changes started on node nonode@nohost [info] 2020-09-11T18:56:06.251694Z nonode@nohost <0.11.0> -------- Application jiffy started on node nonode@nohost [notice] 2020-09-11T18:56:06.254550Z nonode@nohost <0.312.0> 7adb09d71a couchdb.example.com:5984 192.168.16.16 admin PUT /erin_kmsdb 201 ok 14 [error] 2020-09-11T18:56:06.258825Z nonode@nohost <0.314.0> 76bea59fd2 Request to create N=3 DB but only 1 node(s) [notice] 2020-09-11T18:56:06.273688Z nonode@nohost <0.314.0> 76bea59fd2 couchdb.example.com:5984 192.168.16.16 admin PUT /erin_peer 201 ok 16 [error] 2020-09-11T18:56:06.276178Z nonode@nohost <0.315.0> 6355196f03 Request to create N=3 DB but only 1 node(s) [info] 2020-09-11T18:56:06.282158Z nonode@nohost <0.11.0> -------- Application jwtf started on node nonode@nohost ```

There's the 401 while attempting to create Alice's verifiable store.

llorllale commented 4 years ago

Calling the _session endpoint is not enough:

View ``` [notice] 2020-09-11T19:54:41.771458Z nonode@nohost <0.82.0> -------- config: [couch_httpd_auth] secret set to 9d259ff2b2c492fa0aedfe8c80db7c2e for reason nil [notice] 2020-09-11T19:54:41.773335Z nonode@nohost <0.82.0> -------- config: [couch_httpd_auth] secret set to bd089cf84f1e713998c00f15d9be6883 for reason nil [notice] 2020-09-11T19:54:41.773971Z nonode@nohost <0.82.0> -------- config: [couch_httpd_auth] secret set to c828f9478987308a4c76a143c935099f for reason nil [notice] 2020-09-11T19:54:41.798154Z nonode@nohost <0.309.0> a11a309da8 couchdb.example.com:5984 192.168.112.12 undefined POST /_session 200 ok 155 [notice] 2020-09-11T19:54:41.798547Z nonode@nohost <0.310.0> 053a4f97ca couchdb.example.com:5984 192.168.112.13 undefined POST /_session 200 ok 121 [notice] 2020-09-11T19:54:41.798708Z nonode@nohost <0.308.0> 1e3d583e7f couchdb.example.com:5984 192.168.112.11 undefined POST /_session 200 ok 161 [notice] 2020-09-11T19:54:41.811285Z nonode@nohost <0.311.0> 564ad78c61 couchdb.example.com:5984 192.168.112.13 undefined GET /_session 200 ok 2 [notice] 2020-09-11T19:54:41.811295Z nonode@nohost <0.312.0> 5e4dbddfa8 couchdb.example.com:5984 192.168.112.11 undefined GET /_session 200 ok 1 [notice] 2020-09-11T19:54:41.812173Z nonode@nohost <0.313.0> da82b484d0 couchdb.example.com:5984 192.168.112.12 admin GET /_session 200 ok 2 [notice] 2020-09-11T19:54:41.813491Z nonode@nohost <0.311.0> a152c7ecdd couchdb.example.com:5984 192.168.112.13 undefined PUT /alice_verifiable 401 ok 1 [notice] 2020-09-11T19:54:41.813927Z nonode@nohost <0.312.0> 1d9f8c94c1 couchdb.example.com:5984 192.168.112.11 undefined PUT /erin_verifiable 401 ok 1 [error] 2020-09-11T19:54:41.844414Z nonode@nohost <0.313.0> a29f528afb Request to create N=3 DB but only 1 node(s) [notice] 2020-09-11T19:54:41.912725Z nonode@nohost <0.313.0> a29f528afb couchdb.example.com:5984 192.168.112.12 admin PUT /bob_verifiable 201 ok 99 [error] 2020-09-11T19:54:41.915884Z nonode@nohost <0.314.0> 54e584230f Request to create N=3 DB but only 1 node(s) [notice] 2020-09-11T19:54:41.928788Z nonode@nohost <0.314.0> 54e584230f couchdb.example.com:5984 192.168.112.12 admin PUT /bob_kmsdb 201 ok 15 [error] 2020-09-11T19:54:41.932135Z nonode@nohost <0.315.0> 3f0559dfc2 Request to create N=3 DB but only 1 node(s) [notice] 2020-09-11T19:54:41.950262Z nonode@nohost <0.315.0> 3f0559dfc2 couchdb.example.com:5984 192.168.112.12 admin PUT /bob_peer 201 ok 20 [error] 2020-09-11T19:54:41.959225Z nonode@nohost <0.316.0> 31a8c49d7c Request to create N=3 DB but only 1 node(s) ```
llorllale commented 4 years ago

Querying _users was not enough... seems CouchDB sometimes can't create it?

View ``` [notice] 2020-09-11T20:13:02.846674Z nonode@nohost <0.324.0> -------- chttpd_auth_cache changes listener died because the _users database does not exist. Create the database to silence this notice. [error] 2020-09-11T20:13:02.846869Z nonode@nohost emulator -------- Error in process <0.2644.0> with exit value: {database_does_not_exist,[{mem3_shards,load_shards_from_db,"_users",[{file,"src/mem3_shards.erl"},{line,399}]},{mem3_shards,load_shards_from_disk,1,[{file,"src/mem3_shards.erl"},{line,374}]},{mem3_shards,load_shards_from_disk,2,[{file,"src/mem3_shards.erl"},{line,403}]},{mem3_shards,for_docid,3,[{file,"src/mem3_shards.erl"},{line,96}]},{fabric_doc_open,go,3,[{file,"src/fabric_doc_open.erl"},{line,39}]},{chttpd_auth_cache,ensure_auth_ddoc_exists,2,[{file,"src/chttpd_auth_cache.erl"},{line,198}]},{chttpd_auth_cache,listen_for_changes,1,[{file,"src/chttpd_auth_cache.erl"},{line,145}]}]} ```

None of the agent databases were created in this run.