[CI] testExpiredTokensDeletedAfterExpiration fails in assertBusy #37063

tvernum · 2019-01-02T03:28:38Z

From https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+corretto-periodic/ES_BUILD_JAVA=openjdk12,label=amazon/27/console

Does not reproduce.

./gradlew :x-pack:plugin:security:unitTest -Dtests.seed=7676C6812F4AA719 -Dtests.class=org.elasticsearch.xpack.security.authc.TokenAuthIntegTests -Dtests.method="testExpiredTokensDeletedAfterExpiration"

01:57:29 FAILURE 35.6s J7 | TokenAuthIntegTests.testExpiredTokensDeletedAfterExpiration <<< FAILURES!
01:57:29    > Throwable #1: java.lang.AssertionError: 
01:57:29    > Expected: <0L>
01:57:29    >      but: was <1L>
01:57:29    > 	at __randomizedtesting.SeedInfo.seed([7676C6812F4AA719:7757D298140CE808]:0)
01:57:29    > 	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
01:57:29    > 	at org.elasticsearch.xpack.security.authc.TokenAuthIntegTests.lambda$testExpiredTokensDeletedAfterExpiration$1(TokenAuthIntegTests.java:189)
01:57:29    > 	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:847)
01:57:29    > 	at org.elasticsearch.xpack.security.authc.TokenAuthIntegTests.testExpiredTokensDeletedAfterExpiration(TokenAuthIntegTests.java:171)
01:57:29    > 	at java.lang.Thread.run(Thread.java:748)
01:57:29    > 	Suppressed: java.lang.AssertionError: 
01:57:29    > Expected: <0L>
01:57:29    >      but: was <1L>
01:57:29    > 		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
01:57:29    > 		at org.elasticsearch.xpack.security.authc.TokenAuthIntegTests.lambda$testExpiredTokensDeletedAfterExpiration$1(TokenAuthIntegTests.java:189)
01:57:29    > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:835)
01:57:29    > 		... 40 more
01:57:29    > 	Suppressed: java.lang.AssertionError: 
01:57:29    > Expected: <0L>
01:57:29    >      but: was <1L>

I have a couple of ideas about what could cause this:

If securityClient.prepareInvalidateToken("fooobar") fails in an unexpected way then that exception will occur inside the assertBusy and not stop the test, but it might mean that the token removed was never started. I don't see any evidence of that in the logs though.
Due to clock/DST changes, etc. It's possible that setting the token's creation time back by 1 day isn't enough to trigger its deletion (The remover looks for tokens that are 24h old). Setting it back 36 hours would be more reliable.

The text was updated successfully, but these errors were encountered:

elasticmachine · 2019-01-02T03:28:39Z

Pinging @elastic/es-security

tvernum · 2019-01-02T04:27:40Z

Another failure.
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-unix-compatibility/os=fedora/155/consoleFull

./gradlew :x-pack:plugin:security:unitTest -Dtests.seed=A48F36938E17E1F2 \
-Dtests.class=org.elasticsearch.xpack.security.authc.TokenAuthIntegTests \
-Dtests.method="testExpiredTokensDeletedAfterExpiration" \
-Dtests.security.manager=true -Dtests.locale=da -Dtests.timezone=Africa/Lome -Dcompiler.java=11 -Druntime.java=8

In this case it seems to be caused by scenario 1, but it doesn't reproduce.

02:29:56 FAILURE 36.0s J7 | TokenAuthIntegTests.testExpiredTokensDeletedAfterExpiration <<< FAILURES!
02:29:56    > Throwable #1: java.lang.AssertionError: 
02:29:56    > Expected: <0L>
02:29:56    >      but: was <1L>
02:29:56    > 	at __randomizedtesting.SeedInfo.seed([A48F36938E17E1F2:A5AE228AB551AEE3]:0)
02:29:56    > 	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
02:29:56    > 	at org.elasticsearch.xpack.security.authc.TokenAuthIntegTests.lambda$testExpiredTokensDeletedAfterExpiration$1(TokenAuthIntegTests.java:189)
02:29:56    > 	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:847)
02:29:56    > 	at org.elasticsearch.xpack.security.authc.TokenAuthIntegTests.testExpiredTokensDeletedAfterExpiration(TokenAuthIntegTests.java:171)
02:29:56    > 	at java.lang.Thread.run(Thread.java:748)
02:29:56    > 	Suppressed: org.junit.ComparisonFailure: expected:<[token malformed]> but was:<[invalid_grant]>
02:29:56    > 		at

tvernum · 2019-01-02T08:59:33Z

And again. I'm going to mute this.
@jkakavas Can you have a look, I guess something in #36893 or #36766 made this fragile.

jkakavas · 2019-01-02T21:55:35Z

I got it to reproduce "consistently" (after 4-8 consecutive runs with -Dtest.iters). My initial thinking was that the issue is a race condition in the test and that the delete by query at

elasticsearch/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/authc/ExpiredTokenRemover.java

Line 65 in 265fdce

    
           executeAsyncWithOrigin(client, SECURITY_ORIGIN, DeleteByQueryAction.INSTANCE, expiredDbq,

doesn't get executed before the subsequent search request in the test at

elasticsearch/x-pack/plugin/security/src/test/java/org/elasticsearch/xpack/security/authc/TokenAuthIntegTests.java

Line 152 in 0cae979

    
           SearchResponse searchResponse = client.prepareSearch(SecurityIndexManager.SECURITY_INDEX_NAME)

but that would be taken care of by the retries in the assertBusy block. It turns out that the issue is with

elasticsearch/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/authc/TokenService.java

Line 1076 in 0cae979

    
           if (client.threadPool().relativeTimeInMillis() - lastExpirationRunMs > deleteInterval.getMillis()) {

and the fact that we submit an invalidation request also a little further up on the same test. This has the effect that the two invalidation requests are executed with ~1s interval and as the deleteInterval is set to 1s, this fails often. (The ones that pass, pass because the second invalidation request happens to be executed after 1001 to 1200 milliseconds )

This manifests now as we removed the bwc invalidation logic and this made the invalidation duration much shorter

What doesn't fit with this theory is the

Suppressed: org.junit.ComparisonFailure: expected:<[token malformed]> but was:<[invalid_grant]>

that was seen in CI as the only way to get an invalid_grant Exception during invalidation of a specific token is to attempt and invalidate a token that doesn't exist or hit the max attempt counter

Setting it back 36 hours would be more reliable.

I adjusted this and it didn't make a difference but this is a very good suggestion regardless of the issue at hand.

I adjusted the deleteInterval to 200 ms for these tests so that we don't encounter this anymore

Relates to #37063

tlrx · 2019-02-27T10:08:35Z

This test failed on 6.7 today:
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.7+multijob-unix-compatibility/os=oraclelinux-6/42/consoleFull

(edited by @jkakavas to add formatting)

java.lang.AssertionError: 
Expected: <0L>
     but: was <1L>
	at __randomizedtesting.SeedInfo.seed([6E90AD157E24A0E8:6FB1B90C4562EFF9]:0)
	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
	at org.junit.Assert.assertThat(Assert.java:956)
	at org.junit.Assert.assertThat(Assert.java:923)
	at org.elasticsearch.xpack.security.authc.TokenAuthIntegTests.lambda$testExpiredTokensDeletedAfterExpiration$1(TokenAuthIntegTests.java:195)
	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:858)
	at org.elasticsearch.xpack.security.authc.TokenAuthIntegTests.testExpiredTokensDeletedAfterExpiration(TokenAuthIntegTests.java:176)
	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 com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1750)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:938)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:974)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:988)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:48)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
	at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:947)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:832)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:883)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:894)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:48)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
	at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
	at java.lang.Thread.run(Thread.java:748)
	Suppressed: org.junit.ComparisonFailure: expected:<[token malformed]> but was:<[invalid_grant]>
		at org.junit.Assert.assertEquals(Assert.java:115)
		at org.junit.Assert.assertEquals(Assert.java:144)
		at org.elasticsearch.xpack.security.authc.TokenAuthIntegTests.lambda$testExpiredTokensDeletedAfterExpiration$1(TokenAuthIntegTests.java:185)
		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:846)
		... 40 more
	Suppressed: java.lang.AssertionError: 
Expected: <0L>
     but: was <1L>
		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
		at org.junit.Assert.assertThat(Assert.java:956)
		at org.junit.Assert.assertThat(Assert.java:923)
		at org.elasticsearch.xpack.security.authc.TokenAuthIntegTests.lambda$testExpiredTokensDeletedAfterExpiration$1(TokenAuthIntegTests.java:195)
		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:846)
		... 40 more
	Suppressed: java.lang.AssertionError: 
Expected: <0L>
     but: was <1L>
		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
		at org.junit.Assert.assertThat(Assert.java:956)
		at org.junit.Assert.assertThat(Assert.java:923)
		at org.elasticsearch.xpack.security.authc.TokenAuthIntegTests.lambda$testExpiredTokensDeletedAfterExpiration$1(TokenAuthIntegTests.java:195)
		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:846)
		... 40 more
	Suppressed: java.lang.AssertionError: 
Expected: <0L>
     but: was <1L>
		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
		at org.junit.Assert.assertThat(Assert.java:956)
		at org.junit.Assert.assertThat(Assert.java:923)
		at org.elasticsearch.xpack.security.authc.TokenAuthIntegTests.lambda$testExpiredTokensDeletedAfterExpiration$1(TokenAuthIntegTests.java:195)
		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:846)
		... 40 more
	Suppressed: java.lang.AssertionError: 
Expected: <0L>
     but: was <1L>
		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
		at org.junit.Assert.assertThat(Assert.java:956)
		at org.junit.Assert.assertThat(Assert.java:923)
		at org.elasticsearch.xpack.security.authc.TokenAuthIntegTests.lambda$testExpiredTokensDeletedAfterExpiration$1(TokenAuthIntegTests.java:195)
		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:846)
		... 40 more
	Suppressed: java.lang.AssertionError: 
Expected: <0L>
     but: was <1L>
		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
		at org.junit.Assert.assertThat(Assert.java:956)
		at org.junit.Assert.assertThat(Assert.java:923)
		at org.elasticsearch.xpack.security.authc.TokenAuthIntegTests.lambda$testExpiredTokensDeletedAfterExpiration$1(TokenAuthIntegTests.java:195)
		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:846)
		... 40 more
	Suppressed: java.lang.AssertionError: 
Expected: <0L>
     but: was <1L>
		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
		at org.junit.Assert.assertThat(Assert.java:956)
		at org.junit.Assert.assertThat(Assert.java:923)
		at org.elasticsearch.xpack.security.authc.TokenAuthIntegTests.lambda$testExpiredTokensDeletedAfterExpiration$1(TokenAuthIntegTests.java:195)
		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:846)
		... 40 more
	Suppressed: java.lang.AssertionError: 
Expected: <0L>
     but: was <1L>
		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
		at org.junit.Assert.assertThat(Assert.java:956)
		at org.junit.Assert.assertThat(Assert.java:923)
		at org.elasticsearch.xpack.security.authc.TokenAuthIntegTests.lambda$testExpiredTokensDeletedAfterExpiration$1(TokenAuthIntegTests.java:195)
		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:846)
		... 40 more
	Suppressed: java.lang.AssertionError: 
Expected: <0L>
     but: was <1L>
		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
		at org.junit.Assert.assertThat(Assert.java:956)
		at org.junit.Assert.assertThat(Assert.java:923)
		at org.elasticsearch.xpack.security.authc.TokenAuthIntegTests.lambda$testExpiredTokensDeletedAfterExpiration$1(TokenAuthIntegTests.java:195)
		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:846)
		... 40 more
	Suppressed: java.lang.AssertionError: 
Expected: <0L>
     but: was <1L>
		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
		at org.junit.Assert.assertThat(Assert.java:956)
		at org.junit.Assert.assertThat(Assert.java:923)
		at org.elasticsearch.xpack.security.authc.TokenAuthIntegTests.lambda$testExpiredTokensDeletedAfterExpiration$1(TokenAuthIntegTests.java:195)
		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:846)
		... 40 more
	Suppressed: java.lang.AssertionError: 
Expected: <0L>
     but: was <1L>
		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
		at org.junit.Assert.assertThat(Assert.java:956)
		at org.junit.Assert.assertThat(Assert.java:923)
		at org.elasticsearch.xpack.security.authc.TokenAuthIntegTests.lambda$testExpiredTokensDeletedAfterExpiration$1(TokenAuthIntegTests.java:195)
		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:846)
		... 40 more
	Suppressed: java.lang.AssertionError: 
Expected: <0L>
     but: was <1L>
		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
		at org.junit.Assert.assertThat(Assert.java:956)
		at org.junit.Assert.assertThat(Assert.java:923)
		at org.elasticsearch.xpack.security.authc.TokenAuthIntegTests.lambda$testExpiredTokensDeletedAfterExpiration$1(TokenAuthIntegTests.java:195)
		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:846)
		... 40 more
	Suppressed: java.lang.AssertionError: 
Expected: <0L>
     but: was <1L>
		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
		at org.junit.Assert.assertThat(Assert.java:956)
		at org.junit.Assert.assertThat(Assert.java:923)
		at org.elasticsearch.xpack.security.authc.TokenAuthIntegTests.lambda$testExpiredTokensDeletedAfterExpiration$1(TokenAuthIntegTests.java:195)
		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:846)
		... 40 more
	Suppressed: java.lang.AssertionError: 
Expected: <0L>
     but: was <1L>
		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
		at org.junit.Assert.assertThat(Assert.java:956)
		at org.junit.Assert.assertThat(Assert.java:923)
		at org.elasticsearch.xpack.security.authc.TokenAuthIntegTests.lambda$testExpiredTokensDeletedAfterExpiration$1(TokenAuthIntegTests.java:195)
		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:846)
		... 40 more
	Suppressed: java.lang.AssertionError: 
Expected: <0L>
     but: was <1L>
		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
		at org.junit.Assert.assertThat(Assert.java:956)
		at org.junit.Assert.assertThat(Assert.java:923)
		at org.elasticsearch.xpack.security.authc.TokenAuthIntegTests.lambda$testExpiredTokensDeletedAfterExpiration$1(TokenAuthIntegTests.java:195)
		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:846)
		... 40 more

I'm reopening this issue to raise your attention @jkakavas (maybe just a fix to backport?) since I muted the test on 6.7 in 0002203

We run subsequent token invalidation requests and we still want to trigger the deletion of expired tokens so we need to lower the deleteInterval parameter significantly. Especially now that the bwc expiration logic is removed and the invalidation process is much shorter Resolves #37063

jkakavas · 2019-02-27T11:32:48Z

Resolved in c7a193f by backporting the fix, thanks @tlrx !

We run subsequent token invalidation requests and we still want to trigger the deletion of expired tokens so we need to lower the deleteInterval parameter significantly. Especially now that the bwc expiration logic is removed and the invalidation process is much shorter Resolves #37063

tvernum added >test-failure Triaged test failures from CI :Security/Authentication Logging in, Usernames/passwords, Realms (Native/LDAP/AD/SAML/PKI/etc) labels Jan 2, 2019

tvernum assigned jkakavas Jan 2, 2019

jkakavas closed this as completed in f0cd19f Jan 2, 2019

tlrx added a commit that referenced this issue Feb 27, 2019

Mute TokenAuthIntegTests.testExpiredTokensDeletedAfterExpiration()

0002203

Relates to #37063

tlrx reopened this Feb 27, 2019

jkakavas closed this as completed Feb 27, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[CI] testExpiredTokensDeletedAfterExpiration fails in assertBusy #37063

[CI] testExpiredTokensDeletedAfterExpiration fails in assertBusy #37063

tvernum commented Jan 2, 2019

elasticmachine commented Jan 2, 2019

tvernum commented Jan 2, 2019

tvernum commented Jan 2, 2019

jkakavas commented Jan 2, 2019

tlrx commented Feb 27, 2019 •

edited by jkakavas

Loading

jkakavas commented Feb 27, 2019

[CI] testExpiredTokensDeletedAfterExpiration fails in assertBusy #37063

[CI] testExpiredTokensDeletedAfterExpiration fails in assertBusy #37063

Comments

tvernum commented Jan 2, 2019

elasticmachine commented Jan 2, 2019

tvernum commented Jan 2, 2019

tvernum commented Jan 2, 2019

jkakavas commented Jan 2, 2019

tlrx commented Feb 27, 2019 • edited by jkakavas Loading

jkakavas commented Feb 27, 2019

tlrx commented Feb 27, 2019 •

edited by jkakavas

Loading