Avoid concurrent shutdown of Infinispan caches to avoid lockup. by ahus1 · Pull Request #10288 · keycloak/keycloak

ahus1 · 2022-02-17T10:22:55Z

ahus1 · 2022-02-25T09:07:08Z

Modeltest was in the green! Close/Open to trigger pipeline.

ahus1 · 2022-02-28T10:37:13Z

This change now combines multiple optimizations in logging and error handling for the model tests related to Infinispan. The tests work now more reliably, at the same time there might be more problematic things in the code.

A review feedback would include which changes to keep in this PR and which not, and maybe to split it into multiple PRs.

martin-kanis · 2022-03-03T08:36:56Z

@ahus1 Thanks for the improvements. It looks good to me.
As Hynek proposed on the call, it would be good to extract change related to PersistenceManagerImpl.java to a separate commit.
Another thing to consider is to introduce this method

protected void awaitLatch(CountDownLatch latch) {
        try {
            latch.await();
        } catch (InterruptedException e) {
            throw new RuntimeException(e);
        }
    }

to the KeycloakModelTest as a util method and use it across model tests. It became a common pattern in the model test. I introduced the method in UserSessionProviderOfflineModelTest but it's private there. The refactoring doesn't need to be included in this PR as it's not strictly related to this issue.

This is tracked in upstream issue https://issues.redhat.com/browse/ISPN-13664 Closes keycloak#10016

ahus1 · 2022-03-03T10:56:51Z

@martin-kanis - thanks for pointing me to the existing latch logic; I missed it as I was looking only at test failures.

I took this one step further than you suggested and made the start/stop latch the default for all inIndependentFactories() as it looked strange to me to do it for some but not all of them. The awaitLatch() stayed where it was as it is still used in one place. I also ensured that the interrupted flag for the thread is set properly: otherwise the next await or sleep might not see it.

I pushed the changes, the build is still running. Please re-review.

…eport any exceptions within another thread as a test failure. Adding additional information like a thread dump when it doesn't shutdown as expected. Closes keycloak#10016

ahus1 · 2022-03-03T17:51:36Z

The test on GHA failed due to a transient (?) problem when communicating with LDAP.

[ERROR] org.keycloak.testsuite.model.UserModelTest.testAddDirtyRemoveFederationUsersInTheSameGroupConcurrent  Time elapsed: 2.35 s  <<< ERROR!
org.keycloak.models.ModelException: Could not unbind DN [uid=user-68,ou=People,dc=keycloak,dc=org]
   at org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager.destroySubcontext(LDAPOperationManager.java:475)
   at org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager.access$100(LDAPOperationManager.java:67)
   at org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager$1.execute(LDAPOperationManager.java:160)
   at org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager$1.execute(LDAPOperationManager.java:153)
   at org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager.execute(LDAPOperationManager.java:731)
   at org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager.execute(LDAPOperationManager.java:711)
   at org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager.execute(LDAPOperationManager.java:706)
   at org.keycloak.storage.ldap.idm.store.ldap.LDAPOperationManager.removeEntry(LDAPOperationManager.java:153)
   at org.keycloak.storage.ldap.idm.store.ldap.LDAPIdentityStore.remove(LDAPIdentityStore.java:234)
   at org.keycloak.storage.ldap.LDAPStorageProvider.removeUser(LDAPStorageProvider.java:322)
   at org.keycloak.testsuite.model.UserModelTest.lambda$testAddDirtyRemoveFederationUsersInTheSameGroupConcurrent$15(UserModelTest.java:216)
   at java.base/java.util.stream.Streams$RangeIntSpliterator.forEachRemaining(Streams.java:104)
   at java.base/java.util.stream.IntPipeline$Head.forEach(IntPipeline.java:593)
   at org.keycloak.testsuite.model.UserModelTest.lambda$testAddDirtyRemoveFederationUsersInTheSameGroupConcurrent$16(UserModelTest.java:214)
   at org.keycloak.testsuite.model.KeycloakModelTest.lambda$withRealm$13(KeycloakModelTest.java:631)
   at org.keycloak.testsuite.model.KeycloakModelTest.lambda$inComittedTransaction$11(KeycloakModelTest.java:596)
   at org.keycloak.testsuite.model.KeycloakModelTest.lambda$inComittedTransaction$12(KeycloakModelTest.java:613)
   at org.keycloak.models.utils.KeycloakModelUtils.runJobInTransaction(KeycloakModelUtils.java:239)
   at org.keycloak.testsuite.model.KeycloakModelTest.inComittedTransaction(KeycloakModelTest.java:601)
   at org.keycloak.testsuite.model.KeycloakModelTest.inComittedTransaction(KeycloakModelTest.java:596)
   at org.keycloak.testsuite.model.KeycloakModelTest.withRealm(KeycloakModelTest.java:628)
   at org.keycloak.testsuite.model.UserModelTest.testAddDirtyRemoveFederationUsersInTheSameGroupConcurrent(UserModelTest.java:211)
   at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
   at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

Added a retry, also stabilized some more tests and fixed some of the logging so it doesn't log to STDERR and pollutes the GHA: 572c769b1e11977f99deeb73338ab31e8700a3ec

Let's see what the next run brings, and see the results tomorrow.

ahus1 · 2022-03-03T19:30:06Z

@martin-kanis - Model tests are green, ready to continue your review.

martin-kanis · 2022-03-04T08:54:59Z

@ahus1 Thank you for the update. I see the logs from model tests and they are very big. Around 107 MB so I need to download them because my browser can't handle it. There are many stacktraces related to Infinispan. So I am wondering if we can get rid of them. WDYT?

ahus1 · 2022-03-04T08:57:11Z

@martin-kanis - reducing the amount of logs gets a +1 from me. I'd like to have it in a separate ticket, and I'm happy to look into it after this issue. Please open an issue an link it to this one.

martin-kanis · 2022-03-04T09:08:21Z

@martin-kanis - reducing the amount of logs gets a +1 from me. I'd like to have it in a separate ticket, and I'm happy to look into it after this issue. Please open an issue an link it to this one.

Here it is #10588. Thank you!

martin-kanis

Thanks @ahus1. Looks good.

hmlnarik

Thanks for the PR!

ahus1 added area/storage Indicates an issue that touches storage (change in data layout or data manipulation) kind/bug Categorizes a PR related to a bug team/storage-sig labels Feb 17, 2022

ahus1 self-assigned this Feb 17, 2022

hmlnarik reviewed Feb 22, 2022

View reviewed changes

Comment thread testsuite/model/src/test/java/org/keycloak/testsuite/model/KeycloakModelTest.java Outdated

ahus1 marked this pull request as draft February 22, 2022 10:00

ahus1 commented Feb 22, 2022

View reviewed changes

Comment thread testsuite/model/src/test/java/org/keycloak/testsuite/model/infinispan/CacheExpirationTest.java Outdated

ahus1 closed this Feb 24, 2022

ahus1 reopened this Feb 24, 2022

ahus1 closed this Feb 25, 2022

ahus1 reopened this Feb 25, 2022

ahus1 closed this Feb 25, 2022

ahus1 reopened this Feb 25, 2022

ahus1 force-pushed the 10016-soft-shutdown-of-infinispan branch 2 times, most recently from 7bc50a1 to a4b7556 Compare February 28, 2022 07:16

ahus1 marked this pull request as ready for review February 28, 2022 10:34

ahus1 assigned hmlnarik Feb 28, 2022

ahus1 requested review from hmlnarik and martin-kanis February 28, 2022 10:37

martin-kanis reviewed Mar 3, 2022

View reviewed changes

Comment thread testsuite/model/src/test/java/org/keycloak/testsuite/model/infinispan/CacheExpirationTest.java Outdated

Workaround for deadlock when shutting down Infinispan in 12.1.7.Final.

2d7c20a

This is tracked in upstream issue https://issues.redhat.com/browse/ISPN-13664 Closes keycloak#10016

ahus1 force-pushed the 10016-soft-shutdown-of-infinispan branch from a4b7556 to a517bf7 Compare March 3, 2022 10:52

ahus1 requested a review from martin-kanis March 3, 2022 10:56

Ensure that Infinispan shutdowns correctly at the end of the tests. R…

8badea0

…eport any exceptions within another thread as a test failure. Adding additional information like a thread dump when it doesn't shutdown as expected. Closes keycloak#10016

ahus1 force-pushed the 10016-soft-shutdown-of-infinispan branch from 572c769 to 8badea0 Compare March 3, 2022 17:34

martin-kanis mentioned this pull request Mar 4, 2022

Reduce log size for the model tests #10588

Closed

martin-kanis approved these changes Mar 4, 2022

View reviewed changes

ahus1 added the status/ready label Mar 4, 2022

hmlnarik approved these changes Mar 4, 2022

View reviewed changes

hmlnarik merged commit ebfc24d into keycloak:main Mar 4, 2022

Uh oh!

Conversation

ahus1 commented Feb 17, 2022

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

ahus1 commented Feb 25, 2022

Uh oh!

ahus1 commented Feb 28, 2022

Uh oh!

Uh oh!

martin-kanis commented Mar 3, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

ahus1 commented Mar 3, 2022

Uh oh!

ahus1 commented Mar 3, 2022

Uh oh!

ahus1 commented Mar 3, 2022

Uh oh!

martin-kanis commented Mar 4, 2022

Uh oh!

ahus1 commented Mar 4, 2022

Uh oh!

martin-kanis commented Mar 4, 2022

Uh oh!

martin-kanis left a comment

Choose a reason for hiding this comment

Uh oh!

hmlnarik left a comment

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

martin-kanis commented Mar 3, 2022 •

edited

Loading