[CI] SpecificMasterNodesIT#testSimpleOnlyMasterNodeElection failure

[martijnvg]

Build url: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-windows-compatibility/383/consoleText

ERROR   32.6s J0 | SpecificMasterNodesIT.testSimpleOnlyMasterNodeElection <<< FAILURES!
   > Throwable #1: java.lang.RuntimeException: Can't get master node NodeNotConnectedException[[node_tm1][127.0.0.1:9401] Node not connected]
   > 	at __randomizedtesting.SeedInfo.seed([B5244B21C6B2CCB8:C9FFA236E02797B6]:0)
   > 	at org.elasticsearch.test.InternalTestCluster.getMasterName(InternalTestCluster.java:1594)
   > 	at org.elasticsearch.test.InternalTestCluster.getMasterName(InternalTestCluster.java:1580)
   > 	at org.elasticsearch.test.InternalTestCluster.nonMasterClient(InternalTestCluster.java:688)
   > 	at org.elasticsearch.cluster.SpecificMasterNodesIT.testSimpleOnlyMasterNodeElection(SpecificMasterNodesIT.java:78)
   > 	at java.lang.Thread.run(Thread.java:745)
   > Caused by: MasterNotDiscoveredException[NodeNotConnectedException[[node_tm1][127.0.0.1:9401] Node not connected]]; nested: NodeNotConnectedException[[node_tm1][127.0.0.1:9401] Node not connected];
   > 	at org.elasticsearch.action.support.master.TransportMasterNodeAction$AsyncSingleAction$4.onTimeout(TransportMasterNodeAction.java:209)
   > 	at org.elasticsearch.cluster.ClusterStateObserver$ContextPreservingListener.onTimeout(ClusterStateObserver.java:317)
   > 	at org.elasticsearch.cluster.ClusterStateObserver$ObserverClusterStateListener.onTimeout(ClusterStateObserver.java:244)
   > 	at org.elasticsearch.cluster.service.ClusterApplierService$NotifyTimeout.run(ClusterApplierService.java:575)
   > 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:569)
   > 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
   > 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
   > 	... 1 more
   > Caused by: NodeNotConnectedException[[node_tm1][127.0.0.1:9401] Node not connected]
   > 	at org.elasticsearch.transport.TcpTransport.getConnection(TcpTransport.java:617)
   > 	at org.elasticsearch.transport.TcpTransport.getConnection(TcpTransport.java:118)
   > 	at org.elasticsearch.transport.TransportService.getConnection(TransportService.java:523)
   > 	at org.elasticsearch.transport.TransportService.sendRequest(TransportService.java:486)
   > 	at org.elasticsearch.action.support.master.TransportMasterNodeAction$AsyncSingleAction.doStart(TransportMasterNodeAction.java:175)
   > 	at org.elasticsearch.action.support.master.TransportMasterNodeAction$AsyncSingleAction.start(TransportMasterNodeAction.java:126)
   > 	at org.elasticsearch.action.support.master.TransportMasterNodeAction.doExecute(TransportMasterNodeAction.java:104)
   > 	at org.elasticsearch.action.support.master.TransportMasterNodeAction.doExecute(TransportMasterNodeAction.java:54)
   > 	at org.elasticsearch.action.support.TransportAction$RequestFilterChain.proceed(TransportAction.java:167)
   > 	at org.elasticsearch.action.support.TransportAction.execute(TransportAction.java:139)
   > 	at org.elasticsearch.action.support.HandledTransportAction$TransportHandler.messageReceived(HandledTransportAction.java:64)
   > 	at org.elasticsearch.action.support.HandledTransportAction$TransportHandler.messageReceived(HandledTransportAction.java:54)
   > 	at org.elasticsearch.transport.AssertingTransportInterceptor$1.messageReceived(AssertingTransportInterceptor.java:76)
   > 	at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:66)
   > 	at org.elasticsearch.transport.TcpTransport$RequestHandler.doRun(TcpTransport.java:1525)
   > 	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
   > 	at org.elasticsearch.common.util.concurrent.EsExecutors$1.execute(EsExecutors.java:139)
   > 	at org.elasticsearch.transport.TcpTransport.handleRequest(TcpTransport.java:1482)
   > 	at org.elasticsearch.transport.TcpTransport.messageReceived(TcpTransport.java:1352)
   > 	at org.elasticsearch.transport.MockTcpTransport.readMessage(MockTcpTransport.java:171)
   > 	at org.elasticsearch.transport.MockTcpTransport.access$900(MockTcpTransport.java:72)
   > 	at org.elasticsearch.transport.MockTcpTransport$MockChannel$1.lambda$doRun$0(MockTcpTransport.java:349)
   > 	at org.elasticsearch.common.util.CancellableThreads.executeIO(CancellableThreads.java:105)
   > 	at org.elasticsearch.transport.MockTcpTransport$MockChannel$1.doRun(MockTcpTransport.java:349)
   > 	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
   > 	... 3 more

Reproduce command: gradle :core:integTest -Dtests.seed=B5244B21C6B2CCB8 -Dtests.class=org.elasticsearch.cluster.SpecificMasterNodesIT -Dtests.method="testSimpleOnlyMasterNodeElection" -Dtests.security.manager=true -Dtests.locale=sl-SI -Dtests.timezone=Australia/Adelaide

It didn't reproduce for me.

[talevy]

another occurrence: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-windows-compatibility/441/console

[jpountz]

Another failure: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-windows-compatibility/517/console.

Still on Windows.

[bleskes]

I tried to pin this one down but couldn't. I push another commit enabling logging so I can see what's going on the next time it fails.

[ywelsch]

I think I know what's going on:

[2017-07-20T12:08:50,470][INFO ][o.e.c.s.ClusterApplierService] [node_tm1] added {{node_td0}{x-cBZZWBTgaw3HnIvASSoQ}{-70w0dZrQRamhbcEb-Yn8Q}{127.0.0.1}{127.0.0.1:9400},}, reason: apply cluster state (from master [master {node_tm1}{w9RMBfuvTHOltc_pciHQ9g}{VwzY_zHhSjytF5ZwhXDv5g}{127.0.0.1}{127.0.0.1:9401} committed version [3] source [zen-disco-node-join[{node_td0}{x-cBZZWBTgaw3HnIvASSoQ}{-70w0dZrQRamhbcEb-Yn8Q}{127.0.0.1}{127.0.0.1:9400}]]])

See, that's cluster state version 3. Now we shutdown the master node, and start up another master node. If you look at those master nodes, you see that they have the same persistent id:

{node_tm1}{w9RMBfuvTHOltc_pciHQ9g}{VwzY_zHhSjytF5ZwhXDv5g}{127.0.0.1}{127.0.0.1:9401}
{node_tm2}{w9RMBfuvTHOltc_pciHQ9g}{G48cQz0BQb-6eajl0Nccuw}{127.0.0.1}{127.0.0.1:9401}

However, node_tm2 starts again with cluster state version 0, it's using a clean state. After the data node has rejoined node_tm2 we have:

[2017-07-20T12:08:51,090][INFO ][o.e.c.s.ClusterApplierService] [node_tm2] added {{node_td0}{x-cBZZWBTgaw3HnIvASSoQ}{-70w0dZrQRamhbcEb-Yn8Q}{127.0.0.1}{127.0.0.1:9400},}, reason: apply cluster state (from master [master {node_tm2}{w9RMBfuvTHOltc_pciHQ9g}{G48cQz0BQb-6eajl0Nccuw}{127.0.0.1}{127.0.0.1:9401} committed version [3] source [zen-disco-node-join[{node_td0}{x-cBZZWBTgaw3HnIvASSoQ}{-70w0dZrQRamhbcEb-Yn8Q}{127.0.0.1}{127.0.0.1:9400}]]])

again cluster state version 3.

Let's look at MasterNodeChangePredicate, which is used by TransportMasterNodeAction for the ClusterObserver:

public static Predicate<ClusterState> build(ClusterState currentState) {
        final long currentVersion = currentState.version();
        final String currentMaster = currentState.nodes().getMasterNodeId();
        return newState -> {
            final String newMaster = newState.nodes().getMasterNodeId();
            final boolean accept;
            if (newMaster == null) {
                accept = false;
            } else if (newMaster.equals(currentMaster) == false){
                accept = true;
            } else {
                accept = newState.version() > currentVersion;
            }
            return accept;
        };
    }

If, due to batching on the applier, the data node did not apply the cluster state where the old master has been removed, but directly applies the one with the new master, the predicate will return false, as we will have same persistent master node id and same CS version.

[bleskes]

Great catch @ywelsch . I thought about this scenario but erroneously discarded it, thinking that since the node uses the same data folder, it will recover the cluster state with the version (sadly.. this is where it goes wrong) and thus the version will be incremented. Note though that batching is one possible cause. Another is concurrency in calling the observer - it may skip a cluster state update while transport master action deals with things.

I will work on a fix tomorrow.