search

bcgov / TheOrgBook

A public repository of verifiable claims about organizations. A key component of the Verifiable Organization Network.
http://von.pathfinder.gov.bc.ca
Apache License 2.0
78 stars 66 forks source link

Error on deploy django pod on AWS OpenShift environment #795

Closed kenhuang closed 5 years ago

kenhuang commented 5 years ago

Not sure why the same setting works locally but not on an AWS environment?

LEDGER_URL is set to http://dev.dflow.bcovrin.vonx.io/genesis

Error message from django pod:


---> Running application from Python script (app-vonx.py) ...
--
  | Enabling realtime indexing ...
  | Loading custom settings file: custom_settings_bcgov.py
  | INFO 2019-05-13 02:18:16,238 manager 1 140017502279424 Initializing Indy service
  | Operations to perform:
  | Apply all migrations: admin, api, api_v2, auth, contenttypes, sessions
  | Running migrations:
  | No migrations to apply.
  | Your models have changes that are not yet reflected in a migration, and so won't be applied.
  | Run 'manage.py makemigrations' to make new migrations, and then re-run 'manage.py migrate' to apply them.
  | INFO 2019-05-13 02:18:16,534 exchange 1 140017502279424 Started exchange
  | INFO 2019-05-13 02:18:16,538 service 1 140017234499328 Max concurrent: 20
  | INFO 2019-05-13 02:18:16,539 service 1 140017234499328 Started service: indy
  | INFO 2019-05-13 02:18:16,540 service 1 140017234499328 Starting sync: indy
  | INFO 2019-05-13 02:18:16,540 service 1 140017234499328 Fetching genesis transaction file from http://dev.dflow.bcovrin.vonx.io/genesis
  | INFO 2019-05-13 02:18:16,551 service 1 140017259677440 Started service: manager
  | INFO 2019-05-13 02:18:16,561 service 1 140017259677440 Starting sync: manager
  | INFO 2019-05-13 02:18:16,561 service 1 140017259677440 Completed sync: manager
  | ======== Running on http://0.0.0.0:8080  ========
  | (Press CTRL+C to quit)
  | INFO 2019-05-13 02:18:16,733 libindy 1 140016269391616  src/commands/mod.rs:90 \| Worker thread started
  | INFO 2019-05-13 02:18:16,741 libindy 1 140016269391616  src/commands/mod.rs:130 \| PoolCommand command received
  | INFO 2019-05-13 02:18:16,741 libindy 1 140016269391616  src/commands/pool.rs:133 \| SetProtocolVersion command received
  | INFO 2019-05-13 02:18:16,741 nodepool 1 140017234499328 Pool ledger indy set protocol V_16
  | INFO 2019-05-13 02:18:16,746 libindy 1 140016269391616  src/commands/mod.rs:130 \| PoolCommand command received
  | INFO 2019-05-13 02:18:16,746 libindy 1 140016269391616  src/commands/pool.rs:58 \| Create command received
  | INFO 2019-05-13 02:18:16,757 libindy 1 140016269391616  src/commands/mod.rs:130 \| PoolCommand command received
  | INFO 2019-05-13 02:18:16,757 libindy 1 140016269391616  src/commands/pool.rs:66 \| Open command received
  | INFO 2019-05-13 02:18:18,635 config 1 140017502279424 Using Postgres storage ...
  | INFO 2019-05-13 02:18:18,636 boot 1 140017502279424 Registering indy agent
  | INFO 2019-05-13 02:18:25,301 helpers 1 140017502279424 10.130.0.1 [13/May/2019:02:18:25 +0000] "GET /health HTTP/1.1" 451 196 "-" "kube-probe/1.11+"
  | INFO 2019-05-13 02:18:55,301 helpers 1 140017502279424 10.130.0.1 [13/May/2019:02:18:55 +0000] "GET /health HTTP/1.1" 451 196 "-" "kube-probe/1.11+"
  | INFO 2019-05-13 02:19:16,832 libindy 1 140016269391616  src/commands/mod.rs:130 \| PoolCommand command received
  | INFO 2019-05-13 02:19:16,832 libindy 1 140016269391616  src/commands/pool.rs:70 \| OpenAck handle 1, pool_id 1, result Err(Timeout)
  | ERROR 2019-05-13 02:19:16,832 libindy 1 140016269391616     src/errors/indy.rs:73 \| Casting error to ErrorCode: Timeout
  | WARNING 2019-05-13 02:19:16,832 libindy 1 140017234499328 _indy_loop_callback: Function returned error 307
  | ERROR 2019-05-13 02:19:16,833 service 1 140017234499328 Fatal error during indy sync:
  | Traceback (most recent call last):
  | File "/home/indy/.pyenv/versions/3.6.8/lib/python3.6/site-packages/vonx/common/service.py", line 177, in _sync
  | synced = await self._service_sync()
  | File "/home/indy/.pyenv/versions/3.6.8/lib/python3.6/site-packages/vonx/indy/service.py", line 201, in _service_sync
  | await self._setup_pool()
  | File "/home/indy/.pyenv/versions/3.6.8/lib/python3.6/site-packages/vonx/indy/service.py", line 438, in _setup_pool
  | await self._pool.open()
  | File "/home/indy/.pyenv/versions/3.6.8/lib/python3.6/site-packages/von_anchor/nodepool.py", line 282, in open
  | self._handle = await pool.open_pool_ledger(self.name, json.dumps(self.cfg))
  | File "/home/indy/.pyenv/versions/3.6.8/lib/python3.6/site-packages/indy/pool.py", line 82, in open_pool_ledger
  | open_pool_ledger.cb)
  | indy.error.IndyError: ErrorCode.PoolLedgerTimeout
  | ERROR 2019-05-13 02:19:18,845 boot 1 140017502279424 Error during Indy initialization:
  | Traceback (most recent call last):
  | File "/home/indy/api_indy/tob_anchor/boot.py", line 152, in perform_register_services
  | await register_services()
  | File "/home/indy/api_indy/tob_anchor/boot.py", line 178, in register_services
  | await client.sync()
  | File "/home/indy/.pyenv/versions/3.6.8/lib/python3.6/site-packages/vonx/indy/client.py", line 457, in sync
  | ServiceSyncReq(wait))
  | File "/home/indy/.pyenv/versions/3.6.8/lib/python3.6/site-packages/vonx/indy/client.py", line 61, in _fetch
  | raise IndyClientError(result.value)
  | vonx.indy.errors.IndyClientError: Service could not be synced: indy
  | INFO 2019-05-13 02:19:18,861 service 1 140017234499328 Stopped service: indy
  | INFO 2019-05-13 02:19:18,871 service 1 140017259677440 Stopped service: manager
  | INFO 2019-05-13 02:19:18,877 exchange 1 140017502279424 Stopping exchange
  | ERROR 2019-05-13 02:19:18,878 base_events 1 140017502279424 Task exception was never retrieved
  | future: <Task finished coro=<perform_register_services() done, defined at /home/indy/api_indy/tob_anchor/boot.py:145> exception=IndyClientError('Service could not be synced: indy',)>
  | Traceback (most recent call last):
  | File "/home/indy/api_indy/tob_anchor/boot.py", line 152, in perform_register_services
  | await register_services()
  | File "/home/indy/api_indy/tob_anchor/boot.py", line 178, in register_services
  | await client.sync()
  | File "/home/indy/.pyenv/versions/3.6.8/lib/python3.6/site-packages/vonx/indy/client.py", line 457, in sync
  | ServiceSyncReq(wait))
  | File "/home/indy/.pyenv/versions/3.6.8/lib/python3.6/site-packages/vonx/indy/client.py", line 61, in _fetch
  | raise IndyClientError(result.value)
  | vonx.indy.errors.IndyClientError: Service could not be synced: indy
  | INFO 2019-05-13 02:19:20,234 helpers 1 140017502279424 10.130.0.1 [13/May/2019:02:19:20 +0000] "GET /health HTTP/1.1" 451 196 "-" "kube-probe/1.11+"
  | INFO 2019-05-13 02:19:25,297 helpers 1 140017502279424 10.130.0.1 [13/May/2019:02:19:25 +0000] "GET /health HTTP/1.1" 451 196 "-" "kube-probe/1.11+"
  | INFO 2019-05-13 02:19:55,298 helpers 1 140017502279424 10.130.0.1 [13/May/2019:02:19:55 +0000] "GET /health HTTP/1.1" 451 196 "-" "kube-probe/1.11+"
  | INFO 2019-05-13 02:20:20,234 helpers 1 140017502279424 10.130.0.1 [13/May/2019:02:20:20 +0000] "GET /health HTTP/1.1" 451 196 "-" "kube-probe/1.11+"
  | INFO 2019-05-13 02:20:25,297 helpers 1 140017502279424 10.130.0.1 [13/May/2019:02:20:25 +0000] "GET /health HTTP/1.1" 451 196 "-" "kube-probe/1.11+"
  | INFO 2019-05-13 02:20:55,298 helpers 1 140017502279424 10.130.0.1 [13/May/2019:02:20:55 +0000] "GET /health HTTP/1.1" 451 196 "-" "kube-probe/1.11+"

Message from local OpenShift:

---> Running application from Python script (app-vonx.py) ...
--
  | Enabling realtime indexing ...
  | Loading custom settings file: custom_settings_bcgov.py
  | INFO 2019-05-06 22:34:09,257 manager 1 139902915413760 Initializing Indy service
  | Operations to perform:
  | Apply all migrations: admin, api, api_v2, auth, contenttypes, sessions
  | Running migrations:
  | No migrations to apply.
  | Your models have changes that are not yet reflected in a migration, and so won't be applied.
  | Run 'manage.py makemigrations' to make new migrations, and then re-run 'manage.py migrate' to apply them.
  | INFO 2019-05-06 22:34:09,524 exchange 1 139902915413760 Started exchange
  | INFO 2019-05-06 22:34:09,529 service 1 139902444365568 Max concurrent: 20
  | INFO 2019-05-06 22:34:09,531 service 1 139902444365568 Started service: indy
  | INFO 2019-05-06 22:34:09,532 service 1 139902444365568 Starting sync: indy
  | INFO 2019-05-06 22:34:09,532 service 1 139902444365568 Fetching genesis transaction file from http://dev.dflow.bcovrin.vonx.io/genesis
  | INFO 2019-05-06 22:34:09,536 service 1 139902672811776 Started service: manager
  | INFO 2019-05-06 22:34:09,548 service 1 139902672811776 Starting sync: manager
  | INFO 2019-05-06 22:34:09,548 service 1 139902672811776 Completed sync: manager
  | ======== Running on http://0.0.0.0:8080  ========
  | (Press CTRL+C to quit)
  | INFO 2019-05-06 22:34:10,833 libindy 1 139901814994688  src/commands/mod.rs:90 \| Worker thread started
  | INFO 2019-05-06 22:34:10,833 libindy 1 139901814994688  src/commands/mod.rs:130 \| PoolCommand command received
  | INFO 2019-05-06 22:34:10,833 libindy 1 139901814994688  src/commands/pool.rs:133 \| SetProtocolVersion command received
  | INFO 2019-05-06 22:34:10,833 nodepool 1 139902444365568 Pool ledger indy set protocol V_16
  | INFO 2019-05-06 22:34:10,834 libindy 1 139901814994688  src/commands/mod.rs:130 \| PoolCommand command received
  | INFO 2019-05-06 22:34:10,834 libindy 1 139901814994688  src/commands/pool.rs:58 \| Create command received
  | INFO 2019-05-06 22:34:10,835 libindy 1 139901814994688  src/commands/mod.rs:130 \| PoolCommand command received
  | INFO 2019-05-06 22:34:10,835 libindy 1 139901814994688  src/commands/pool.rs:66 \| Open command received
  | INFO 2019-05-06 22:34:11,639 config 1 139902915413760 Using Postgres storage ...
  | INFO 2019-05-06 22:34:11,639 boot 1 139902915413760 Registering indy agent
  | INFO 2019-05-06 22:34:12,031 libindy 1 139901814994688  src/commands/mod.rs:130 \| PoolCommand command received
  | INFO 2019-05-06 22:34:12,031 libindy 1 139901814994688  src/commands/pool.rs:70 \| OpenAck handle 1, pool_id 1, result Ok(())
  | INFO 2019-05-06 22:34:12,039 libindy 1 139901814994688  src/commands/mod.rs:138 \| WalletCommand command received
  | INFO 2019-05-06 22:34:12,039 wallet 1 139902444365568 Loaded wallet library type postgres_storage (libindystrgpostgres.so)
  | INFO 2019-05-06 22:34:12,041 libindy 1 139901814994688  src/commands/mod.rs:138 \| WalletCommand command received
  | INFO 2019-05-06 22:34:12,041 libindy 1 139901814994688  src/commands/mod.rs:138 \| WalletCommand command received
  | INFO 2019-05-06 22:34:12,698 libindy 1 139901814994688  src/commands/mod.rs:138 \| WalletCommand command received
  | ERROR 2019-05-06 22:34:12,754 libindy 1 139901814994688     src/errors/indy.rs:73 \| Casting error to ErrorCode: Wallet with this name already exists: Storage already exists
  | WARNING 2019-05-06 22:34:12,757 libindy 1 139902444365568 _indy_loop_callback: Function returned error 203
  | INFO 2019-05-06 22:34:12,759 wallet 1 139902444365568 Wallet already exists: tob_holder
  | INFO 2019-05-06 22:34:12,760 libindy 1 139901814994688  src/commands/mod.rs:138 \| WalletCommand command received
  | INFO 2019-05-06 22:34:12,774 libindy 1 139901814994688  src/commands/mod.rs:138 \| WalletCommand command received
  | INFO 2019-05-06 22:34:13,435 libindy 1 139901814994688  src/commands/mod.rs:138 \| WalletCommand command received
  | INFO 2019-05-06 22:34:13,435 wallet 1 139902444365568 Opened wallet tob_holder on handle 4
  | INFO 2019-05-06 22:34:13,436 libindy 1 139901814994688  src/commands/mod.rs:134 \| DidCommand command received
  | INFO 2019-05-06 22:34:13,436 libindy 1 139901814994688  src/commands/did.rs:150 \| ListMyDidsWithMeta command received
  | INFO 2019-05-06 22:34:13,447 libindy 1 139901814994688  src/commands/mod.rs:134 \| DidCommand command received
  | INFO 2019-05-06 22:34:13,447 libindy 1 139901814994688  src/commands/did.rs:158 \| KeyForLocalDid command received
  | INFO 2019-05-06 22:34:13,448 libindy 1 139901814994688  src/commands/did.rs:371 \| key_for_local_did >>> wallet_handle: 4, did: "SQHAgHtSHCKUCtxDWFmsfX"
  | INFO 2019-05-06 22:34:13,448 wallet 1 139902444365568 Wallet tob_holder got verkey EqzFEK5umcpo8e6SkBPyxsiYKT3JqwTXwKaicmr3tB7E for existing DID SQHAgHtSHCKUCtxDWFmsfX
  | INFO 2019-05-06 22:34:13,448 libindy 1 139901814994688  src/commands/mod.rs:138 \| WalletCommand command received
  | INFO 2019-05-06 22:34:13,451 libindy 1 139901814994688  src/commands/mod.rs:138 \| WalletCommand command received
  | INFO 2019-05-06 22:34:13,459 libindy 1 139901814994688  src/commands/mod.rs:138 \| WalletCommand command received
  | INFO 2019-05-06 22:34:14,149 libindy 1 139901814994688  src/commands/mod.rs:138 \| WalletCommand command received
  | INFO 2019-05-06 22:34:14,150 wallet 1 139902444365568 Opened wallet tob_holder on handle 5
  | INFO 2019-05-06 22:34:14,150 libindy 1 139901814994688  src/commands/mod.rs:134 \| DidCommand command received
  | INFO 2019-05-06 22:34:14,150 libindy 1 139901814994688  src/commands/did.rs:150 \| ListMyDidsWithMeta command received
  | INFO 2019-05-06 22:34:14,160 libindy 1 139901814994688  src/commands/mod.rs:134 \| DidCommand command received
  | INFO 2019-05-06 22:34:14,160 libindy 1 139901814994688  src/commands/did.rs:158 \| KeyForLocalDid command received
  | INFO 2019-05-06 22:34:14,160 libindy 1 139901814994688  src/commands/did.rs:371 \| key_for_local_did >>> wallet_handle: 5, did: "SQHAgHtSHCKUCtxDWFmsfX"
  | INFO 2019-05-06 22:34:14,161 wallet 1 139902444365568 Wallet tob_holder got verkey EqzFEK5umcpo8e6SkBPyxsiYKT3JqwTXwKaicmr3tB7E for existing DID SQHAgHtSHCKUCtxDWFmsfX
  | INFO 2019-05-06 22:34:14,161 libindy 1 139901814994688  src/commands/mod.rs:114 \| AnoncredsCommand command received
  | INFO 2019-05-06 22:34:14,161 libindy 1 139901814994688  src/commands/anoncreds/mod.rs:54 \| Prover command received
  | INFO 2019-05-06 22:34:14,161 libindy 1 139901814994688  src/commands/anoncreds/prover.rs:161 \| CreateMasterSecret command received
  | ERROR 2019-05-06 22:34:14,162 libindy 1 139901814994688     src/errors/indy.rs:73 \| Casting error to ErrorCode: Duplicated master secret: MasterSecret already exists master-secret
  | WARNING 2019-05-06 22:34:14,162 libindy 1 139902444365568 _indy_loop_callback: Function returned error 404
  | INFO 2019-05-06 22:34:14,162 holderprover 1 139902444365568 HolderProver did not create link secret - it already exists
  | INFO 2019-05-06 22:34:14,163 libindy 1 139901814994688  src/commands/mod.rs:126 \| LedgerCommand command received
  | INFO 2019-05-06 22:34:14,163 libindy 1 139901814994688  src/commands/ledger.rs:276 \| BuildGetNymRequest command received
  | INFO 2019-05-06 22:34:14,164 libindy 1 139901814994688  src/services/ledger/mod.rs:82 \| build_get_nym_request >>> identifier: Some("SQHAgHtSHCKUCtxDWFmsfX"), dest: "SQHAgHtSHCKUCtxDWFmsfX"
  | INFO 2019-05-06 22:34:14,164 libindy 1 139901814994688  src/services/ledger/mod.rs:89 \| build_get_nym_request <<< request: "{\"reqId\":1557182054164155222,\"identifier\":\"SQHAgHtSHCKUCtxDWFmsfX\",\"operation\":{\"type\":\"105\",\"dest\":\"SQHAgHtSHCKUCtxDWFmsfX\"},\"protocolVersion\":2}"
  | INFO 2019-05-06 22:34:14,164 libindy 1 139901814994688  src/commands/mod.rs:126 \| LedgerCommand command received
  | INFO 2019-05-06 22:34:14,164 libindy 1 139901814994688  src/commands/ledger.rs:221 \| SubmitRequest command received
  | INFO 2019-05-06 22:34:14,376 libindy 1 139901814994688  src/commands/mod.rs:126 \| LedgerCommand command received
  | INFO 2019-05-06 22:34:14,376 libindy 1 139901814994688  src/commands/ledger.rs:225 \| SubmitAck command received
  | INFO 2019-05-06 22:34:14,376 service 1 139902444365568 Registering DID SQHAgHtSHCKUCtxDWFmsfX
  | INFO 2019-05-06 22:34:14,792 libindy 1 139901814994688  src/commands/mod.rs:126 \| LedgerCommand command received
  | INFO 2019-05-06 22:34:14,792 libindy 1 139901814994688  src/commands/ledger.rs:269 \| BuildGetAttribRequest command received
  | INFO 2019-05-06 22:34:14,792 libindy 1 139901814994688  src/services/ledger/mod.rs:134 \| build_get_attrib_request >>> identifier: Some("SQHAgHtSHCKUCtxDWFmsfX"), dest: "SQHAgHtSHCKUCtxDWFmsfX", hash: None, raw: Some("endpoint"), enc: None
  | INFO 2019-05-06 22:34:14,792 libindy 1 139901814994688  src/services/ledger/mod.rs:144 \| build_get_attrib_request <<< request: "{\"reqId\":1557182054792846873,\"identifier\":\"SQHAgHtSHCKUCtxDWFmsfX\",\"operation\":{\"type\":\"104\",\"dest\":\"SQHAgHtSHCKUCtxDWFmsfX\",\"raw\":\"endpoint\"},\"protocolVersion\":2}"
  | INFO 2019-05-06 22:34:14,793 libindy 1 139901814994688  src/commands/mod.rs:126 \| LedgerCommand command received
  | INFO 2019-05-06 22:34:14,793 libindy 1 139901814994688  src/commands/ledger.rs:221 \| SubmitRequest command received
  | INFO 2019-05-06 22:34:14,999 libindy 1 139901814994688  src/commands/mod.rs:126 \| LedgerCommand command received
  | INFO 2019-05-06 22:34:14,999 libindy 1 139901814994688  src/commands/ledger.rs:225 \| SubmitAck command received
  | INFO 2019-05-06 22:34:14,999 base 1 139902444365568 _AgentCore.get_endpoint: ledger query returned response with no data
  | INFO 2019-05-06 22:34:14,999 base 1 139902444365568 tob_holder endpoint already set as None
  | INFO 2019-05-06 22:34:14,999 service 1 139902444365568 messages.Endpoint stored: None
  | INFO 2019-05-06 22:34:14,999 service 1 139902444365568 Indy agent synced: TheOrgBook_Holder
  | INFO 2019-05-06 22:34:15,000 service 1 139902444365568 Completed sync: indy
  | INFO 2019-05-06 22:34:35,144 helpers 1 139902915413760 172.17.0.1 [06/May/2019:22:34:35 +0000] "GET /health HTTP/1.1" 200 200 "-" "kube-probe/1.11+"
ianco commented 5 years ago

"PoolLedgerTimeout" means your app can't connect to the ledger, usually because of firewall or IP issues.

WadeBarnes commented 5 years ago

Ledger nodes listen on ports ranging from 9700 to 9799. The django pod needs to be able to initiate outbound communications on that port range.

kenhuang commented 5 years ago

Thanks for the suggestion. yes, it was due to the outbound firewall issue.