[CI] HotThreadsIT.testHotThreadsDontFail failure on master

[matriv]

Logs: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-unix-compatibility/os=centos/211/console

REPRODUCE WITH:

/gradlew :server:integTest \
  -Dtests.seed=233C30BFCE2B7117 \
  -Dtests.class=org.elasticsearch.action.admin.HotThreadsIT \
  -Dtests.method="testHotThreadsDontFail" \
  -Dtests.security.manager=true \
  -Dtests.locale=es-MX \
  -Dtests.timezone=Asia/Yerevan \
  -Dcompiler.java=11 \
  -Druntime.java=8

Couldn't reproduce locally (100+ iterations)

  1> [2019-01-29T15:44:34,933][INFO ][o.e.c.c.Coordinator      ] [node_s1] setting initial configuration to VotingConfiguration{FOMFnLR6RaC0dEzMnFkJ1A,saAXE5n_SbeS_kPuGtZ9eQ,{bootstrap-placeholder}-node_s2}
  1> [2019-01-29T15:44:35,350][INFO ][o.e.c.s.MasterService    ] [node_s1] elected-as-master ([2] nodes joined)[{node_s0}{FOMFnLR6RaC0dEzMnFkJ1A}{6t1ue7wmTM626qcAoGXuVw}{127.0.0.1}{127.0.0.1:35907} elect leader, {node_s1}{saAXE5n_SbeS_kPuGtZ9eQ}{IlVsI13pT3m97zB9kigMBw}{127.0.0.1}{127.0.0.1:43437} elect leader, _BECOME_MASTER_TASK_, _FINISH_ELECTION_], node-join[{node_s2}{2TYkOhZXTt-QaPNJgYFNsw}{DbhzCUXTR7SBzAU85okUDQ}{127.0.0.1}{127.0.0.1:41242} join existing leader], term: 1, version: 1, reason: master node changed {previous [], current [{node_s1}{saAXE5n_SbeS_kPuGtZ9eQ}{IlVsI13pT3m97zB9kigMBw}{127.0.0.1}{127.0.0.1:43437}]}, added {{node_s0}{FOMFnLR6RaC0dEzMnFkJ1A}{6t1ue7wmTM626qcAoGXuVw}{127.0.0.1}{127.0.0.1:35907},{node_s2}{2TYkOhZXTt-QaPNJgYFNsw}{DbhzCUXTR7SBzAU85okUDQ}{127.0.0.1}{127.0.0.1:41242},}
  1> [2019-01-29T15:44:35,492][INFO ][o.e.c.s.ClusterApplierService] [node_s0] master node changed {previous [], current [{node_s1}{saAXE5n_SbeS_kPuGtZ9eQ}{IlVsI13pT3m97zB9kigMBw}{127.0.0.1}{127.0.0.1:43437}]}, added {{node_s1}{saAXE5n_SbeS_kPuGtZ9eQ}{IlVsI13pT3m97zB9kigMBw}{127.0.0.1}{127.0.0.1:43437},{node_s2}{2TYkOhZXTt-QaPNJgYFNsw}{DbhzCUXTR7SBzAU85okUDQ}{127.0.0.1}{127.0.0.1:41242},}, term: 1, version: 1, reason: ApplyCommitRequest{term=1, version=1, sourceNode={node_s1}{saAXE5n_SbeS_kPuGtZ9eQ}{IlVsI13pT3m97zB9kigMBw}{127.0.0.1}{127.0.0.1:43437}}
  2> REPRODUCE WITH: ./gradlew :server:integTest -Dtests.seed=233C30BFCE2B7117 -Dtests.class=org.elasticsearch.action.admin.HotThreadsIT -Dtests.method="testHotThreadsDontFail" -Dtests.security.manager=true -Dtests.locale=es-MX -Dtests.timezone=Asia/Yerevan -Dcompiler.java=11 -Druntime.java=8
  1> [2019-01-29T15:44:35,494][INFO ][o.e.c.s.ClusterApplierService] [node_s2] master node changed {previous [], current [{node_s1}{saAXE5n_SbeS_kPuGtZ9eQ}{IlVsI13pT3m97zB9kigMBw}{127.0.0.1}{127.0.0.1:43437}]}, added {{node_s1}{saAXE5n_SbeS_kPuGtZ9eQ}{IlVsI13pT3m97zB9kigMBw}{127.0.0.1}{127.0.0.1:43437},{node_s0}{FOMFnLR6RaC0dEzMnFkJ1A}{6t1ue7wmTM626qcAoGXuVw}{127.0.0.1}{127.0.0.1:35907},}, term: 1, version: 1, reason: ApplyCommitRequest{term=1, version=1, sourceNode={node_s1}{saAXE5n_SbeS_kPuGtZ9eQ}{IlVsI13pT3m97zB9kigMBw}{127.0.0.1}{127.0.0.1:43437}}
  2> NOTE: leaving temporary files on disk at: /var/lib/jenkins/workspace/elastic+elasticsearch+master+multijob-unix-compatibility/os/centos/server/build/testrun/integTest/J3/temp/org.elasticsearch.action.admin.HotThreadsIT_233C30BFCE2B7117-001
  2> NOTE: test params are: codec=Asserting(Lucene80): {field1.keyword=PostingsFormat(name=Asserting), field1=PostingsFormat(name=Asserting), _id=PostingsFormat(name=Asserting)}, docValues:{field1.keyword=DocValuesFormat(name=Lucene70), _seq_no=DocValuesFormat(name=Lucene70), _primary_term=DocValuesFormat(name=Lucene70), _version=DocValuesFormat(name=Lucene70)}, maxPointsInLeafNode=128, maxMBSortInHeap=5.534645509088748, sim=Asserting(org.apache.lucene.search.similarities.AssertingSimilarity@7769dd0e), locale=es-MX, timezone=Asia/Yerevan
  2> NOTE: Linux 2.6.32-754.10.1.el6.x86_64 amd64/Oracle Corporation 1.8.0_202 (64-bit)/cpus=16,threads=1,free=465545688,total=513802240
  1> [2019-01-29T15:44:35,497][INFO ][o.e.n.Node               ] [integ_1] started
  2> NOTE: All tests run in this JVM: [HotThreadsIT]
  1> [2019-01-29T15:44:35,497][INFO ][o.e.n.Node               ] [integ_3] started
  1> [2019-01-29T15:44:35,504][INFO ][o.e.c.s.ClusterApplierService] [node_s1] master node changed {previous [], current [{node_s1}{saAXE5n_SbeS_kPuGtZ9eQ}{IlVsI13pT3m97zB9kigMBw}{127.0.0.1}{127.0.0.1:43437}]}, added {{node_s0}{FOMFnLR6RaC0dEzMnFkJ1A}{6t1ue7wmTM626qcAoGXuVw}{127.0.0.1}{127.0.0.1:35907},{node_s2}{2TYkOhZXTt-QaPNJgYFNsw}{DbhzCUXTR7SBzAU85okUDQ}{127.0.0.1}{127.0.0.1:41242},}, term: 1, version: 1, reason: Publication{term=1, version=1}
  1> [2019-01-29T15:44:35,516][INFO ][o.e.n.Node               ] [integ_2] started
  1> [2019-01-29T15:44:35,544][INFO ][o.e.c.s.MasterService    ] [node_s1] node-join[{node_sc3}{aV_f9mFyTOWlZhplwSEfxQ}{qceQ1ZilTLikPSqFG3IJ4w}{127.0.0.1}{127.0.0.1:45343} join existing leader], term: 1, version: 2, reason: added {{node_sc3}{aV_f9mFyTOWlZhplwSEfxQ}{qceQ1ZilTLikPSqFG3IJ4w}{127.0.0.1}{127.0.0.1:45343},}
  1> [2019-01-29T15:44:35,578][INFO ][o.e.c.s.ClusterApplierService] [node_s2] added {{node_sc3}{aV_f9mFyTOWlZhplwSEfxQ}{qceQ1ZilTLikPSqFG3IJ4w}{127.0.0.1}{127.0.0.1:45343},}, term: 1, version: 2, reason: ApplyCommitRequest{term=1, version=2, sourceNode={node_s1}{saAXE5n_SbeS_kPuGtZ9eQ}{IlVsI13pT3m97zB9kigMBw}{127.0.0.1}{127.0.0.1:43437}}
  1> [2019-01-29T15:44:35,578][INFO ][o.e.c.s.ClusterApplierService] [node_sc3] master node changed {previous [], current [{node_s1}{saAXE5n_SbeS_kPuGtZ9eQ}{IlVsI13pT3m97zB9kigMBw}{127.0.0.1}{127.0.0.1:43437}]}, added {{node_s1}{saAXE5n_SbeS_kPuGtZ9eQ}{IlVsI13pT3m97zB9kigMBw}{127.0.0.1}{127.0.0.1:43437},{node_s0}{FOMFnLR6RaC0dEzMnFkJ1A}{6t1ue7wmTM626qcAoGXuVw}{127.0.0.1}{127.0.0.1:35907},{node_s2}{2TYkOhZXTt-QaPNJgYFNsw}{DbhzCUXTR7SBzAU85okUDQ}{127.0.0.1}{127.0.0.1:41242},}, term: 1, version: 2, reason: ApplyCommitRequest{term=1, version=2, sourceNode={node_s1}{saAXE5n_SbeS_kPuGtZ9eQ}{IlVsI13pT3m97zB9kigMBw}{127.0.0.1}{127.0.0.1:43437}}
  1> [2019-01-29T15:44:35,579][INFO ][o.e.n.Node               ] [integ_4] started
  1> [2019-01-29T15:44:35,580][INFO ][o.e.c.s.ClusterApplierService] [node_s0] added {{node_sc3}{aV_f9mFyTOWlZhplwSEfxQ}{qceQ1ZilTLikPSqFG3IJ4w}{127.0.0.1}{127.0.0.1:45343},}, term: 1, version: 2, reason: ApplyCommitRequest{term=1, version=2, sourceNode={node_s1}{saAXE5n_SbeS_kPuGtZ9eQ}{IlVsI13pT3m97zB9kigMBw}{127.0.0.1}{127.0.0.1:43437}}
  1> [2019-01-29T15:44:35,633][INFO ][o.e.c.s.ClusterApplierService] [node_s1] added {{node_sc3}{aV_f9mFyTOWlZhplwSEfxQ}{qceQ1ZilTLikPSqFG3IJ4w}{127.0.0.1}{127.0.0.1:45343},}, term: 1, version: 2, reason: Publication{term=1, version=2}
  1> [2019-01-29T15:44:35,750][INFO ][o.e.g.GatewayService     ] [node_s1] recovered [0] indices into cluster_state
  1> [2019-01-29T15:44:36,331][INFO ][o.e.c.m.MetaDataIndexTemplateService] [node_s1] adding template [random_index_template] for index patterns [*]
  1> [2019-01-29T15:44:36,402][INFO ][o.e.a.a.HotThreadsIT     ] [testHotThreadsDontFail] [HotThreadsIT#testHotThreadsDontFail]: all set up test
  1> [2019-01-29T15:44:36,416][INFO ][o.e.a.a.HotThreadsIT     ] [testHotThreadsDontFail] using custom data_path for index: [HudQrFRmGG]
  1> [2019-01-29T15:44:36,455][INFO ][o.e.c.m.MetaDataCreateIndexService] [node_s1] [test] creating index, cause [api], templates [random_index_template], shards [6]/[1], mappings []
  1> [2019-01-29T15:44:37,806][INFO ][o.e.a.a.HotThreadsIT     ] [testHotThreadsDontFail] Index [3] docs async: [true] bulk: [false]
  1> [2019-01-29T15:44:38,270][INFO ][o.e.c.r.a.AllocationService] [node_s1] Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[test][5], [test][1], [test][0], [test][3], [test][2]] ...]).
  1> [2019-01-29T15:44:38,427][INFO ][o.e.c.m.MetaDataMappingService] [node_s1] [test/Xna3aYPaSLezRRHL3OvARQ] create_mapping [type1]
  1> [2019-01-29T15:44:40,095][INFO ][o.e.p.PluginsService     ] [testHotThreadsDontFail] no modules loaded
  1> [2019-01-29T15:44:40,095][INFO ][o.e.p.PluginsService     ] [testHotThreadsDontFail] loaded plugin [org.elasticsearch.transport.nio.MockNioTransportPlugin]
  1> [2019-01-29T15:44:40,318][INFO ][o.e.p.PluginsService     ] [testHotThreadsDontFail] no modules loaded
  1> [2019-01-29T15:44:40,318][INFO ][o.e.p.PluginsService     ] [testHotThreadsDontFail] loaded plugin [org.elasticsearch.transport.nio.MockNioTransportPlugin]
  1> [2019-01-29T15:45:10,475][INFO ][o.e.a.a.HotThreadsIT     ] [testHotThreadsDontFail] [HotThreadsIT#testHotThreadsDontFail]: cleaning up after test
  1> [2019-01-29T15:45:10,487][WARN ][o.e.t.OutboundHandler    ] [node_s1] send message failed [channel: NioSocketChannel{localAddress=/127.0.0.1:43437, remoteAddress=/127.0.0.1:57414}]
  1> java.io.IOException: Connection reset by peer
  1> 	at sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[?:?]
  1> 	at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) ~[?:?]
  1> 	at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) ~[?:?]
  1> 	at sun.nio.ch.IOUtil.write(IOUtil.java:51) ~[?:?]
  1> 	at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471) ~[?:?]
  1> 	at org.elasticsearch.nio.SocketChannelContext.flushToChannel(SocketChannelContext.java:336) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.BytesChannelContext.singleFlush(BytesChannelContext.java:87) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.BytesChannelContext.flushChannel(BytesChannelContext.java:59) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.EventHandler.handleWrite(EventHandler.java:139) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.NioSelector.handleWrite(NioSelector.java:390) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.NioSelector.writeToChannel(NioSelector.java:339) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.SocketChannelContext.sendMessage(SocketChannelContext.java:143) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.transport.nio.MockNioTransport$MockSocketChannel.sendMessage(MockNioTransport.java:314) ~[framework-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.transport.OutboundHandler.internalSendMessage(OutboundHandler.java:80) ~[main/:?]
  1> 	at org.elasticsearch.transport.OutboundHandler.sendMessage(OutboundHandler.java:70) ~[main/:?]
  1> 	at org.elasticsearch.transport.TcpTransport.sendResponse(TcpTransport.java:737) ~[main/:?]
  1> 	at org.elasticsearch.transport.TcpTransport.lambda$new$1(TcpTransport.java:162) ~[main/:?]
  1> 	at org.elasticsearch.transport.TransportHandshaker.handleHandshake(TransportHandshaker.java:98) ~[main/:?]
  1> 	at org.elasticsearch.transport.TcpTransport.handleRequest(TcpTransport.java:1018) ~[main/:?]
  1> 	at org.elasticsearch.transport.TcpTransport.messageReceived(TcpTransport.java:921) ~[main/:?]
  1> 	at org.elasticsearch.transport.TcpTransport.inboundMessage(TcpTransport.java:752) ~[main/:?]
  1> 	at org.elasticsearch.transport.TcpTransport.consumeNetworkReads(TcpTransport.java:779) ~[main/:?]
  1> 	at org.elasticsearch.transport.nio.MockNioTransport$MockTcpReadWriteHandler.consumeReads(MockNioTransport.java:241) ~[framework-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.SocketChannelContext.handleReadBytes(SocketChannelContext.java:213) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.BytesChannelContext.read(BytesChannelContext.java:47) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.EventHandler.handleRead(EventHandler.java:119) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.NioSelector.handleRead(NioSelector.java:398) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.NioSelector.processKey(NioSelector.java:246) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.NioSelector.singleLoop(NioSelector.java:172) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.NioSelector.runLoop(NioSelector.java:129) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_202]
  1> [2019-01-29T15:45:10,495][WARN ][o.e.t.TransportService   ] [node_s1] Received response for a request that has timed out, sent [30076ms] ago, timed out [0ms] ago, action [internal:coordination/fault_detection/follower_check], node [{node_s0}{FOMFnLR6RaC0dEzMnFkJ1A}{6t1ue7wmTM626qcAoGXuVw}{127.0.0.1}{127.0.0.1:35907}], id [146]
  1> [2019-01-29T15:45:10,655][INFO ][o.e.c.m.MetaDataDeleteIndexService] [node_s1] [test/Xna3aYPaSLezRRHL3OvARQ] deleting index
  1> [2019-01-29T15:45:11,051][INFO ][o.e.c.m.MetaDataIndexTemplateService] [node_s1] removing template [random_index_template]
  1> [2019-01-29T15:45:11,084][INFO ][o.e.p.PluginsService     ] [testHotThreadsDontFail] no modules loaded
  1> [2019-01-29T15:45:11,085][INFO ][o.e.p.PluginsService     ] [testHotThreadsDontFail] loaded plugin [org.elasticsearch.transport.nio.MockNioTransportPlugin]
  1> [2019-01-29T15:45:11,176][INFO ][o.e.a.a.HotThreadsIT     ] [testHotThreadsDontFail] [HotThreadsIT#testHotThreadsDontFail]: cleaned up after test
  1> [2019-01-29T15:45:11,177][INFO ][o.e.a.a.HotThreadsIT     ] [testHotThreadsDontFail] after test
ERROR   44.7s J3 | HotThreadsIT.testHotThreadsDontFail <<< FAILURES!
   > Throwable #1: NoNodeAvailableException[None of the configured nodes are available: [{#transport#-1}{EF_FcOpLTPeZQ_LUVd5MNA}{127.0.0.1}{127.0.0.1:43437}]]
   > 	at __randomizedtesting.SeedInfo.seed([233C30BFCE2B7117:71D6155E6A3F7E85]:0)
   > 	at org.elasticsearch.client.transport.TransportClientNodesService.ensureNodesAreAvailable(TransportClientNodesService.java:351)
   > 	at org.elasticsearch.client.transport.TransportClientNodesService.execute(TransportClientNodesService.java:249)
   > 	at org.elasticsearch.client.transport.TransportProxyClient.execute(TransportProxyClient.java:57)
   > 	at org.elasticsearch.client.transport.TransportClient.doExecute(TransportClient.java:386)
   > 	at org.elasticsearch.client.support.AbstractClient.execute(AbstractClient.java:393)
   > 	at org.elasticsearch.client.support.AbstractClient.execute(AbstractClient.java:382)
   > 	at org.elasticsearch.action.ActionRequestBuilder.execute(ActionRequestBuilder.java:45)
   > 	at org.elasticsearch.action.ActionRequestBuilder.get(ActionRequestBuilder.java:52)
   > 	at org.elasticsearch.action.admin.HotThreadsIT.testHotThreadsDontFail(HotThreadsIT.java:125)
   > 	at java.lang.Thread.run(Thread.java:748)

[elasticmachine]

Pinging @elastic/es-core-infra

[danielmitterdorfer]

To me it appears as if there is no actual problem with the test per se but rather that there was a problem sending a message between node_s1 and (probably) node_s0 because node_s0 was slow to respond.

In the logs we see:

12:45:20   1> [2019-01-29T15:45:10,487][WARN ][o.e.t.OutboundHandler    ] [node_s1] send message failed [channel: NioSocketChannel{localAddress=/127.0.0.1:43437, remoteAddress=/127.0.0.1:57414}]

followed by:

12:45:20   1> [2019-01-29T15:45:10,495][WARN ][o.e.t.TransportService   ] [node_s1] Received response for a request that has timed out, sent [30076ms] ago, timed out [0ms] ago, action [internal:coordination/fault_detection/follower_check], node [{node_s0}{FOMFnLR6RaC0dEzMnFkJ1A}{6t1ue7wmTM626qcAoGXuVw}{127.0.0.1}{127.0.0.1:35907}], id [146]

However, there is no indication why node_s0 was slow to respond but I wonder whether this is related to the timeout issues in CI by which we have been plagued recently.

I have also attached the full logs for this test suite.

[danielmitterdorfer]

Closing this one as a duplicate of #37275.

[elasticmachine]

Pinging @elastic/es-distributed

[droberts195]

The same test failed in the same way in https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+7.0+intake/93/console

I do wonder whether this is not simply a case of CI machine slowness though.

Here is the relevant snippet from this failure log:

16:04:08   1> [2019-02-14T17:03:38,163][INFO ][o.e.p.PluginsService     ] [testHotThreadsDontFail] loaded plugin [org.elasticsearch.transport.nio.MockNioTransportPlugin]
16:04:08   1> [2019-02-14T17:04:08,232][INFO ][o.e.a.a.HotThreadsIT     ] [testHotThreadsDontFail] [HotThreadsIT#testHotThreadsDontFail]: cleaning up after test
16:04:08   1> [2019-02-14T17:04:08,234][WARN ][o.e.t.TransportService   ] [node_sm0] Received response for a request that has timed out, sent [27427ms] ago, timed out [17413ms] ago, action [internal:coordination/fault_detection/follower_check], node [{node_sd3}{CwpFk8h5T3SajLe2yZ2vCw}{uBsXp-VASRCdoNhVY14Agg}{127.0.0.1}{127.0.0.1:35479}], id [1162]
16:04:08   1> [2019-02-14T17:04:08,233][WARN ][o.e.t.OutboundHandler    ] [node_sd3] send message failed [channel: NioSocketChannel{localAddress=/127.0.0.1:35479, remoteAddress=/127.0.0.1:36046}]
16:04:08   1> java.io.IOException: Connection reset by peer

There is no response for almost exactly 30 seconds. Then within 0.002 seconds of the test giving up and failing it receives the response. It reeks of the network layer failing to pass on a message until it is shut down. Could an expert in Elasticsearch networking think of a reason why this might happen?

[droberts195]

A similar thing happened in the original report - no response for almost exactly 30 seconds then a response 0.008 seconds after giving up.

[droberts195]

It reeks of the network layer failing to pass on a message

It is of course the mock network layer, so probably not a problem for production, just maybe a source of spurious test failures.

[original-brownbear]

It is of course the mock network layer, so probably not a problem for production, just maybe a source of spurious test failures.

I agree: the fact that we fail to process messages in both directions for 30s and then suddenly wake up to continue by finishing multiple operations when our default timeout on many operations is 30s as well is very suspicious here.

In particular:

  1> [2019-02-14T17:03:38,163][INFO ][o.e.p.PluginsService     ] [testHotThreadsDontFail] loaded plugin [org.elasticsearch.transport.nio.MockNioTransportPlugin]
  1> [2019-02-14T17:04:08,232][INFO ][o.e.a.a.HotThreadsIT     ] [testHotThreadsDontFail] [HotThreadsIT#testHotThreadsDontFail]: cleaning up after test
  1> [2019-02-14T17:04:08,234][WARN ][o.e.t.TransportService   ] [node_sm0] Received response for a request that has timed out, sent [27427ms] ago, timed out [17413ms] ago, action [internal:coordination/fault_detection/follower_check], node [{node_sd3}{CwpFk8h5T3SajLe2yZ2vCw}{uBsXp-VASRCdoNhVY14Agg}{127.0.0.1}{127.0.0.1:35479}], id [1162]
  1> [2019-02-14T17:04:08,233][WARN ][o.e.t.OutboundHandler    ] [node_sd3] send message failed [channel: NioSocketChannel{localAddress=/127.0.0.1:35479, remoteAddress=/127.0.0.1:36046}]
  1> java.io.IOException: Connection reset by peer
  1> 	at sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[?:?]
  1> 	at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) ~[?:?]
  1> 	at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) ~[?:?]
  1> 	at sun.nio.ch.IOUtil.write(IOUtil.java:51) ~[?:?]
  1> 	at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471) ~[?:?]
  1> 	at org.elasticsearch.nio.SocketChannelContext.flushToChannel(SocketChannelContext.java:336) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.BytesChannelContext.singleFlush(BytesChannelContext.java:87) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.BytesChannelContext.flushChannel(BytesChannelContext.java:59) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.EventHandler.handleWrite(EventHandler.java:139) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.NioSelector.handleWrite(NioSelector.java:390) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.NioSelector.writeToChannel(NioSelector.java:339) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.SocketChannelContext.sendMessage(SocketChannelContext.java:143) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.transport.nio.MockNioTransport$MockSocketChannel.sendMessage(MockNioTransport.java:314) ~[framework-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.transport.OutboundHandler.internalSendMessage(OutboundHandler.java:80) ~[main/:?]
  1> 	at org.elasticsearch.transport.OutboundHandler.sendMessage(OutboundHandler.java:70) ~[main/:?]
  1> 	at org.elasticsearch.transport.TcpTransport.sendResponse(TcpTransport.java:737) ~[main/:?]
  1> 	at org.elasticsearch.transport.TcpTransport.lambda$new$1(TcpTransport.java:162) ~[main/:?]
  1> 	at org.elasticsearch.transport.TransportHandshaker.handleHandshake(TransportHandshaker.java:100) ~[main/:?]
  1> 	at org.elasticsearch.transport.TcpTransport.handleRequest(TcpTransport.java:1018) ~[main/:?]
  1> 	at org.elasticsearch.transport.TcpTransport.messageReceived(TcpTransport.java:921) ~[main/:?]
  1> 	at org.elasticsearch.transport.TcpTransport.inboundMessage(TcpTransport.java:752) ~[main/:?]
  1> 	at org.elasticsearch.transport.TcpTransport.consumeNetworkReads(TcpTransport.java:779) ~[main/:?]
  1> 	at org.elasticsearch.transport.nio.MockNioTransport$MockTcpReadWriteHandler.consumeReads(MockNioTransport.java:241) ~[framework-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.SocketChannelContext.handleReadBytes(SocketChannelContext.java:213) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.BytesChannelContext.read(BytesChannelContext.java:47) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.EventHandler.handleRead(EventHandler.java:119) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.NioSelector.handleRead(NioSelector.java:398) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.NioSelector.processKey(NioSelector.java:246) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.NioSelector.singleLoop(NioSelector.java:172) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at org.elasticsearch.nio.NioSelector.runLoop(NioSelector.java:129) ~[elasticsearch-nio-7.0.0-SNAPSHOT.jar:7.0.0-SNAPSHOT]
  1> 	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_202]
  1> [2019-02-14T17:04:08,234][WARN ][o.e.t.TransportService   ] [node_sm0] Received response for a request that has timed out, sent [14411ms] ago, timed out [4404ms] ago, action [internal:coordination/fault_detection/follower_check], node [{node_sd3}{CwpFk8h5T3SajLe2yZ2vCw}{uBsXp-VASRCdoNhVY14Agg}{127.0.0.1}{127.0.0.1:35479}], id [1204]
  1> [2019-02-14T17:04:08,234][WARN ][o.e.t.TransportService   ] [node_sd3] Received response for a request that has timed out, sent [29428ms] ago, timed out [19420ms] ago, action [internal:coordination/fault_detection/leader_check], node [{node_sm0}{22PS6dUhSCuN10EVV44bJA}{Rm_b9V-OR3SNN9uEAGQOmg}{127.0.0.1}{127.0.0.1:41899}], id [1237]
  1> [2019-02-14T17:04:08,234][WARN ][o.e.t.TransportService   ] [node_sd3] Received response for a request that has timed out, sent [16413ms] ago, timed out [6404ms] ago, action [internal:coordination/fault_detection/leader_check], node [{node_sm0}{22PS6dUhSCuN10EVV44bJA}{Rm_b9V-OR3SNN9uEAGQOmg}{127.0.0.1}{127.0.0.1:41899}], id [1240]

suggests that we may be missing a write somewhere and then triggering it somehow because some other thing triggers a new write 30s later to get the IO loop to pick up the writes again. It's just too much of a coincidence to be explained by a slow CI run or GC pause.

[original-brownbear]

Closing this as a duplicate of #37275 again. This is a general issue not specific to this test.