[CI] StableMasterDisruptionIT testFollowerCheckerDetectsUnresponsiveNodeAfterMasterReelection failing

[martijnvg]

Similar to #84172, but opening a new issue, since that failure was triaged and closed some time ago.

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

Reproduction line:
./gradlew ':server:internalClusterTest' --tests "org.elasticsearch.discovery.StableMasterDisruptionIT.testFollowerCheckerDetectsUnresponsiveNodeAfterMasterReelection" -Dtests.seed=307D64547B8478A7 -Dtests.locale=mk -Dtests.timezone=Australia/Brisbane -Druntime.java=17

Applicable branches:
master

Reproduces locally?:
No

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

Failure excerpt:

com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=1668, name=Thread-9, state=RUNNABLE, group=TGRP-StableMasterDisruptionIT]

  at __randomizedtesting.SeedInfo.seed([307D64547B8478A7:B6009E0B0638C111]:0)

  Caused by: java.lang.AssertionError: java.lang.IllegalArgumentException: remote node [{node_s1}{q-h1mCKKR3KEscL6GIgLHQ}{q5G89eA6Q-6vK79v3fK9gg}{node_s1}{127.0.0.1}{127.0.0.1:35677}{cdfhilrstw}] is build [30406baabfbafad6603e68177b7500f551715738] of version [8.4.0] but this node is build [unknown] of version [8.4.0] which has an incompatible wire format

    at __randomizedtesting.SeedInfo.seed([307D64547B8478A7]:0)
    at org.elasticsearch.transport.InboundHandler.handleResponse(InboundHandler.java:347)
    at org.elasticsearch.transport.InboundHandler.messageReceived(InboundHandler.java:143)
    at org.elasticsearch.transport.InboundHandler.inboundMessage(InboundHandler.java:95)
    at org.elasticsearch.transport.TcpTransport.inboundMessage(TcpTransport.java:790)
    at org.elasticsearch.transport.InboundPipeline.forwardFragments(InboundPipeline.java:149)
    at org.elasticsearch.transport.InboundPipeline.doHandleBytes(InboundPipeline.java:121)
    at org.elasticsearch.transport.InboundPipeline.handleBytes(InboundPipeline.java:86)
    at org.elasticsearch.transport.netty4.Netty4MessageInboundHandler.channelRead(Netty4MessageInboundHandler.java:63)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
    at io.netty.handler.logging.LoggingHandler.channelRead(LoggingHandler.java:280)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
    at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:722)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:623)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:586)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at java.lang.Thread.run(Thread.java:833)

    Caused by: java.lang.IllegalArgumentException: remote node [{node_s1}{q-h1mCKKR3KEscL6GIgLHQ}{q5G89eA6Q-6vK79v3fK9gg}{node_s1}{127.0.0.1}{127.0.0.1:35677}{cdfhilrstw}] is build [30406baabfbafad6603e68177b7500f551715738] of version [8.4.0] but this node is build [unknown] of version [8.4.0] which has an incompatible wire format

      at org.elasticsearch.transport.TransportService$HandshakeResponse.throwOnIncompatibleBuild(TransportService.java:591)
      at org.elasticsearch.transport.TransportService$HandshakeResponse.maybeThrowOnIncompatibleBuild(TransportService.java:578)
      at org.elasticsearch.transport.TransportService$HandshakeResponse.<init>(TransportService.java:572)
      at org.elasticsearch.action.ActionListenerResponseHandler.read(ActionListenerResponseHandler.java:58)
      at org.elasticsearch.action.ActionListenerResponseHandler.read(ActionListenerResponseHandler.java:25)
      at org.elasticsearch.transport.TransportService$ContextRestoreResponseHandler.read(TransportService.java:1320)
      at org.elasticsearch.transport.TransportService$ContextRestoreResponseHandler.read(TransportService.java:1307)
      at org.elasticsearch.transport.InboundHandler.handleResponse(InboundHandler.java:339)
      at org.elasticsearch.transport.InboundHandler.messageReceived(InboundHandler.java:143)
      at org.elasticsearch.transport.InboundHandler.inboundMessage(InboundHandler.java:95)
      at org.elasticsearch.transport.TcpTransport.inboundMessage(TcpTransport.java:790)
      at org.elasticsearch.transport.InboundPipeline.forwardFragments(InboundPipeline.java:149)
      at org.elasticsearch.transport.InboundPipeline.doHandleBytes(InboundPipeline.java:121)
      at org.elasticsearch.transport.InboundPipeline.handleBytes(InboundPipeline.java:86)
      at org.elasticsearch.transport.netty4.Netty4MessageInboundHandler.channelRead(Netty4MessageInboundHandler.java:63)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
      at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
      at io.netty.handler.logging.LoggingHandler.channelRead(LoggingHandler.java:280)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
      at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
      at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
      at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
      at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
      at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
      at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
      at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:722)
      at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:623)
      at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:586)
      at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496)
      at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
      at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
      at java.lang.Thread.run(Thread.java:833)

[elasticmachine]

Pinging @elastic/es-distributed (Team:Distributed)

[original-brownbear]

Another case of a real node (from some REST test) having its port clash with the internal cluster tests. The commit hash in the error message is exactly the build commit hash that was tested here.

[DaveCTurner]

In #85777 we changed how port ranges are calculated, at least in integ tests. We should check whether that's now incompatible with how the REST tests compute their port ranges.

[DaveCTurner]

The real-cluster tests set http.port: 0 and transport.port: 0 which causes them to pick some random ephemeral port. Maybe the ephemeral port range on some CI workers is too large and overlaps the port ranges used by ESTestCase? We could either fix that or pick specific port ranges for these nodes instead. I'll open an issue for the delivery team to consider.

[mark-vieira]

Another case of a real node (from some REST test) having its port clash with the internal cluster tests. The commit hash in the error message is exactly the build commit hash that was tested here.

This doesn't seem to be the case though. If it were, I'd expect to find that port in a unicast_hosts.txt file for one of thoese test distribution but that wasn't the case. However, I did see this port listed in the test output for org.elasticsearch.reindex.DeleteByQueryBasicTests which looking at the build timeline, did in fact overlap with :server:internalClusterTest.

[0004-06-07T08:21:51,230][INFO ][o.e.n.Node               ] [[test_SUITE-TEST_WORKER_VM=[254]-CLUSTER_SEED=[-1842585342178243255]-HASH=[1324D526913]-cluster[T#4]]] starting ...
[0004-06-07T08:21:51,229][INFO ][o.e.n.Node               ] [[test_SUITE-TEST_WORKER_VM=[254]-CLUSTER_SEED=[-1842585342178243255]-HASH=[1324D526913]-cluster[T#1]]] starting ...
[0004-06-07T08:21:51,229][INFO ][o.e.n.Node               ] [[test_SUITE-TEST_WORKER_VM=[254]-CLUSTER_SEED=[-1842585342178243255]-HASH=[1324D526913]-cluster[T#3]]] starting ...
[0004-06-07T08:21:51,229][INFO ][o.e.n.Node               ] [[test_SUITE-TEST_WORKER_VM=[254]-CLUSTER_SEED=[-1842585342178243255]-HASH=[1324D526913]-cluster[T#2]]] starting ...
[0004-06-07T08:21:51,384][INFO ][o.e.t.TransportService   ] [[test_SUITE-TEST_WORKER_VM=[254]-CLUSTER_SEED=[-1842585342178243255]-HASH=[1324D526913]-cluster[T#4]]] publish_address {127.0.0.1:39425}, bound_addresses {[::1]:35815}, {127.0.0.1:39425}
[0004-06-07T08:21:51,384][INFO ][o.e.t.TransportService   ] [[test_SUITE-TEST_WORKER_VM=[254]-CLUSTER_SEED=[-1842585342178243255]-HASH=[1324D526913]-cluster[T#2]]] publish_address {127.0.0.1:35677}, bound_addresses {[::1]:39969}, {127.0.0.1:35677}
[0004-06-07T08:21:51,384][INFO ][o.e.t.TransportService   ] [[test_SUITE-TEST_WORKER_VM=[254]-CLUSTER_SEED=[-1842585342178243255]-HASH=[1324D526913]-cluster[T#1]]] publish_address {127.0.0.1:39693}, bound_addresses {[::1]:37493}, {127.0.0.1:39693}
[0004-06-07T08:21:51,384][INFO ][o.e.t.TransportService   ] [[test_SUITE-TEST_WORKER_VM=[254]-CLUSTER_SEED=[-1842585342178243255]-HASH=[1324D526913]-cluster[T#3]]] publish_address {127.0.0.1:44895}, bound_addresses {[::1]:34453}, {127.0.0.1:44895}

[DaveCTurner]

Oh interesting. Sorry for the misdiagnosis. These ports make no sense, they should all be within a specific 30 ports somewhere between 13301 and 36660, but in fact they're all over the place. Here's the culprit:

elasticsearch/test/framework/src/main/java/org/elasticsearch/test/InternalTestCluster.java

Lines 384 to 385 in b60ccc4

	builder.put(TransportSettings.PORT.getKey(), 0);
	builder.put("http.port", 0);

🤦

That means they're being allocated from the ephemeral port range on this worker. Still, the fact that some of them are ≤36660 means that there is some kind of overlap between the fixed ports chosen by ESTestCase and the ephemeral ones chosen by other tests.

[mark-vieira]

Still, the fact that some of them are ≤36660 means that there is some kind of overlap between the fixed ports chosen by ESTestCase and the ephemeral ones chosen by other tests.

I mean, if some of them are using dynamic port allocation by just choosing port 0 wouldn't that be expected? It seems to me we need to fix InternalTestCluster to use similar logic here, no?

[DaveCTurner]

Yes, we need to fix InternalTestCluster so that it picks ports from the right 30-port range between 13301 and 36600, but then we also need the tests that use transport.port: 0 to avoid this range.

[mark-vieira]

but then we also need the tests that use transport.port: 0 to avoid this range

I think the ephermal port range is something that can be configured on the host system but we'd have to confirm this.