search

hyperledger-archives / aries-cloudagent-loadgenerator

aries-cloudagent-loadgenerator
https://wiki.hyperledger.org/display/aries
Apache License 2.0
17 stars 11 forks source link

Load tests failing to run in Ubuntu 18.04 #70

Open wadeking98 opened 1 year ago

wadeking98 commented 1 year ago

I'm using the aries load generator in Ubuntu 18.04. I've ran the script scripts/install-vm.sh and setup/manage.sh start and I'm using the default .env file. When I run setup/manage.sh start all the containers start up, however, the grafana interface shows no test data results. When I inspect the load-generator-1 with sudo docker logs load-generator-1, it shows the following error message:

137335 ERROR c.b.s.g.a.logger.ErrorLogger - type=aries_client_error ariesClientType=AcaPy.IssuerVerifier httpMethod=POST uri=/schemas httpCode=502 durationInMs=459.14613 appErrorCode=n/a message="<html>
<head><title>502 Bad Gateway</title></head>
<body>
<center><h1>502 Bad Gateway</h1></center>
<hr><center>nginx/1.23.3</center>
</body>
</html>
" time=1672785798762
137595 INFO  o.s.b.a.l.ConditionEvaluationReportLoggingListener - 

Error starting ApplicationContext. To display the conditions report re-run your application with 'debug' enabled.
137808 ERROR o.s.boot.SpringApplication - Application run failed
java.lang.IllegalStateException: Failed to execute CommandLineRunner

so I inspected the issuer-verifier-nginx container and I found the following error message:

2023/01/03 22:43:18 [error] 29#29: *1 connect() failed (111: Connection refused) while connecting to upstream, client: 172.25.0.23, server: , request: "POST /schemas HTTP/1.1", upstream: "http://172.25.0.11:10000/schemas", host: "issuer-verifier-nginx:10000"
2023/01/03 22:43:18 [error] 29#29: *1 connect() failed (111: Connection refused) while connecting to upstream, client: 172.25.0.23, server: , request: "POST /schemas HTTP/1.1", upstream: "http://172.25.0.13:10000/schemas", host: "issuer-verifier-nginx:10000"
2023/01/03 22:43:18 [error] 29#29: *1 connect() failed (111: Connection refused) while connecting to upstream, client: 172.25.0.23, server: , request: "POST /schemas HTTP/1.1", upstream: "http://172.25.0.14:10000/schemas", host: "issuer-verifier-nginx:10000"
2023/01/03 22:43:18 [error] 29#29: *1 connect() failed (111: Connection refused) while connecting to upstream, client: 172.25.0.23, server: , request: "POST /schemas HTTP/1.1", upstream: "http://172.25.0.16:10000/schemas", host: "issuer-verifier-nginx:10000"
2023/01/03 22:43:18 [error] 29#29: *1 connect() failed (111: Connection refused) while connecting to upstream, client: 172.25.0.23, server: , request: "POST /schemas HTTP/1.1", upstream: "http://172.25.0.15:10000/schemas", host: "issuer-verifier-nginx:10000"

These addresses belong to the issuer-verifier agents. so this much mean that the endpoints aren't active for some reason. This is the log output for agents_issuer-verifier-acapy_1 

2023-01-03 23:05:10,752 aries_cloudagent.config.ledger INFO Fetching genesis transactions from: http://host.docker.internal:9000/genesis
2023-01-03 23:05:10,871 aries_cloudagent.core.profile INFO Create profile manager: askar
2023-01-03 23:05:30,904 aries_askar.native.aries_askar.ffi.store INFO   src/ffi/store.rs:218 | Opened store StoreHandle(1)
2023-01-03 23:05:30,905 aries_askar.native.aries_askar.ffi.store INFO   src/ffi/store.rs:527 | Started session SessionHandle(1) on store StoreHandle(1) (txn: true)
2023-01-03 23:05:30,933 aries_askar.native.aries_askar.backend.db_utils INFO    src/backend/db_utils.rs:102 | Acquire pool connection
2023-01-03 23:05:30,933 aries_askar.native.aries_askar.backend.db_utils INFO    src/backend/db_utils.rs:105 | Start transaction
2023-01-03 23:05:31,007 aries_askar.native.aries_askar.backend.db_utils INFO    src/backend/db_utils.rs:146 | Commit transaction on close
2023-01-03 23:05:31,007 aries_askar.native.aries_askar.backend.db_utils INFO    src/backend/db_utils.rs:168 | Dropped pool connection
2023-01-03 23:05:31,007 aries_askar.native.aries_askar.ffi.store INFO   src/ffi/store.rs:1007 | Closed session SessionHandle(1)
2023-01-03 23:05:31,008 aries_askar.native.aries_askar.ffi.store INFO   src/ffi/store.rs:527 | Started session SessionHandle(2) on store StoreHandle(1) (txn: false)
2023-01-03 23:05:31,356 aries_askar.native.aries_askar.ffi.store INFO   src/ffi/store.rs:527 | Started session SessionHandle(3) on store StoreHandle(1) (txn: false)
2023-01-03 23:05:31,370 aries_askar.native.aries_askar.backend.db_utils INFO    src/backend/db_utils.rs:102 | Acquire pool connection
2023-01-03 23:05:31,377 aries_askar.native.aries_askar.ffi.store INFO   src/ffi/store.rs:1007 | Closed session SessionHandle(3)
2023-01-03 23:05:31,378 aries_askar.native.aries_askar.backend.db_utils INFO    src/backend/db_utils.rs:168 | Dropped pool connection
2023-01-03 23:05:31,378 aries_askar.native.aries_askar.ffi.store INFO   src/ffi/store.rs:527 | Started session SessionHandle(4) on store StoreHandle(1) (txn: false)
2023-01-03 23:05:31,385 aries_askar.native.aries_askar.backend.db_utils INFO    src/backend/db_utils.rs:102 | Acquire pool connection
2023-01-03 23:05:31,420 aries_askar.native.aries_askar.ffi.store INFO   src/ffi/store.rs:1007 | Closed session SessionHandle(4)
2023-01-03 23:05:31,420 aries_askar.native.aries_askar.backend.db_utils INFO    src/backend/db_utils.rs:168 | Dropped pool connection
2023-01-03 23:05:31,421 aries_askar.native.aries_askar.ffi.store INFO   src/ffi/store.rs:527 | Started session SessionHandle(5) on store StoreHandle(1) (txn: false)
2023-01-03 23:05:31,426 aries_askar.native.aries_askar.backend.db_utils INFO    src/backend/db_utils.rs:102 | Acquire pool connection
2023-01-03 23:05:31,428 aries_askar.native.aries_askar.ffi.store INFO   src/ffi/store.rs:1007 | Closed session SessionHandle(5)
2023-01-03 23:05:31,428 aries_askar.native.aries_askar.backend.db_utils INFO    src/backend/db_utils.rs:168 | Dropped pool connection
2023-01-03 23:05:31,460 aries_askar.native.aries_askar.ffi.store INFO   src/ffi/store.rs:527 | Started session SessionHandle(6) on store StoreHandle(1) (txn: false)
2023-01-03 23:05:31,499 aries_askar.native.aries_askar.backend.db_utils INFO    src/backend/db_utils.rs:102 | Acquire pool connection
2023-01-03 23:05:31,529 aries_askar.native.aries_askar.ffi.store INFO   src/ffi/store.rs:1007 | Closed session SessionHandle(6)
2023-01-03 23:05:31,530 aries_askar.native.aries_askar.backend.db_utils INFO    src/backend/db_utils.rs:168 | Dropped pool connection
2023-01-03 23:05:31,530 aries_askar.native.aries_askar.ffi.store INFO   src/ffi/store.rs:527 | Started session SessionHandle(7) on store StoreHandle(1) (txn: false)
2023-01-03 23:05:31,533 aries_askar.native.aries_askar.backend.db_utils INFO    src/backend/db_utils.rs:102 | Acquire pool connection
2023-01-03 23:05:31,534 aries_askar.native.aries_askar.ffi.store INFO   src/ffi/store.rs:1007 | Closed session SessionHandle(7)
2023-01-03 23:05:31,535 aries_askar.native.aries_askar.backend.db_utils INFO    src/backend/db_utils.rs:168 | Dropped pool connection
2023-01-03 23:05:31,642 aries_askar.native.aries_askar.backend.db_utils INFO    src/backend/db_utils.rs:102 | Acquire pool connection

The logs on the other issuer-verifier agents are either blank or just contain the top two lines.
I noticed that the holder agents seem to startup fine and the only real difference between the two is that the holder agents use sqlite wallet storage, while the issuer-verifiers use postgres storage. I inspected the data base container issuer-verifier-wallet-db and it shows the following error:

2023-01-03 22:39:58.585 UTC [1] LOG:  starting PostgreSQL 13.1 on x86_64-pc-linux-musl, compiled by gcc (Alpine 10.2.1_pre1) 10.2.1 20201203, 64-bit
2023-01-03 22:39:58.590 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5000
2023-01-03 22:39:58.591 UTC [1] LOG:  listening on IPv6 address "::", port 5000
2023-01-03 22:39:58.620 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5000"
2023-01-03 22:39:58.647 UTC [47] LOG:  database system was shut down at 2023-01-03 22:39:58 UTC
2023-01-03 22:39:58.666 UTC [1] LOG:  database system is ready to accept connections
2023-01-03 22:40:14.519 UTC [56] FATAL:  database "wallet_db" does not exist
2023-01-03 22:40:14.522 UTC [57] FATAL:  database "wallet_db" does not exist

It's saying that wallet_db doesn't exist which is strange because if I connect to it using psql I can connect to the database and view tables: image image

I'm not really sure what is going on here, is this a timing issue? Maybe the agents are starting up before postgres makes a wallet_db database? Any help would be appreciated

PaulWen commented 1 year ago

Hi @wadeking98 thank you for reaching out! I just noticed that I also missed your message in the Discord channel, sorry!

Starting with your concerns about database "wallet_db" does not exist within the Postgres logs I can assure you that this is normal. I am guessing AcaPy/Askar tries to connect to the DB first (resulting in this error) and in case the DB does not exist it will create it.

Could you please check if you are able to see an error message similar to this one in the logs of the manage.sh start command?

Waiting for the ledger to start... (sleeping 20 seconds)
Registering issuer DID...
{"detail": "Not ready"}

I also updated the main branch to ensure that this error can not occur in the future: https://github.com/My-DIGI-ID/aries-cloudagent-loadgenerator/commit/433167084bd0f3d878469e49a5d6f387031aa603

Please let me know if this already solves your problem.

wadeking98 commented 1 year ago

Hi @PaulWen, I've switched environments to windows with wsl 2 and I've pull your latest changes, unfortunately I'm still running into similar errors. I'm using the install-vm.sh script to install docker and docker-compose.

docker-compose version: v2.15.1 docker engine version: 20.10.22 docker desktop version: 20.10.22

The errors are slightly different this time, both the holder and the verifier agents fail to start up

Holder agent:

2023-01-14 02:45:50,651 aries_askar.native.aries_askar.ffi.store INFO   src/ffi/store.rs:527 | Started session SessionHandle(2) on store StoreHandle(1) (txn: false)
2023-01-14 02:46:10,675 aries_cloudagent.commands.start ERROR Exception during startup:
Traceback (most recent call last):
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/commands/start.py", line 72, in init
    await startup
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/commands/start.py", line 28, in start_app
    await conductor.setup()
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/core/conductor.py", line 174, in setup
    self.root_profile, self.setup_public_did and self.setup_public_did.did
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/config/ledger.py", line 136, in ledger_config
    async with ledger:
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/ledger/indy_vdr.py", line 296, in __aenter__
    await self.pool.context_open()
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/ledger/indy_vdr.py", line 229, in context_open
    await self.open()
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/ledger/indy_vdr.py", line 192, in open
    self.handle = await open_pool(transactions=txns, socks_proxy=self.socks_proxy)
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/indy_vdr/pool.py", line 177, in open_pool
    await pool.refresh()
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/indy_vdr/pool.py", line 58, in refresh
    await bindings.pool_refresh(self.handle)
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/asyncio/futures.py", line 327, in __iter__
    yield self  # This tells Task to wait for completion.
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/asyncio/tasks.py", line 250, in _wakeup
    future.result()
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/asyncio/futures.py", line 243, in result
    raise self._exception
indy_vdr.error.VdrError: Pool timeout: Request was interrupted
2023-01-14 02:46:10,677 aries_askar.native.aries_askar.backend.db_utils INFO    src/backend/db_utils.rs:167 | Dropped pool connection
2023-01-14 02:46:10,677 aries_askar.native.aries_askar.ffi.store INFO   src/ffi/store.rs:412 | Closed store StoreHandle(1)
FATAL: exception not rethrown
Aborted

Verifier Agent:

2023-01-14 02:47:26,735 aries_cloudagent.config.ledger INFO Fetching genesis transactions from: http://host.docker.internal:9000/genesis
2023-01-14 02:47:26,748 aries_cloudagent.core.profile INFO Create profile manager: askar
2023-01-14 02:47:27,697 aries_askar.native.aries_askar.ffi.store INFO src/ffi/store.rs:213 | Opened store StoreHandle(1)
2023-01-14 02:47:27,699 aries_askar.native.aries_askar.ffi.store INFO src/ffi/store.rs:527 | Started session SessionHandle(1) on store StoreHandle(1) (txn: true)
2023-01-14 02:47:27,701 aries_askar.native.aries_askar.backend.db_utils INFO src/backend/db_utils.rs:102 | Acquire pool connection
2023-01-14 02:47:27,701 aries_askar.native.aries_askar.backend.db_utils INFO src/backend/db_utils.rs:105 | Start transaction
2023-01-14 02:47:27,717 aries_askar.native.aries_askar.backend.db_utils INFO src/backend/db_utils.rs:145 | Commit transaction on close
2023-01-14 02:47:27,720 aries_askar.native.aries_askar.backend.db_utils INFO src/backend/db_utils.rs:167 | Dropped pool connection
2023-01-14 02:47:27,720 aries_askar.native.aries_askar.ffi.store INFO src/ffi/store.rs:1009 | Closed session SessionHandle(1)
2023-01-14 02:47:27,721 aries_askar.native.aries_askar.ffi.store INFO src/ffi/store.rs:527 | Started session SessionHandle(2) on store StoreHandle(1) (txn: false)
2023-01-14 02:47:47,726 aries_cloudagent.commands.start ERROR Exception during startup:
Traceback (most recent call last):
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/commands/start.py", line 72, in init
    await startup
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/commands/start.py", line 28, in start_app
    await conductor.setup()
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/core/conductor.py", line 174, in setup
    self.root_profile, self.setup_public_did and self.setup_public_did.did
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/config/ledger.py", line 136, in ledger_config
    async with ledger:
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/ledger/indy_vdr.py", line 296, in __aenter__
    await self.pool.context_open()
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/ledger/indy_vdr.py", line 229, in context_open
    await self.open()
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/aries_cloudagent/ledger/indy_vdr.py", line 192, in open
    self.handle = await open_pool(transactions=txns, socks_proxy=self.socks_proxy)
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/indy_vdr/pool.py", line 177, in open_pool
    await pool.refresh()
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/site-packages/indy_vdr/pool.py", line 58, in refresh
    await bindings.pool_refresh(self.handle)
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/asyncio/futures.py", line 327, in __iter__
    yield self  # This tells Task to wait for completion.
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/asyncio/tasks.py", line 250, in _wakeup
    future.result()
  File "/home/indy/.pyenv/versions/3.6.13/lib/python3.6/asyncio/futures.py", line 243, in result
    raise self._exception
indy_vdr.error.VdrError: Pool timeout: Request was interrupted
2023-01-14 02:47:47,728 aries_askar.native.aries_askar.backend.db_utils INFO src/backend/db_utils.rs:167 | Dropped pool connection
Shutting down
2023-01-14 02:47:47,728 aries_askar.native.aries_askar.ffi.store INFO src/ffi/store.rs:412 | Closed store StoreHandle(1)
2023-01-14 02:47:47,729 aries_askar.native.aries_askar.ffi.store INFO src/ffi/store.rs:1011 | Session not found for closing: SessionHandle(2)

It seems to me like there's some issue connecting to the ledger, although I can confirm that von-network is running as expected.

PaulWen commented 1 year ago

Hi @wadeking98, do you see 4 von_node containers + 1 von_webserver container starting up? Do you see the VON Ledger web UI when opening http://localhost:9000?