elastic / elasticsearch

Free and Open Source, Distributed, RESTful Search Engine
https://www.elastic.co/products/elasticsearch
Other
1.09k stars 24.83k forks source link

[CI] StableMasterDisruptionIT testRepeatedNullMasterRecognizedAsGreenIfMasterDoesNotKnowItIsUnstable failing #89431

Closed masseyke closed 2 years ago

masseyke commented 2 years ago

Build scan: https://gradle-enterprise.elastic.co/s/sjbgu4zjbxhmo/tests/:server:internalClusterTest/org.elasticsearch.discovery.StableMasterDisruptionIT/testRepeatedNullMasterRecognizedAsGreenIfMasterDoesNotKnowItIsUnstable

Reproduction line: ./gradlew ':server:internalClusterTest' --tests "org.elasticsearch.discovery.StableMasterDisruptionIT.testRepeatedNullMasterRecognizedAsGreenIfMasterDoesNotKnowItIsUnstable" -Dtests.seed=5F13EFF29906BB53 -Dtests.locale=en-IE -Dtests.timezone=Australia/South -Druntime.java=17

Applicable branches: main

Reproduces locally?: No

Failure history: https://gradle-enterprise.elastic.co/scans/tests?tests.container=org.elasticsearch.discovery.StableMasterDisruptionIT&tests.test=testRepeatedNullMasterRecognizedAsGreenIfMasterDoesNotKnowItIsUnstable

Failure excerpt:

java.lang.AssertionError: {"status":"yellow","cluster_name":"TEST-TEST_WORKER_VM=[226]-CLUSTER_SEED=[7924964341647394941]-HASH=[F908511566]-cluster","indicators":{"master_is_stable":{"status":"yellow","symptom":"The cluster's master has alternated between [{node_t0}{cX_Eos3KTJi7ejP3Ciy7Gw}{ZPwl9rtsTlmdxJanBAD2ew}{node_t0}{127.0.0.1}{127.0.0.1:20111}{m}] and no master multiple times in the last 30m","details":{"current_master":{"node_id":"cX_Eos3KTJi7ejP3Ciy7Gw","name":"node_t0"},"recent_masters":[{"node_id":"cX_Eos3KTJi7ejP3Ciy7Gw","name":"node_t0"},{"node_id":"cX_Eos3KTJi7ejP3Ciy7Gw","name":"node_t0"},{"node_id":"cX_Eos3KTJi7ejP3Ciy7Gw","name":"node_t0"}],"exception_fetching_history":{"message":"[node_t0][127.0.0.1:20111][internal:cluster/master_history/get] request_id [25] timed out after [10044ms]","stack_trace":"org.elasticsearch.transport.ReceiveTimeoutTransportException: [node_t0][127.0.0.1:20111][internal:cluster/master_history/get] request_id [25] timed out after [10044ms]\n"}},"impacts":[{"severity":1,"description":"The cluster cannot create, delete, or rebalance indices, and cannot insert or update documents.","impact_areas":["ingest"]},{"severity":1,"description":"Scheduled tasks such as Watcher, ILM, and SLM will not work. The _cat APIs will not work.","impact_areas":["deployment_management"]},{"severity":3,"description":"Snapshot and restore will not work. Searchable snapshots cannot be mounted.","impact_areas":["backup"]}],"diagnosis":[{"cause":"The Elasticsearch cluster does not have a stable master node.","action":"Get help at https://ela.st/getting-help","help_url":"https://ela.st/getting-help"}]},"repository_integrity":{"status":"unknown","symptom":"Could not determine health status. Check details on critical issues preventing the health status from reporting.","details":{"reasons":{"master_is_stable":"yellow"}}},"shards_availability":{"status":"unknown","symptom":"Could not determine health status. Check details on critical issues preventing the health status from reporting.","details":{"reasons":{"master_is_stable":"yellow"}}}}}
Expected: <GREEN>
     but: was <YELLOW>

  at __randomizedtesting.SeedInfo.seed([5F13EFF29906BB53:B4381153A289DA9A]:0)
  at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:18)
  at org.junit.Assert.assertThat(Assert.java:956)
  at org.elasticsearch.discovery.StableMasterDisruptionIT.lambda$assertMasterStability$0(StableMasterDisruptionIT.java:140)
  at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:1104)
  at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:1077)
  at org.elasticsearch.discovery.StableMasterDisruptionIT.assertMasterStability(StableMasterDisruptionIT.java:137)
  at org.elasticsearch.discovery.StableMasterDisruptionIT.assertGreenMasterStability(StableMasterDisruptionIT.java:133)
  at org.elasticsearch.discovery.StableMasterDisruptionIT.testRepeatedNullMasterRecognizedAsGreenIfMasterDoesNotKnowItIsUnstable(StableMasterDisruptionIT.java:474)
  at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-2)
  at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
  at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  at java.lang.reflect.Method.invoke(Method.java:568)
  at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1758)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:946)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:982)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:996)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at org.apache.lucene.tests.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:44)
  at org.apache.lucene.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
  at org.apache.lucene.tests.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:45)
  at org.apache.lucene.tests.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:60)
  at org.apache.lucene.tests.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:44)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:390)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:843)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:490)
  at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:955)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:840)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:891)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:902)
  at org.apache.lucene.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at org.apache.lucene.tests.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:38)
  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 org.apache.lucene.tests.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
  at org.apache.lucene.tests.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
  at org.apache.lucene.tests.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:44)
  at org.apache.lucene.tests.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:60)
  at org.apache.lucene.tests.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:47)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:390)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl.lambda$forkTimeoutingTask$0(ThreadLeakControl.java:850)
  at java.lang.Thread.run(Thread.java:833)
elasticsearchmachine commented 2 years ago

Pinging @elastic/es-data-management (Team:Data Management)

masseyke commented 2 years ago

I haven't been able to reproduce this one yet, but here's my guess as to what's happening: We intentionally force the master to simulate a long GC pause repeatedly in this test so that the other nodes think it has gone null (no master). Then we stop pausing the master, and we assert that the data nodes think the master has gone null too often, but the master thinks it has been fine. In this case it's returning this response:

{
    "status": "yellow",
    "cluster_name": "TEST-TEST_WORKER_VM=[226]-CLUSTER_SEED=[7924964341647394941]-HASH=[F908511566]-cluster",
    "indicators": {
        "master_is_stable": {
            "status": "yellow",
            "symptom": "The cluster's master has alternated between [{node_t0}{cX_Eos3KTJi7ejP3Ciy7Gw}{ZPwl9rtsTlmdxJanBAD2ew}{node_t0}{127.0.0.1}{127.0.0.1:20111}{m}] and no master multiple times in the last 30m",
            "details": {
                "current_master": {
                    "node_id": "cX_Eos3KTJi7ejP3Ciy7Gw",
                    "name": "node_t0"
                },
                "recent_masters": [
                    {
                        "node_id": "cX_Eos3KTJi7ejP3Ciy7Gw",
                        "name": "node_t0"
                    },
                    {
                        "node_id": "cX_Eos3KTJi7ejP3Ciy7Gw",
                        "name": "node_t0"
                    },
                    {
                        "node_id": "cX_Eos3KTJi7ejP3Ciy7Gw",
                        "name": "node_t0"
                    }
                ],
                "exception_fetching_history": {
                    "message": "[node_t0][127.0.0.1:20111][internal:cluster/master_history/get] request_id [25] timed out after [10044ms]",
                    "stack_trace": "org.elasticsearch.transport.ReceiveTimeoutTransportException: [node_t0][127.0.0.1:20111][internal:cluster/master_history/get] request_id [25] timed out after [10044ms]\n"
                }
            },
            "impacts": [
                {
                    "severity": 1,
                    "description": "The cluster cannot create, delete, or rebalance indices, and cannot insert or update documents.",
                    "impact_areas": [
                        "ingest"
                    ]
                },
                {
                    "severity": 1,
                    "description": "Scheduled tasks such as Watcher, ILM, and SLM will not work. The _cat APIs will not work.",
                    "impact_areas": [
                        "deployment_management"
                    ]
                },
                {
                    "severity": 3,
                    "description": "Snapshot and restore will not work. Searchable snapshots cannot be mounted.",
                    "impact_areas": [
                        "backup"
                    ]
                }
            ],
            "diagnosis": [
                {
                    "cause": "The Elasticsearch cluster does not have a stable master node.",
                    "action": "Get help at https://ela.st/getting-help",
                    "help_url": "https://ela.st/getting-help"
                }
            ]
        },
        "repository_integrity": {
            "status": "unknown",
            "symptom": "Could not determine health status. Check details on critical issues preventing the health status from reporting.",
            "details": {
                "reasons": {
                    "master_is_stable": "yellow"
                }
            }
        },
        "shards_availability": {
            "status": "unknown",
            "symptom": "Could not determine health status. Check details on critical issues preventing the health status from reporting.",
            "details": {
                "reasons": {
                    "master_is_stable": "yellow"
                }
            }
        }
    }
}

There was a timeout while reaching out to the master to see if it thinks there is a problem. I'm guessing that this timeout came during a time when the master was paused (and that the random pause had lasted 10+ seconds). I noticed that in CoordinationDiagnosticsService#clusterChanged we only send the request for master history when the master node turns null, but not when it turns non-null after being null. So when the master node came back alive we didn't make a follow-up request. If that's right, there are two possible ways we could fix this: (1) Change clusterChanged() to also fetch the remote history when a master changes from null to not-null (maybe only if it's been non-null in our local history so that we don't make this request when the cluster first comes up). (2) Change the test to not have GC pauses longer than the request timeout for master history, and live with the fact that sometimes we'll get false positives in practice. Of those, # 1 probably sounds more appealing.

masseyke commented 2 years ago

It looks like there are actually 3 bugs here: (1) We don't query for the remote master history if the master is non-null (described above) (2) The countDown latch was waiting for 2 of the 3 nodes to ack the missing master. That's not really a bug, but the master node is never going to see itself as null so it's pointless to even have code for that (3) The call to ensureStableMaster() was not specifying a node. In this case it was picking the master node to do the check from, and the master node always thinks it's fine. So it returned before the two data nodes had joined the master node. Then the next disruption would begin before the data nodes had joined the master, so they'd never receive a clusterChanged event that the master had gone null, so the countDown latch would have to wait for 30 seconds (a big waste of time).

dimitris-athanasiou commented 2 years ago

Another failure in https://gradle-enterprise.elastic.co/s/4qezcu7ubfxgw/tests/:server:internalClusterTest/org.elasticsearch.discovery.StableMasterDisruptionIT/testRepeatedNullMasterRecognizedAsGreenIfMasterDoesNotKnowItIsUnstable?top-execution=1

ywangd commented 2 years ago

This still fails on 8.4 https://gradle-enterprise.elastic.co/s/y645yuwowvuas

@masseyke Maybe we need backport the fix?

masseyke commented 2 years ago

Sorry just saw this, and just backported it -- https://github.com/elastic/elasticsearch/pull/90040