search

trustbloc / sandbox

Demonstration environments
Apache License 2.0
21 stars 31 forks source link

UI tests fail after restart of all pods #1081

Closed project-administrator closed 2 years ago

project-administrator commented 3 years ago

A restart of the pods triggers all UI tests to fail.

The issue can be reproduced in the local sandbox environment.

Steps to reproduce:

sandbox$ CPUS=6 MEMORY=8g make setup-deploy && sleep 1000 && make automation-test # start the local env and run the tests
## tests succeed

sandbox$ for pod in `kubectl get --no-headers=true pods -o name | grep -Ev 'mysql|couchdb|ipfs'`; do kubectl delete $pod; done # restart all pods except of the DBs

wait for the pods to restart and get into the Running state, and re-run the tests:

sandbox$ make automation-test
## tests fail

all tests will fail. In order to work around this issue, we can re-deploy the jobs:

sandbox/k8s/jobs$ make undeploy
sandbox/k8s/jobs$ make deploy

running the tests will succeed now: 

sandbox$ make automation-test
## tests succeed

Expected result: tests succeed after re-starting all of the pods without running (re-deploying) the jobs.

alialkhalidi commented 2 years ago

updating the restart step to reproduce the issue to include strapi/oathkeeper and list of current persistance-backends:

for pod in $(kubectl get --no-headers=true pods -o name | grep -Ev 'mq|pod/oathkeeper|strapi|postgres|mongodb|ipfs'); do kubectl delete $pod --wait=false; done

This will make all the test except new-bank-account.js test pass. adapter-issuer logs:

[edge-adapter/issuerops] 2021/11/17 22:19:43 UTC - http.WriteErrorResponseWithLog -> ERROR endpoint=[/oidc/request] status=[500] errMsg=[server error]

re-running the issuer_adapter_configure.sh job script makes all the ui-tests to pass, and has the following results:

./issuer_adapter_configure.sh Adding Issuer Adapter profiles 'created' field from profile tb-cc-issuer response is: {"errMessage":"failed to create profile: profile tb-cc-issuer already exists"} 'created' field from profile tb-cr-issuer response is: {"errMessage":"failed to create profile: profile tb-cr-issuer already exists"} 'created' field from profile tb-dl-issuer response is: {"errMessage":"failed to create profile: profile tb-dl-issuer already exists"} Finished adding Issuer Adapter profiles

@rolsonquadras @sudeshrshetty is this something we can fix in the adapter-issuer?

alialkhalidi commented 2 years ago

With the previous PR the remaining set of pods (cms/oathkeeper) are covered. one followup item is to make the cms use profiles job idempotent; it should not fail when data (admin, user, profiles, etc) is already present.

rolsonquadras commented 2 years ago

re-running the issuer_adapter_configure.sh job script makes all the ui-tests to pass, and has the following results:

./issuer_adapter_configure.sh Adding Issuer Adapter profiles 'created' field from profile tb-cc-issuer response is: {"errMessage":"failed to create profile: profile tb-cc-issuer already exists"} 'created' field from profile tb-cr-issuer response is: {"errMessage":"failed to create profile: profile tb-cr-issuer already exists"} 'created' field from profile tb-dl-issuer response is: {"errMessage":"failed to create profile: profile tb-dl-issuer already exists"} Finished adding Issuer Adapter profiles

@rolsonquadras @sudeshrshetty is this something we can fix in the adapter-issuer?

@alialkhalidi we shouldn't create a new profile on restarts - these are one time setups. Is there a way to separate these scripts from restart logic ?

alialkhalidi commented 2 years ago

I'll try to clarify... its not about re-running the jobs; in fact, that is not possible unless we re-deploy the jobs. re-runing the script (from the job) make issuer-adapter work again rendering the ui-tests to the pass, without it, and with a simple restart, it does not.... something is not getting persisted across restarts in adapter-issuer, though the responses from the script state whats expected... data is there. if the profiles are there, why issuer-adapter needs these calls to be back?

alialkhalidi commented 2 years ago

with the latest sandbox/k8s, adapter logging added, and after a restart, adapter-issuer is showing these logs:

[edge-adapter/issuerops] 2021/12/02 23:30:30 UTC - http.WriteErrorResponseWithLog -> ERROR endpoint=[/oidc/request] status=[500] errMsg=[get oidc client: constructing oidc client: failed to init oidc provider with url [tb-cr-issuer] : Get "tb-cr-issuer/.well-known/openid-configuration": unsupported protocol scheme ""]

[edge-adapter/issuerops] 2021/12/02 23:31:34 UTC - http.WriteErrorResponseWithLog -> ERROR endpoint=[/oidc/request] status=[500] errMsg=[get oidc client: constructing oidc client: failed to init oidc provider with url [tb-dl-issuer] : Get "tb-dl-issuer/.well-known/openid-configuration": unsupported protocol scheme ""] I checked mongodb tables, the records show oidc pointing to hydra. the log message shows its missing https://hydra..... is the path correct though?

rolsonquadras commented 2 years ago

The issue has been fixes as part of https://github.com/trustbloc/adapter/issues/552.

@alialkhalidi can you please revalidate the scenario ?

alialkhalidi commented 2 years ago

validated and the issue still exists. restart step update:

for pod in $(kubectl get --no-headers=true pods -o name | grep -Ev 'mq|local-kms|postgres|mongodb|ipfs'); do kubectl delete $pod --wait=false; done

ui-test output:

[0-2] RUNNING in chrome - /test/specs/new-bank-account.js
[0-2] 2021-12-16T01:54:53.799Z WARN webdriver: Request encountered a stale element - terminating request
2021-12-16T01:54:53.821Z WARN chromedriver: [1639619693.821][WARNING]: screenshot failed, retrying disconnected: received Inspector.detached event
[0-2] 2021-12-16T01:54:53.837Z WARN webdriver: Request failed with status 404 due to no such window: target window already closed
[0-2] from unknown error: web view not found
[0-2]   (Session info: headless chrome=96.0.4664.45)
[0-2] 2021-12-16T01:54:59.356Z WARN webdriver: Request encountered a stale element - terminating request
[0-2] (node:1169609) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 1)
[0-2] (Use `node --trace-warnings ...` to show where the warning was created)
[0-2] 2021-12-16T01:55:10.505Z WARN webdriver: Request encountered a stale element - terminating request
[0-2] 2021-12-16T01:55:33.755Z WARN webdriver: Request encountered a stale element - terminating request
[0-2] Error in "TrustBloc - New Bank Account.Get Drivers License and Connect to Assurance Issuer"
Error: element ("iframe") still not existing after 60000ms
    at /home/ali/work/testing/sandbox/test/ui-automation/node_modules/webdriverio/build/commands/browser/waitUntil.js:66:23
    at async Element.wrapCommandFn (/home/ali/work/testing/sandbox/test/ui-automation/node_modules/@wdio/utils/build/shim.js:131:29)
    at async Element.elementErrorHandlerCallbackFn (/home/ali/work/testing/sandbox/test/ui-automation/node_modules/webdriverio/build/middlewares.js:24:32)
    at async Element.wrapCommandFn (/home/ali/work/testing/sandbox/test/ui-automation/node_modules/@wdio/utils/build/shim.js:131:29)
    at async Element.wrapCommandFn (/home/ali/work/testing/sandbox/test/ui-automation/node_modules/@wdio/utils/build/shim.js:131:29)
    at async Element.elementErrorHandlerCallbackFn (/home/ali/work/testing/sandbox/test/ui-automation/node_modules/webdriverio/build/middlewares.js:24:32)
    at async Element.wrapCommandFn (/home/ali/work/testing/sandbox/test/ui-automation/node_modules/@wdio/utils/build/shim.js:131:29)
    at async Object.exports.chooseWallet (/home/ali/work/testing/sandbox/test/ui-automation/test/helpers/chapi.js:14:5)
    at async Context.<anonymous> (/home/ali/work/testing/sandbox/test/ui-automation/test/specs/new-bank-account.js:74:9)
[0-2] Error in "TrustBloc - New Bank Account.Open a Bank Account"
Error: element ("span*=Drivers License") still not clickable after 60000ms
    at /home/ali/work/testing/sandbox/test/ui-automation/node_modules/webdriverio/build/commands/browser/waitUntil.js:66:23
    at async Element.wrapCommandFn (/home/ali/work/testing/sandbox/test/ui-automation/node_modules/@wdio/utils/build/shim.js:131:29)
    at async Element.elementErrorHandlerCallbackFn (/home/ali/work/testing/sandbox/test/ui-automation/node_modules/webdriverio/build/middlewares.js:24:32)
    at async Element.wrapCommandFn (/home/ali/work/testing/sandbox/test/ui-automation/node_modules/@wdio/utils/build/shim.js:131:29)
    at async Element.wrapCommandFn (/home/ali/work/testing/sandbox/test/ui-automation/node_modules/@wdio/utils/build/shim.js:131:29)
    at async Element.elementErrorHandlerCallbackFn (/home/ali/work/testing/sandbox/test/ui-automation/node_modules/webdriverio/build/middlewares.js:24:32)
    at async Element.wrapCommandFn (/home/ali/work/testing/sandbox/test/ui-automation/node_modules/@wdio/utils/build/shim.js:131:29)
    at async Context.<anonymous> (/home/ali/work/testing/sandbox/test/ui-automation/test/specs/new-bank-account.js:100:9)
[0-2] (node:1169609) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 2)
[0-2] (node:1169609) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 3)
[0-2] (node:1169609) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 6)
[0-2] (node:1169609) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 8)
[0-2] FAILED in chrome - /test/specs/new-bank-account.js

job issuer_adapter.sh script re-run output:

Adding Issuer Adapter profiles
'created' field from profile tb-cc-issuer response is: {"errMessage":"failed to create profile: profile tb-cc-issuer already exists"}
'created' field from profile tb-cr-issuer response is: {"errMessage":"failed to create profile: profile tb-cr-issuer already exists"}
'created' field from profile tb-dl-issuer response is: {"errMessage":"failed to create profile: profile tb-dl-issuer already exists"}
Finished adding Issuer Adapter profiles
Adding Issuer Adapter profiles
'created' field from profile tb-cc-issuer response is: {"errMessage":"failed to create profile: profile tb-cc-issuer already exists"}
'created' field from profile tb-cr-issuer response is: {"errMessage":"failed to create profile: profile tb-cr-issuer already exists"}
'created' field from profile tb-dl-issuer response is: {"errMessage":"failed to create profile: profile tb-dl-issuer already exists"}
Finished adding Issuer Adapter profiles

after which the failing test pass!

rolsonquadras commented 2 years ago

@alialkhalidi would it be possible to share the issuer-adapter failure logs ?

alialkhalidi commented 2 years ago

issuer-adapter logs:

 [edge-adapter/wallet-bridge] 2021/12/16 14:50:12 UTC - http.WriteErrorResponseWithLog -> ERROR endpoint=[/wallet-bridge/get-preferences/{id}] status=[500] errMsg=[data not found]
 [edge-adapter/issuerops] 2021/12/16 14:50:17 UTC - http.WriteResponseWithLog -> INFO endpoint=[/issuer/didcomm/chapi/request] msg=[success]
 [edge-adapter/wallet-bridge] 2021/12/16 14:50:17 UTC - operation.(*Operation).SaveWalletPreferences -> INFO endpoint=[/wallet-bridge/save-preferences] msg=[success]
 [edge-adapter/wallet-bridge] 2021/12/16 14:50:25 UTC - operation.(*Operation).stateMsgListener -> WARNING Failed to update wallet application profile with invitationID=954db1b0-42ec-4b9b-861c-93d9d2472e51 and connectionID=c2401236-2d69-427b-ada3-f72075480596: failed to get user info for given invitation ID [954db1b0-42ec-4b9b-861c-93d9d2472e51]: data not found
 [aries-framework/out-of-band/service] 2021/12/16 14:50:25 UTC - n/a -> ERROR command=[out-of-band] action=[handleDIDEvent] [] errMsg=[handleDIDEvent: ParentThreadID is empty]
 [edge-adapter/msgsvc] 2021/12/16 14:50:25 UTC - route.(*Service).didCommMsgListener -> INFO msgType=[https://trustbloc.dev/blinded-routing/1.0/diddoc-req] id=[0474514b-28af-497a-b52b-26bc70ec750d] msg=[success]
 [edge-adapter/msgsvc] 2021/12/16 14:50:28 UTC - route.(*Service).didCommMsgListener -> INFO msgType=[https://trustbloc.dev/blinded-routing/1.0/register-route-req] id=[e43fdef8-9318-4f4c-b887-934a9f6a7f68] msg=[success]
 [edge-adapter/issuerops] 2021/12/16 14:50:29 UTC - http.WriteResponseWithLog -> INFO endpoint=[/connect/validate] msg=[success]
 [edge-adapter/issuerops] 2021/12/16 14:50:37 UTC - http.WriteErrorResponseWithLog -> ERROR endpoint=[/issuer/didcomm/chapi/request] status=[500] errMsg=[error creating reference credential : create credential : failed to execute http request: http request: 500 no valid credential scope]
rolsonquadras commented 2 years ago

The issue has been fixed in trustbloc/adapter#576.

Verified the changes locally:

  1. deploy components
  2. run automation tests - all pass
  3. restart pods for pod in $(kubectl get --no-headers=true pods -o name | grep -Ev 'mq|local-kms|postgres|mongodb|ipfs'); do kubectl delete $pod --wait=false; done
  4. run automation test - all pass

@alialkhalidi can you please verify this as well ?

alialkhalidi commented 2 years ago

@rolsonquadras verified and all ui-test pass now. Thanks!!. closing.