ddap-dam deployment fails occasionally because of a 500 error during deployment

[monicavalluri]

Error Log:

[chaopeng]

Need more information: The error stack looks from ddap. It does not make sense this error when deployment, find auth token state which is a temporary state in login process.

[monicavalluri]

@mbarkley

[mbarkley]

Hey @chaopeng, the headers and response body at the top of those logs is what was returned to us by the DAM in that test run. We don't have any additional information, other than that this occasionally is returned to us during the login process.

We get this response from the IC after we have logged in to wallet (the IDP configured in our IC), at some point before being redirected back to the client (DDAP) redirect URI. The point in our test that fails is expecting us to be on the IC consent page, so it could be that page, or the redirect URI the IC uses when doing OIDC with wallet.

[mbarkley]

Here is an update log of what I think is the same problem from today. The stack trace indicates that the test failed to login (you can also see that from the redirect at the top of the output). This happened while two deployments were running e2e tests at the same time in our staging environment.

Test set: com.dnastack.ddap.server.AutoCompleteApiTest
-------------------------------------------------------------------------------
Tests run: 2, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 18.375 s <<< FAILURE! - in com.dnastack.ddap.server.AutoCompleteApiTest
shouldFindSuggestionsForVariableValues(com.dnastack.ddap.server.AutoCompleteApiTest)  Time elapsed: 5.142 s  <<< FAILURE!
java.lang.AssertionError: 
Redirects:
    https://wallet.staging.dnastack.com/oauth/authorize?client_id=dde7c021-df74-429a-bf04-2bcdb6b0bdfb&login_hint=monica%40dnastack.com&prompt=login+consent&redirect_uri=https%3A%2F%2Fidentity-concentrator.staging.dnastack.com%2Fidentity%2Floggedin&response_type=code&scope=openid+ga4gh_passport_v1+profile+email+identities&state=38dd35b8-3768-4da9-999f-590be0cae1b7
    https://identity-concentrator.staging.dnastack.com/identity/loggedin?code=eyJhbGciOiJIUzI1NiJ9.eyJ0b2tlbktpbmQiOiJjb2RlIiwiZXhwIjoxNTg3MTUzNDA2LCJhenAiOiJkZGU3YzAyMS1kZjc0LTQyOWEtYmYwNC0yYmNkYjZiMGJkZmIiLCJzdWIiOiIyMTU4NWJmNC0zZWYxLTQxNjgtYjJlYy1hYTZhZWU5NzJlNTkiLCJzY29wZSI6Im9wZW5pZCBnYTRnaF9wYXNzcG9ydF92MSBwcm9maWxlIGVtYWlsIGlkZW50aXRpZXMiLCJpYXQiOjE1ODcxNTI4MDZ9.dnZjkV9NUT8UMzFE1wEQXlHX5jNynLbwLZdUW7LISmA&state=38dd35b8-3768-4da9-999f-590be0cae1b7
    https://identity-concentrator.staging.dnastack.com/identity/v1alpha/master/loggedin/wallet?code=eyJhbGciOiJIUzI1NiJ9.eyJ0b2tlbktpbmQiOiJjb2RlIiwiZXhwIjoxNTg3MTUzNDA2LCJhenAiOiJkZGU3YzAyMS1kZjc0LTQyOWEtYmYwNC0yYmNkYjZiMGJkZmIiLCJzdWIiOiIyMTU4NWJmNC0zZWYxLTQxNjgtYjJlYy1hYTZhZWU5NzJlNTkiLCJzY29wZSI6Im9wZW5pZCBnYTRnaF9wYXNzcG9ydF92MSBwcm9maWxlIGVtYWlsIGlkZW50aXRpZXMiLCJpYXQiOjE1ODcxNTI4MDZ9.dnZjkV9NUT8UMzFE1wEQXlHX5jNynLbwLZdUW7LISmA&state=38dd35b8-3768-4da9-999f-590be0cae1b7

Headers: [Content-Length: 57, Content-Type: text/plain; charset=utf-8, Date: Fri, 17 Apr 2020 19:46:47 GMT]
Response body: {"code":13,"message":"datastore: concurrent transaction"}
Expected: is <200>
     but: was <500>
    at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
    at com.dnastack.ddap.common.WalletLoginStrategy.walletLogin(WalletLoginStrategy.java:111)
    at com.dnastack.ddap.common.WalletLoginStrategy.performPersonaLogin(WalletLoginStrategy.java:73)
    at com.dnastack.ddap.common.AbstractBaseE2eTest.fetchRealPersonaToken(AbstractBaseE2eTest.java:262)
    at com.dnastack.ddap.common.AbstractBaseE2eTest.fetchRealPersonaRefreshToken(AbstractBaseE2eTest.java:254)
    at com.dnastack.ddap.common.AbstractBaseE2eTest.fetchRealPersonaRefreshToken(AbstractBaseE2eTest.java:258)
    at com.dnastack.ddap.server.AutoCompleteApiTest.shouldFindSuggestionsForVariableValues(AutoCompleteApiTest.java:61)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
    at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
    at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
    at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
    at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
    at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
    at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
    at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:365)
    at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:273)
    at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:238)
    at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:159)
    at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:384)
    at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:345)
    at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:126)
    at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:418)

[cdvoisin]

Just wanted to check to see if this is still happening, or has been resolved via various fixes and/or component upgrades?

[mbarkley]

It is not happening nearly as much, but I have still seen it a few times since the v0.9.5 release.