SnapshotLifecycleRestIT testFullPolicySnapshot failure #50358

davidkyle · 2019-12-19T10:28:39Z

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-windows-compatibility/os=windows-2016/331/console
https://gradle-enterprise.elastic.co/s/fmz3orwsf6ceu

org.elasticsearch.client.ResponseException: 
method [DELETE], host [http://127.0.0.1:60674], URI [/_snapshot/my-repo/snap-dgpzyeujtlil-pxstwwurg], status line [HTTP/1.1 503 Service Unavailable]
{"error":{"root_cause":[{"type":"concurrent_snapshot_execution_exception","reason":"[my-repo:snap-dgpzyeujtlil-pxstwwurg/5U_JWp2pRceMG2VKwqteqQ] another snapshot is currently running cannot delete"}],"type":"concurrent_snapshot_execution_exception","reason":"[my-repo:snap-dgpzyeujtlil-pxstwwurg/5U_JWp2pRceMG2VKwqteqQ] another snapshot is currently running cannot delete"},"status":503}

at __randomizedtesting.SeedInfo.seed([A77F6987797E068:3AE5B97574CB83D]:0)
at org.elasticsearch.client.RestClient.convertResponse(RestClient.java:283)
at org.elasticsearch.client.RestClient.performRequest(RestClient.java:261)
at org.elasticsearch.client.RestClient.performRequest(RestClient.java:267)
at org.elasticsearch.client.RestClient.performRequest(RestClient.java:267)
at org.elasticsearch.client.RestClient.performRequest(RestClient.java:267)
at org.elasticsearch.client.RestClient.performRequest(RestClient.java:267)
at org.elasticsearch.client.RestClient.performRequest(RestClient.java:267)
at org.elasticsearch.client.RestClient.performRequest(RestClient.java:267)
at org.elasticsearch.client.RestClient.performRequest(RestClient.java:267)
at org.elasticsearch.client.RestClient.performRequest(RestClient.java:235)
at org.elasticsearch.test.rest.ESRestTestCase.wipeSnapshots(ESRestTestCase.java:613)
at org.elasticsearch.test.rest.ESRestTestCase.lambda$wipeCluster$3(ESRestTestCase.java:504)
at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:854)
at org.elasticsearch.test.rest.ESRestTestCase.wipeCluster(ESRestTestCase.java:503)
at org.elasticsearch.test.rest.ESRestTestCase.cleanUpCluster(ESRestTestCase.java:287)
...

Does not reproduce:

gradlew ':x-pack:plugin:ilm:qa:multi-node:integTestRunner' --tests "org.elasticsearch.xpack.slm.SnapshotLifecycleRestIT.testFullPolicySnapshot" \
  -Dtests.seed=A77F6987797E068 \
  -Dtests.security.manager=true \
  -Dtests.locale=ca \
  -Dtests.timezone=Europe/Ulyanovsk \
  -Dcompiler.java=13

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

elasticmachine · 2019-12-19T10:28:41Z

Pinging @elastic/es-core-features (:Core/Features/ILM+SLM)

davidkyle · 2019-12-19T10:53:37Z

A handful of similar failures:

https://gradle-enterprise.elastic.co/s/scv4m7g4w7kcs
https://gradle-enterprise.elastic.co/s/ttguod4m35fqs

Muted on master in ae90f8a

Relates to #50358

danielmitterdorfer · 2020-01-14T12:46:13Z

We have another failure in 7.x (CI link, build scan):

The symptoms look a bit different to me though:

java.lang.AssertionError: 
Expected: a string starting with "snap-"
     but: was "snapuyytvuakl-31toqfartrwfolzgmlvdra"
	at __randomizedtesting.SeedInfo.seed([D4BE8BA449B8A835:DD6726AB6963F060]:0)
	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:18)
	at org.junit.Assert.assertThat(Assert.java:956)
	at org.junit.Assert.assertThat(Assert.java:923)
	at org.elasticsearch.xpack.slm.SnapshotLifecycleRestIT.lambda$testFullPolicySnapshot$1(SnapshotLifecycleRestIT.java:110)

reproduction line:

./gradlew ':x-pack:plugin:ilm:qa:multi-node:integTestRunner' --tests "org.elasticsearch.xpack.slm.SnapshotLifecycleRestIT.testFullPolicySnapshot" -Dtests.seed=D4BE8BA449B8A835 -Dtests.security.manager=true -Dtests.locale=ko-KR -Dtests.timezone=Canada/Central -Dcompiler.java=13 -Druntime.java=8

Does not reproduce locally.

Relates to #50358

This test failed a couple of different ways, related to timing, as well as concurrent snapshots, and also naming. This commit splits the giant `assertBusy` into separate parts so that we don't perform ~5 different requests and tests in the same loop. It also gives each test a unique repository so that no other test can accidentally re-use snapshots. Resolves elastic#50358 (hopefully!)

…51013) This test failed a couple of different ways, related to timing, as well as concurrent snapshots, and also naming. This commit splits the giant `assertBusy` into separate parts so that we don't perform ~5 different requests and tests in the same loop. It also gives each test a unique repository so that no other test can accidentally re-use snapshots. Resolves #50358 (hopefully!)

…lastic#51013) This test failed a couple of different ways, related to timing, as well as concurrent snapshots, and also naming. This commit splits the giant `assertBusy` into separate parts so that we don't perform ~5 different requests and tests in the same loop. It also gives each test a unique repository so that no other test can accidentally re-use snapshots. Resolves elastic#50358 (hopefully!)

This test failed a couple of different ways, related to timing, as well as concurrent snapshots, and also naming. This commit splits the giant `assertBusy` into separate parts so that we don't perform ~5 different requests and tests in the same loop. It also gives each test a unique repository so that no other test can accidentally re-use snapshots. Resolves #50358 (hopefully!)

hendrikmuhs · 2020-01-17T12:35:20Z

Sorry, I have to re-open:

14:07:10 org.elasticsearch.xpack.slm.SnapshotLifecycleRestIT > testFullPolicySnapshot FAILED
14:07:10     java.lang.AssertionError: 
14:07:10     Expected: a string starting with "snap-"
14:07:10          but: was "snapyuqttxlpu-zwgyb5vytjics8kuqznzpq"
14:07:10         at __randomizedtesting.SeedInfo.seed([C2B5BA3D5616DEE8:CB6C173276CD86BD]:0)
14:07:10         at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:18)
14:07:10         at org.junit.Assert.assertThat(Assert.java:956)
14:07:10         at org.junit.Assert.assertThat(Assert.java:923)
14:07:10         at org.elasticsearch.xpack.slm.SnapshotLifecycleRestIT.lambda$testFullPolicySnapshot$1(SnapshotLifecycleRestIT.java:110)
14:07:10         at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:904)
14:07:10         at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:877)
14:07:10         at org.elasticsearch.xpack.slm.SnapshotLifecycleRestIT.testFullPolicySnapshot(SnapshotLifecycleRestIT.java:101)
14:07:26 REPRODUCE WITH: ./gradlew ':x-pack:plugin:ilm:qa:multi-node:integTestRunner' --tests "org.elasticsearch.xpack.slm.SnapshotLifecycleRestIT.testFullPolicySnapshot" -Dtests.seed=C2B5BA3D5616DEE8 -Dtests.security.manager=true -Dtests.locale=es-DO -Dtests.timezone=SystemV/MST7MDT -Dcompiler.java=13 -Druntime.java=8
14:07:26 
14:07:26 Suite: Test class org.elasticsearch.xpack.slm.SnapshotLifecycleRestIT
14:07:26   1> [2020-01-17T05:06:57,560][INFO ][o.e.x.s.SnapshotLifecycleRestIT] [testFullPolicySnapshot] before test
14:07:26   1> [2020-01-17T05:06:57,563][INFO ][o.e.x.s.SnapshotLifecycleRestIT] [testFullPolicySnapshot] initializing REST clients against [http://[::1]:39063, http://127.0.0.1:33047, http://[::1]:35411, http://127.0.0.1:37777, http://[::1]:42741, http://127.0.0.1:46725, http://[::1]:35935, http://127.0.0.1:44347]
14:07:26   1> [2020-01-17T05:07:09,867][INFO ][o.e.x.s.SnapshotLifecycleRestIT] [testFullPolicySnapshot] after test
14:07:26   2> REPRODUCE WITH: ./gradlew ':x-pack:plugin:ilm:qa:multi-node:integTestRunner' --tests "org.elasticsearch.xpack.slm.SnapshotLifecycleRestIT.testFullPolicySnapshot" -Dtests.seed=C2B5BA3D5616DEE8 -Dtests.security.manager=true -Dtests.locale=es-DO -Dtests.timezone=SystemV/MST7MDT -Dcompiler.java=13 -Druntime.java=8
14:07:26   2> java.lang.AssertionError: 
14:07:26     Expected: a string starting with "snap-"
14:07:26          but: was "snapyuqttxlpu-zwgyb5vytjics8kuqznzpq"
14:07:26         at __randomizedtesting.SeedInfo.seed([C2B5BA3D5616DEE8:CB6C173276CD86BD]:0)
14:07:26         at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:18)
14:07:26         at org.junit.Assert.assertThat(Assert.java:956)
14:07:26         at org.junit.Assert.assertThat(Assert.java:923)
14:07:26         at org.elasticsearch.xpack.slm.SnapshotLifecycleRestIT.lambda$testFullPolicySnapshot$1(SnapshotLifecycleRestIT.java:110)
14:07:26         at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:904)
14:07:26         at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:877)
14:07:26         at org.elasticsearch.xpack.slm.SnapshotLifecycleRestIT.testFullPolicySnapshot(SnapshotLifecycleRestIT.java:101)

from

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+7.x+multijob-unix-compatibility/os=amazon/513/consoleFull

Relates to elastic#50358

…tic#51055) This test failed a couple of different ways, related to timing, as well as concurrent snapshots, and also naming. This commit splits the giant `assertBusy` into separate parts so that we don't perform ~5 different requests and tests in the same loop. It also gives each test a unique repository so that no other test can accidentally re-use snapshots. Resolves elastic#50358 (hopefully!)

Rather than check the first returned snapshot for a snapshot starting with `snap-` in SnapshotLifecycleRestIT.testFullPolicy, this commit changes the test to find any snapshots starting with `snap-`. In the event that there are no snapshots (the failure case), this also exposes the full results map so we can diagnose why a failure occurred. Relates to elastic#50358

* Check all snapshots in SnapshotLifecycleRestIT.testFullPolicy Rather than check the first returned snapshot for a snapshot starting with `snap-` in SnapshotLifecycleRestIT.testFullPolicy, this commit changes the test to find any snapshots starting with `snap-`. In the event that there are no snapshots (the failure case), this also exposes the full results map so we can diagnose why a failure occurred. Relates to #50358 * Use a more imperative style for checking

…c#51386) * Check all snapshots in SnapshotLifecycleRestIT.testFullPolicy Rather than check the first returned snapshot for a snapshot starting with `snap-` in SnapshotLifecycleRestIT.testFullPolicy, this commit changes the test to find any snapshots starting with `snap-`. In the event that there are no snapshots (the failure case), this also exposes the full results map so we can diagnose why a failure occurred. Relates to elastic#50358 * Use a more imperative style for checking

* Check all snapshots in SnapshotLifecycleRestIT.testFullPolicy Rather than check the first returned snapshot for a snapshot starting with `snap-` in SnapshotLifecycleRestIT.testFullPolicy, this commit changes the test to find any snapshots starting with `snap-`. In the event that there are no snapshots (the failure case), this also exposes the full results map so we can diagnose why a failure occurred. Relates to #50358 * Use a more imperative style for checking

droberts195 · 2020-01-28T12:40:01Z

It's now failing in a different way, but immediately after the code that was changed in #51386 to try and fix this:

Expected: <[test]>
     but: was <[index-ypfbpkpzll]>

That is coming from line 123 of SnapshotLifecycleRestIT.java, which is immediately after the code change of #51386:

        at __randomizedtesting.SeedInfo.seed([D1426930D73DDCAE:D89BC43FF7E684FB]:0)
        at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:18)
        at org.junit.Assert.assertThat(Assert.java:956)
        at org.junit.Assert.assertThat(Assert.java:923)
        at org.elasticsearch.xpack.slm.SnapshotLifecycleRestIT.lambda$testFullPolicySnapshot$2(SnapshotLifecycleRestIT.java:123)
        at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:905)
        at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:878)
        at org.elasticsearch.xpack.slm.SnapshotLifecycleRestIT.testFullPolicySnapshot(SnapshotLifecycleRestIT.java:108)

This has happened a few times on the 7.x branch. A couple of examples are:

A repro command is:

./gradlew ':x-pack:plugin:ilm:qa:multi-node:integTestRunner' --tests "org.elasticsearch.xpack.slm.SnapshotLifecycleRestIT.testFullPolicySnapshot" \
  -Dtests.seed=D1426930D73DDCAE \
  -Dtests.security.manager=true \
  -Dtests.locale=vi-VN \
  -Dtests.timezone=Africa/Maputo \
  -Dcompiler.java=13

This didn't reproduce locally for me.

This previously was missing some key information in the output of the failure. This captures that information and adds logging at each step so we can determine the cause *if* it fails again. Resolves elastic#50358

* Fix SnapshotLifecycleRestIT.testFullPolicySnapshot This previously was missing some key information in the output of the failure. This captures that information and adds logging at each step so we can determine the cause *if* it fails again. Resolves #50358

* Fix SnapshotLifecycleRestIT.testFullPolicySnapshot This previously was missing some key information in the output of the failure. This captures that information and adds logging at each step so we can determine the cause *if* it fails again. Resolves elastic#50358

* Fix SnapshotLifecycleRestIT.testFullPolicySnapshot This previously was missing some key information in the output of the failure. This captures that information and adds logging at each step so we can determine the cause *if* it fails again. Resolves #50358

davidkyle · 2020-03-16T10:00:12Z

It came back 😱

org.elasticsearch.client.ResponseException: method [DELETE], host [http://127.0.0.1:38055], URI [/_snapshot/full-policy-repo/snap-fy0vwyhpsrmv9f1bgahmtg], status line [HTTP/1.1 503 Service Unavailable]
{"error":{"root_cause":[{"type":"concurrent_snapshot_execution_exception","reason":"[full-policy-repo:snap-fy0vwyhpsrmv9f1bgahmtg/N6ULZf9_Spiwz8IGF0jHdw] another snapshot is currently running cannot delete"}],"type":"concurrent_snapshot_execution_exception","reason":"[full-policy-repo:snap-fy0vwyhpsrmv9f1bgahmtg/N6ULZf9_Spiwz8IGF0jHdw] another snapshot is currently running cannot delete"},"status":503}
	at __randomizedtesting.SeedInfo.seed([8453CDD48058A5E9:8D8A60DBA083FDBC]:0)
	at org.elasticsearch.client.RestClient.convertResponse(RestClient.java:283)
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:261)
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:267)
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:267)
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:267)
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:267)
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:267)
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:267)
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:267)
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:235)
	at org.elasticsearch.test.rest.ESRestTestCase.wipeSnapshots(ESRestTestCase.java:622)
	at org.elasticsearch.test.rest.ESRestTestCase.lambda$wipeCluster$3(ESRestTestCase.java:510)
	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:875)
	at org.elasticsearch.test.rest.ESRestTestCase.wipeCluster(ESRestTestCase.java:509)
	at org.elasticsearch.test.rest.ESRestTestCase.cleanUpCluster(ESRestTestCase.java:293)

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-unix-compatibility/os=sles-15&&immutable/636/console

https://gradle-enterprise.elastic.co/s/l3ntz5zhjvxry/tests/ao2nxxbijves6-3ndcchqutszas

 ./gradlew ':x-pack:plugin:ilm:qa:multi-node:integTestRunner' --tests "org.elasticsearch.xpack.slm.SnapshotLifecycleRestIT.testFullPolicySnapshot" \
  -Dtests.seed=8453CDD48058A5E9 \
  -Dtests.security.manager=true \
  -Dtests.locale=ar-SA \
  -Dtests.timezone=SystemV/HST10 \
  -Dcompiler.java=13

elastic#50358

#50358

davidkyle · 2020-03-16T10:18:40Z

Muted on master in 340fcd1

cbuescher · 2020-04-16T09:49:12Z

This failure on 7.7 looks similar.

org.elasticsearch.client.ResponseException: method [DELETE], host [http://[::1]:41150], URI [/_snapshot/full-policy-repo/snap-0zx3ektksugws-extubuza], status line [HTTP/1.1 503 Service Unavailable]
{"error":{"root_cause":[{"type":"concurrent_snapshot_execution_exception","reason":"[full-policy-repo:snap-0zx3ektksugws-extubuza/6v6TuJAsTNuvGuzs24UwcQ] another snapshot is currently running cannot delete"}],"type":"concurrent_snapshot_execution_exception","reason":"[full-policy-repo:snap-0zx3ektksugws-extubuza/6v6TuJAsTNuvGuzs24UwcQ] another snapshot is currently running cannot delete"},"status":503}
	at __randomizedtesting.SeedInfo.seed([A5EB03C9FA047982:AC32AEC6DADF21D7]:0)
	at org.elasticsearch.client.RestClient.convertResponse(RestClient.java:283)
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:261)
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:267)
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:267)
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:267)
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:267)
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:267)
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:267)
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:267)
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:235)
	at org.elasticsearch.test.rest.ESRestTestCase.wipeSnapshots(ESRestTestCase.java:644)
	at org.elasticsearch.test.rest.ESRestTestCase.lambda$wipeCluster$4(ESRestTestCase.java:541)
	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:905)
	at org.elasticsearch.test.rest.ESRestTestCase.wipeCluster(ESRestTestCase.java:540)
	at org.elasticsearch.test.rest.ESRestTestCase.cleanUpCluster(ESRestTestCase.java:321)

https://gradle-enterprise.elastic.co/s/dfi2xbqejo4fu

Looks like it still fails on 7.x and 7.7 around 3-4 times a month. @dakrone should we mute those branches as well or are you looking for more infos?

dakrone · 2020-07-16T21:48:51Z

I believe this should be resolved now that #56911 has been merged, so I'm going to close it, we can re-open if it occurs again.

davidkyle added >test-failure Triaged test failures from CI :Data Management/ILM+SLM Index and Snapshot lifecycle management v8.0.0 labels Dec 19, 2019

davidkyle added a commit that referenced this issue Dec 19, 2019

Mute SnapshotLifecycleRestIT testFullPolicySnapshot

ae90f8a

Relates to #50358

danielmitterdorfer added the v7.6.0 label Jan 14, 2020

danielmitterdorfer pushed a commit that referenced this issue Jan 14, 2020

Mute SnapshotLifecycleRestIT testFullPolicySnapshot

69a3626

Relates to #50358

dakrone mentioned this issue Jan 14, 2020

Address failures in SnapshotLifecycleRestIT.testFullPolicySnapshot #51013

Merged

$@polyfractal$ polyfractal added v7.7.0 and removed v7.6.0 labels Jan 15, 2020

dakrone mentioned this issue Jan 15, 2020

Address failures in SnapshotLifecycleRestIT.testFullPolicySnap… #51055

Merged

dakrone closed this as completed in #51055 Jan 15, 2020

hendrikmuhs reopened this Jan 17, 2020

SivagurunathanV pushed a commit to SivagurunathanV/elasticsearch that referenced this issue Jan 23, 2020

Mute SnapshotLifecycleRestIT testFullPolicySnapshot

0ef7bbe

Relates to elastic#50358

dakrone mentioned this issue Jan 23, 2020

Check all snapshots in SnapshotLifecycleRestIT.testFullPolicy #51386

Merged

andreidan assigned dakrone Jan 27, 2020

dakrone mentioned this issue Jan 31, 2020

Fix SnapshotLifecycleRestIT.testFullPolicySnapshot #51769

Merged

dakrone closed this as completed in #51769 Jan 31, 2020

dakrone mentioned this issue Jan 31, 2020

[7.x] Fix SnapshotLifecycleRestIT.testFullPolicySnapshot (#517… #51778

Merged

davidkyle reopened this Mar 16, 2020

davidkyle added a commit to davidkyle/elasticsearch that referenced this issue Mar 16, 2020

Mute SnapshotLifecycleRestIT.testFullPolicySnapshot

4d48000

elastic#50358

davidkyle mentioned this issue Mar 16, 2020

Mute SnapshotLifecycleRestIT.testFullPolicySnapshot #53588

Merged

davidkyle added a commit that referenced this issue Mar 16, 2020

Mute SnapshotLifecycleRestIT.testFullPolicySnapshot (#53588)

340fcd1

#50358

bpintea added v7.8.0 and removed v7.7.0 labels Mar 25, 2020

rjernst added the Team:Data Management Meta label for data/management team label May 4, 2020

pugnascotia added v7.8.1 v7.9.0 and removed v7.8.0 v7.8.1 labels May 6, 2020

pugnascotia added v7.10.0 and removed v7.9.0 labels Jul 15, 2020

dakrone closed this as completed Jul 16, 2020

joegallo mentioned this issue Nov 6, 2020

Unmute testFullPolicySnapshot #64738

Merged

jakelandis added v8.0.0-alpha1 and removed v8.0.0 labels Jul 26, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

SnapshotLifecycleRestIT testFullPolicySnapshot failure #50358

SnapshotLifecycleRestIT testFullPolicySnapshot failure #50358

davidkyle commented Dec 19, 2019

elasticmachine commented Dec 19, 2019

davidkyle commented Dec 19, 2019

danielmitterdorfer commented Jan 14, 2020

hendrikmuhs commented Jan 17, 2020

droberts195 commented Jan 28, 2020

davidkyle commented Mar 16, 2020

davidkyle commented Mar 16, 2020

cbuescher commented Apr 16, 2020

dakrone commented Jul 16, 2020

SnapshotLifecycleRestIT testFullPolicySnapshot failure #50358

SnapshotLifecycleRestIT testFullPolicySnapshot failure #50358

Comments

davidkyle commented Dec 19, 2019

elasticmachine commented Dec 19, 2019

davidkyle commented Dec 19, 2019

danielmitterdorfer commented Jan 14, 2020

hendrikmuhs commented Jan 17, 2020

droberts195 commented Jan 28, 2020

davidkyle commented Mar 16, 2020

davidkyle commented Mar 16, 2020

cbuescher commented Apr 16, 2020

dakrone commented Jul 16, 2020