[CI] RelocationIT testIndexAndRelocateConcurrently fails

[cbuescher]

Link to build: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.x+multijob-java-periodic/ESJAVA=java9,ESRUNTIME=openjdk10,nodes=linux/11/console

Doesn't reproduce locally so far:

REPRODUCE WITH: ./gradlew :server:integTest \
  -Dtests.seed=8489FAA2C90E2AAC \
  -Dtests.class=org.elasticsearch.recovery.RelocationIT \
  -Dtests.method="testIndexAndRelocateConcurrently" \
  -Dtests.security.manager=true \
  -Dtests.locale=fi-FI \
  -Dtests.timezone=Europe/Skopje

This looks like the cause of the failure:

04:29:14   1> [2018-03-20T05:29:03,303][WARN ][o.e.i.r.RecoverySourceHandler] [node_t0] [test][0][recover to node_t1] 0 Remote file corruption on node {node_t1}{dE8cLV8gTuCMFnxS0ICKLw}{bENA6S-IRRa1T-O0CtNuhA}{127.0.0.1}{127.0.0.1:59176}, recovering name [segments_2], length [294], checksum [4qv6i7], writtenBy [7.2.1]. local checksum OK
04:29:14   1> org.apache.lucene.index.CorruptIndexException: checksum failed (hardware problem?) : expected=4qv6i7 actual=1afllwc (resource=name [segments_2], length [294], checksum [4qv6i7], writtenBy [7.2.1]) (resource=VerifyingIndexOutput(segments_2))
04:29:14   1> 	at org.elasticsearch.index.store.Store$LuceneVerifyingIndexOutput.readAndCompareChecksum(Store.java:1226) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.index.store.Store$LuceneVerifyingIndexOutput.writeByte(Store.java:1205) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.index.store.Store$LuceneVerifyingIndexOutput.writeBytes(Store.java:1234) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.indices.recovery.RecoveryTarget.writeFileChunk(RecoveryTarget.java:487) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.indices.recovery.PeerRecoveryTargetService$FileChunkTransportRequestHandler.messageReceived(PeerRecoveryTargetService.java:598) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.indices.recovery.PeerRecoveryTargetService$FileChunkTransportRequestHandler.messageReceived(PeerRecoveryTargetService.java:571) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.transport.TransportRequestHandler.messageReceived(TransportRequestHandler.java:30) [main/:?]
04:29:14   1> 	at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:66) [main/:?]
04:29:14   1> 	at org.elasticsearch.transport.TcpTransport$RequestHandler.doRun(TcpTransport.java:1555) [main/:?]
04:29:14   1> 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:672) [main/:?]
04:29:14   1> 	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [main/:?]
04:29:14   1> 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1135) [?:?]
04:29:14   1> 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
04:29:14   1> 	at java.lang.Thread.run(Thread.java:844) [?:?]
04:29:14   1> [2018-03-20T05:29:03,307][TRACE][o.e.i.r.PeerRecoveryTargetService] [node_t1] [test][0] Got exception on recovery
04:29:14   1> org.elasticsearch.transport.RemoteTransportException: [node_t0][127.0.0.1:31016][internal:index/shard/recovery/start_recovery]
04:29:14   1> Caused by: org.elasticsearch.index.engine.RecoveryEngineException: Phase[1] phase1 failed
04:29:14   1> 	at org.elasticsearch.indices.recovery.RecoverySourceHandler.recoverToTarget(RecoverySourceHandler.java:175) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.indices.recovery.PeerRecoverySourceService.recover(PeerRecoverySourceService.java:98) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.indices.recovery.PeerRecoverySourceService.access$000(PeerRecoverySourceService.java:50) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.indices.recovery.PeerRecoverySourceService$StartRecoveryTransportRequestHandler.messageReceived(PeerRecoverySourceService.java:107) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.indices.recovery.PeerRecoverySourceService$StartRecoveryTransportRequestHandler.messageReceived(PeerRecoverySourceService.java:104) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.transport.TransportRequestHandler.messageReceived(TransportRequestHandler.java:30) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:66) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.transport.TcpTransport$RequestHandler.doRun(TcpTransport.java:1555) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:672) [main/:?]
04:29:14   1> 	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [main/:?]
04:29:14   1> 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1135) [?:?]
04:29:14   1> 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
04:29:14   1> 	at java.lang.Thread.run(Thread.java:844) [?:?]
04:29:14   1> Caused by: org.elasticsearch.indices.recovery.RecoverFilesRecoveryException: Failed to transfer [4] files with total size of [3.5kb]
04:29:14   1> 	at org.elasticsearch.indices.recovery.RecoverySourceHandler.phase1(RecoverySourceHandler.java:426) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.indices.recovery.RecoverySourceHandler.recoverToTarget(RecoverySourceHandler.java:173) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.indices.recovery.PeerRecoverySourceService.recover(PeerRecoverySourceService.java:98) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.indices.recovery.PeerRecoverySourceService.access$000(PeerRecoverySourceService.java:50) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.indices.recovery.PeerRecoverySourceService$StartRecoveryTransportRequestHandler.messageReceived(PeerRecoverySourceService.java:107) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.indices.recovery.PeerRecoverySourceService$StartRecoveryTransportRequestHandler.messageReceived(PeerRecoverySourceService.java:104) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.transport.TransportRequestHandler.messageReceived(TransportRequestHandler.java:30) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:66) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.transport.TcpTransport$RequestHandler.doRun(TcpTransport.java:1555) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:672) ~[main/:?]
04:29:14   1> 	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) ~[main/:?]
04:29:14   1> 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1135) ~[?:?]
04:29:14   1> 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
04:29:14   1> 	at java.lang.Thread.run(Thread.java:844) ~[?:?]
04:29:14   1> Caused by: org.elasticsearch.transport.RemoteTransportException: [File corruption occurred on recovery but checksums are ok]
04:29:14   1> 	Suppressed: org.elasticsearch.transport.RemoteTransportException: [node_t1][127.0.0.1:59176][internal:index/shard/recovery/file_chunk]
04:29:14   1> 	Caused by: org.apache.lucene.index.CorruptIndexException: checksum failed (hardware problem?) : expected=4qv6i7 actual=1afllwc (resource=name [segments_2], length [294], checksum [4qv6i7], writtenBy [7.2.1]) (resource=VerifyingIndexOutput(segments_2))
04:29:14   1> 		at org.elasticsearch.index.store.Store$LuceneVerifyingIndexOutput.readAndCompareChecksum(Store.java:1226) ~[main/:?]
04:29:14   1> 		at org.elasticsearch.index.store.Store$LuceneVerifyingIndexOutput.writeByte(Store.java:1205) ~[main/:?]
04:29:14   1> 		at org.elasticsearch.index.store.Store$LuceneVerifyingIndexOutput.writeBytes(Store.java:1234) ~[main/:?]
04:29:14   1> 		at org.elasticsearch.indices.recovery.RecoveryTarget.writeFileChunk(RecoveryTarget.java:487) ~[main/:?]
04:29:14   1> 		at org.elasticsearch.indices.recovery.PeerRecoveryTargetService$FileChunkTransportRequestHandler.messageReceived(PeerRecoveryTargetService.java:598) ~[main/:?]
04:29:14   1> 		at org.elasticsearch.indices.recovery.PeerRecoveryTargetService$FileChunkTransportRequestHandler.messageReceived(PeerRecoveryTargetService.java:571) ~[main/:?]
04:29:14   1> 		at org.elasticsearch.transport.TransportRequestHandler.messageReceived(TransportRequestHandler.java:30) ~[main/:?]
04:29:14   1> 		at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:66) ~[main/:?]
04:29:14   1> 		at org.elasticsearch.transport.TcpTransport$RequestHandler.doRun(TcpTransport.java:1555) ~[main/:?]
04:29:14   1> 		at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:672) [main/:?]
04:29:14   1> 		at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [main/:?]
04:29:14   1> 		at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1135) [?:?]
04:29:14   1> 		at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
04:29:14   1> 		at java.lang.Thread.run(Thread.java:844) [?:?]
04:29:14   1> [2018-03-20T05:29:03,308][TRACE][o.e.i.r.PeerRecoveryTargetService] [node_t1] [test][0] failing recovery from {node_t0}{WB-cLhbrSqqhCbXQ30dZaQ}{DxteO7dbRBiM2AE_dcp74Q}{127.0.0.1}{127.0.0.1:31016}, id [1803]. Send shard failure: [true]

[elasticmachine]

Pinging @elastic/es-distributed

[martijnvg]

Another failure: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.3+multijob-unix-compatibility/os=opensuse/4/console

This time it is a suite time out:
consoleLogs1.txt

[ywelsch]

I've looked at the latest instance provided by @martijnvg. The reason the suite times out is that a primary gets stuck relocating because it cannot acquire the operations permit for the relocation handoff (it waits up to 30 minutes for that) and the test waits for replication operations to complete, one of which does not seem to complete (and not release the operation permit). The operation that is not completing / releasing the operations permit is ▙▗▋█▌▀▇▋▔a195. The logs show:

[2018-04-26T05:30:47,233][TRACE][o.e.a.b.TransportShardBulkAction] [node_t0] send action [indices:data/write/bulk[s]] on primary [[test][1]] for request [BulkShardRequest [[test][1]] containing [index {[test][type1][▙▗▋█▌▀▇▋▔a195], source[{"field1":"one hundred ninety-five "}]}]] with cluster state version [10] to [rFPIA0SCTROJbSppOfu2yA]
[2018-04-26T05:30:47,234][TRACE][o.e.a.b.TransportShardBulkAction] [node_t3] send action [indices:data/write/bulk[s][p]] to local primary [[test][1]] for request [BulkShardRequest [[test][1]] containing [index {[test][type1][▙▗▋█▌▀▇▋▔a195], source[{"field1":"one hundred ninety-five "}]}]] with cluster state version [10] to [rFPIA0SCTROJbSppOfu2yA]

but misses the message showing completion of the operation on the primary, e.g. something along the lines of

[2018-04-26T05:30:47,253][TRACE][o.e.a.b.TransportShardBulkAction] [node_t1] [[test][4]] op [indices:data/write/bulk[s]] completed on primary for request [BulkShardRequest [[test][4]] containing [index {[test][type1][𝌌𝌥𝌁𝌌aa232], source[{"field1":"two hundred thirty-two "}]}]]

The thread dump does not show any activity for the write thread on node_t3 so it does not look like the index operation is actively stuck on the primary. I'm not sure how the operation could have terminated, however, without releasing the permit?

This looks potentially dangerous.

[bleskes]

@ywelsch I'm moving the discussion about the relevance of #30316 here - you mention that you had an indexing operation that failed to complete? can you tell if it was indexing after the primary tried to relocate? if that seems likely then I would agree we can see #30316 as an explanation

[ywelsch]

My analysis was unfortunately inconclusive on this. There have also been no more occurrences of this since @martijnvg reported the last failure. I'm suggesting to close this one for now, and reopen if it occurs again.

[dimitris-athanasiou]

Got another failure of this test. Not sure it is the same reason.

The build is https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+7.3+EAR/73/console

and the relevant scan is https://gradle-enterprise.elastic.co/s/ois5x3v567mlq/tests/kyv2y2z3r4v7m-xytyvorqhynac?openStackTraces=WzFd

The failure this time is:

com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=274, name=elasticsearch[node_t1][generic][T#1], state=RUNNABLE, group=TGRP-RelocationIT]Open stacktrace
Caused by: java.lang.AssertionError: (No message provided)Close stacktrace
at __randomizedtesting.SeedInfo.seed([E725949EF7A0F9A3]:0)
at org.elasticsearch.index.shard.IndexShard.activateWithPrimaryContext(IndexShard.java:2275)
at org.elasticsearch.indices.recovery.RecoveryTarget.handoffPrimaryContext(RecoveryTarget.java:319)
at org.elasticsearch.indices.recovery.PeerRecoveryTargetService$HandoffPrimaryContextRequestHandler.messageReceived(PeerRecoveryTargetService.java:457)
at org.elasticsearch.indices.recovery.PeerRecoveryTargetService$HandoffPrimaryContextRequestHandler.messageReceived(PeerRecoveryTargetService.java:451)
at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:63)
at org.elasticsearch.transport.InboundHandler$RequestHandler.doRun(InboundHandler.java:267)
at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:758)
at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

Reproduce with:

./gradlew :server:integTest --tests "org.elasticsearch.recovery.RelocationIT.testIndexAndRelocateConcurrently" -Dtests.seed=E725949EF7A0F9A3 -Dtests.security.manager=true -Dtests.locale=da-DK -Dtests.timezone=Pacific/Yap -Dcompiler.java=12 -Druntime.java=8