Elasticsearch: [CI] testExpiredTokensDeletedAfterExpiration fails in assertBusy

Created on 2 Jan 2019  路  6Comments  路  Source: elastic/elasticsearch

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:

  1. 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.
  2. 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.
:SecuritAuthentication >test-failure
Source
picture tvernum

All 6 comments

Pinging @elastic/es-security

elasticmachine picture elasticmachine on 2 Jan 2019

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 picture tvernum on 2 Jan 2019

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

tvernum picture tvernum on 2 Jan 2019
👍1

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 https://github.com/elastic/elasticsearch/blob/265fdce312fbe8301d7f563eeaf9c0b8da6bfd61/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/authc/ExpiredTokenRemover.java#L65

doesn't get executed before the subsequent search request in the test at
https://github.com/elastic/elasticsearch/blob/0cae979dfe14274e3d9a277a7ad20872f3c29d26/x-pack/plugin/security/src/test/java/org/elasticsearch/xpack/security/authc/TokenAuthIntegTests.java#L152

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

https://github.com/elastic/elasticsearch/blob/0cae979dfe14274e3d9a277a7ad20872f3c29d26/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/authc/TokenService.java#L1076

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

jkakavas picture jkakavas on 2 Jan 2019

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 00022032f6ccdeb500ad11669c718db54726dffb

tlrx picture tlrx on 27 Feb 2019
👍1

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

jkakavas picture jkakavas on 27 Feb 2019
❤1
Was this page helpful?
0 / 5 - 0 ratings

Related issues

dadoonet picture dadoonet  路  3Comments
makeyang picture makeyang  路  3Comments
ppf2 picture ppf2  路  3Comments
martijnvg picture martijnvg  路  3Comments
matthughes picture matthughes  路  3Comments