[CI] SplitIndexIT.testSplitIndexPrimaryTerm Failure on Windows

[jdconrad]

Unable to reproduce the failure locally on Arch. It looks like it may be a Windows file system issue based on the console log.

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

Reproduce:

gradlew :server:integTest \
  -Dtests.seed=64C5D7D608CE1D96 \
  -Dtests.class=org.elasticsearch.action.admin.indices.create.SplitIndexIT \
  -Dtests.method="testSplitIndexPrimaryTerm" \
  -Dtests.security.manager=true \
  -Dtests.locale=be \
  -Dtests.timezone=Indian/Chagos

Stack:

17:00:40   1> java.nio.file.NoSuchFileException: C:\Users\jenkins\workspace\elastic+elasticsearch+master+multijob-windows-compatibility\server\build\testrun\integTest\J1\temp\org.elasticsearch.action.admin.indices.create.SplitIndexIT_64C5D7D608CE1D96-001\tempDir-002\data\nodes\1\indices\xKokK_BuT-apELfAZW8bIQ\4\index\_0.cfs
17:00:40   1> 	at sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:79) ~[?:?]
17:00:40   1> 	at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97) ~[?:?]
17:00:40   1> 	at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:102) ~[?:?]
17:00:40   1> 	at sun.nio.fs.WindowsFileSystemProvider.newFileChannel(WindowsFileSystemProvider.java:115) ~[?:?]
17:00:40   1> 	at org.apache.lucene.mockfile.FilterFileSystemProvider.newFileChannel(FilterFileSystemProvider.java:202) ~[lucene-test-framework-7.4.0-snapshot-1ed95c097b.jar:7.4.0-snapshot-1ed95c097b 1ed95c097b82ee5f175e93f3fe62572abe064da6 - jimczi - 2018-05-03 16:16:16]
17:00:40   1> 	at org.apache.lucene.mockfile.DisableFsyncFS.newFileChannel(DisableFsyncFS.java:45) ~[lucene-test-framework-7.4.0-snapshot-1ed95c097b.jar:7.4.0-snapshot-1ed95c097b 1ed95c097b82ee5f175e93f3fe62572abe064da6 - jimczi - 2018-05-03 16:16:16]
17:00:40   1> 	at org.apache.lucene.mockfile.FilterFileSystemProvider.newFileChannel(FilterFileSystemProvider.java:202) ~[lucene-test-framework-7.4.0-snapshot-1ed95c097b.jar:7.4.0-snapshot-1ed95c097b 1ed95c097b82ee5f175e93f3fe62572abe064da6 - jimczi - 2018-05-03 16:16:16]
17:00:40   1> 	at org.apache.lucene.mockfile.HandleTrackingFS.newFileChannel(HandleTrackingFS.java:166) ~[lucene-test-framework-7.4.0-snapshot-1ed95c097b.jar:7.4.0-snapshot-1ed95c097b 1ed95c097b82ee5f175e93f3fe62572abe064da6 - jimczi - 2018-05-03 16:16:16]
17:00:40   1> 	at org.apache.lucene.mockfile.HandleTrackingFS.newFileChannel(HandleTrackingFS.java:166) ~[lucene-test-framework-7.4.0-snapshot-1ed95c097b.jar:7.4.0-snapshot-1ed95c097b 1ed95c097b82ee5f175e93f3fe62572abe064da6 - jimczi - 2018-05-03 16:16:16]
17:00:40   1> 	at java.nio.channels.FileChannel.open(FileChannel.java:287) ~[?:1.8.0_162]
17:00:40   1> 	at java.nio.channels.FileChannel.open(FileChannel.java:335) ~[?:1.8.0_162]
17:00:40   1> 	at org.apache.lucene.store.MMapDirectory.openInput(MMapDirectory.java:238) ~[lucene-core-7.4.0-snapshot-1ed95c097b.jar:7.4.0-snapshot-1ed95c097b 1ed95c097b82ee5f175e93f3fe62572abe064da6 - jimczi - 2018-05-03 16:16:13]
17:00:40   1> 	at org.apache.lucene.store.FilterDirectory.openInput(FilterDirectory.java:99) ~[lucene-core-7.4.0-snapshot-1ed95c097b.jar:7.4.0-snapshot-1ed95c097b 1ed95c097b82ee5f175e93f3fe62572abe064da6 - jimczi - 2018-05-03 16:16:13]
17:00:40   1> 	at org.elasticsearch.index.store.Store$MetadataSnapshot.checksumFromLuceneFile(Store.java:912) ~[main/:?]
17:00:40   1> 	at org.elasticsearch.index.store.Store$MetadataSnapshot.loadMetadata(Store.java:878) [main/:?]
17:00:40   1> 	at org.elasticsearch.index.store.Store$MetadataSnapshot.<init>(Store.java:797) [main/:?]
17:00:40   1> 	at org.elasticsearch.index.store.Store.getMetadata(Store.java:293) [main/:?]
17:00:40   1> 	at org.elasticsearch.index.store.Store.getMetadata(Store.java:258) [main/:?]
17:00:40   1> 	at org.elasticsearch.index.store.Store.cleanupAndVerify(Store.java:689) [main/:?]
17:00:40   1> 	at org.elasticsearch.indices.recovery.RecoveryTarget.cleanFiles(RecoveryTarget.java:440) [main/:?]
17:00:40   1> 	at org.elasticsearch.indices.recovery.PeerRecoveryTargetService$CleanFilesRequestHandler.messageReceived(PeerRecoveryTargetService.java:556) [main/:?]
17:00:40   1> 	at org.elasticsearch.indices.recovery.PeerRecoveryTargetService$CleanFilesRequestHandler.messageReceived(PeerRecoveryTargetService.java:550) [main/:?]
17:00:40   1> 	at org.elasticsearch.transport.TransportRequestHandler.messageReceived(TransportRequestHandler.java:30) [main/:?]
17:00:40   1> 	at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:66) [main/:?]
17:00:40   1> 	at org.elasticsearch.transport.TcpTransport$RequestHandler.doRun(TcpTransport.java:1603) [main/:?]
17:00:40   1> 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:724) [main/:?]
17:00:40   1> 	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [main/:?]
17:00:40   1> 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_162]
17:00:40   1> 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_162]
17:00:40   1> 	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_162]
17:00:40   1> [2018-05-07T23:00:27,722][WARN ][o.e.i.c.IndicesClusterStateService] [node_sd1] [[second_split][4]] marking and sending shard failed due to [failed recovery]
17:00:40 
17:00:40   1> org.elasticsearch.indices.recovery.RecoveryFailedException: [second_split][4]: Recovery failed from {node_sd3}{NLTLyjrDQwuBMTwWDThvbQ}{b3m9isxqQZ29FSiO0_Bk3Q}{127.0.0.1}{127.0.0.1:65365} into {node_sd1}{TwB1E1dsTOqzEmdemTSSFA}{ZGobC3lTRlmButqR-U53Eg}{127.0.0.1}{127.0.0.1:62751} (failed to clean after recovery)
17:00:40   1> 	at org.elasticsearch.indices.recovery.RecoveryTarget.cleanFiles(RecoveryTarget.java:468) [main/:?]
17:00:40   1> 	at org.elasticsearch.indices.recovery.PeerRecoveryTargetService$CleanFilesRequestHandler.messageReceived(PeerRecoveryTargetService.java:556) [main/:?]
17:00:40   1> 	at org.elasticsearch.indices.recovery.PeerRecoveryTargetService$CleanFilesRequestHandler.messageReceived(PeerRecoveryTargetService.java:550) [main/:?]
17:00:40   1> 	at org.elasticsearch.transport.TransportRequestHandler.messageReceived(TransportRequestHandler.java:30) [main/:?]
17:00:40   1> 	at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:66) [main/:?]
17:00:40   1> 	at org.elasticsearch.transport.TcpTransport$RequestHandler.doRun(TcpTransport.java:1603) [main/:?]
17:00:40   1> 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:724) [main/:?]
17:00:40   1> 	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [main/:?]
17:00:40   1> 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_162]
17:00:40   1> 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_162]
17:00:40   1> 	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_162]
17:00:40   1> Caused by: java.nio.file.NoSuchFileException: C:\Users\jenkins\workspace\elastic+elasticsearch+master+multijob-windows-compatibility\server\build\testrun\integTest\J1\temp\org.elasticsearch.action.admin.indices.create.SplitIndexIT_64C5D7D608CE1D96-001\tempDir-002\data\nodes\1\indices\xKokK_BuT-apELfAZW8bIQ\4\index\_0.cfs
17:00:40   1> 	at sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:79) ~[?:?]
17:00:40   1> 	at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97) ~[?:?]
17:00:40   1> 	at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:102) ~[?:?]
17:00:40   1> 	at sun.nio.fs.WindowsFileSystemProvider.newFileChannel(WindowsFileSystemProvider.java:115) ~[?:?]
17:00:40   1> 	at org.apache.lucene.mockfile.FilterFileSystemProvider.newFileChannel(FilterFileSystemProvider.java:202) ~[lucene-test-framework-7.4.0-snapshot-1ed95c097b.jar:7.4.0-snapshot-1ed95c097b 1ed95c097b82ee5f175e93f3fe62572abe064da6 - jimczi - 2018-05-03 16:16:16]
17:00:40   1> 	at org.apache.lucene.mockfile.DisableFsyncFS.newFileChannel(DisableFsyncFS.java:45) ~[lucene-test-framework-7.4.0-snapshot-1ed95c097b.jar:7.4.0-snapshot-1ed95c097b 1ed95c097b82ee5f175e93f3fe62572abe064da6 - jimczi - 2018-05-03 16:16:16]
17:00:40   1> 	at org.apache.lucene.mockfile.FilterFileSystemProvider.newFileChannel(FilterFileSystemProvider.java:202) ~[lucene-test-framework-7.4.0-snapshot-1ed95c097b.jar:7.4.0-snapshot-1ed95c097b 1ed95c097b82ee5f175e93f3fe62572abe064da6 - jimczi - 2018-05-03 16:16:16]
17:00:40   1> 	at org.apache.lucene.mockfile.HandleTrackingFS.newFileChannel(HandleTrackingFS.java:166) ~[lucene-test-framework-7.4.0-snapshot-1ed95c097b.jar:7.4.0-snapshot-1ed95c097b 1ed95c097b82ee5f175e93f3fe62572abe064da6 - jimczi - 2018-05-03 16:16:16]
17:00:40   1> 	at org.apache.lucene.mockfile.HandleTrackingFS.newFileChannel(HandleTrackingFS.java:166) ~[lucene-test-framework-7.4.0-snapshot-1ed95c097b.jar:7.4.0-snapshot-1ed95c097b 1ed95c097b82ee5f175e93f3fe62572abe064da6 - jimczi - 2018-05-03 16:16:16]
17:00:40   1> 	at java.nio.channels.FileChannel.open(FileChannel.java:287) ~[?:1.8.0_162]
17:00:40   1> 	at java.nio.channels.FileChannel.open(FileChannel.java:335) ~[?:1.8.0_162]
17:00:40   1> 	at org.apache.lucene.store.MMapDirectory.openInput(MMapDirectory.java:238) ~[lucene-core-7.4.0-snapshot-1ed95c097b.jar:7.4.0-snapshot-1ed95c097b 1ed95c097b82ee5f175e93f3fe62572abe064da6 - jimczi - 2018-05-03 16:16:13]
17:00:40   1> 	at org.apache.lucene.store.FilterDirectory.openInput(FilterDirectory.java:99) ~[lucene-core-7.4.0-snapshot-1ed95c097b.jar:7.4.0-snapshot-1ed95c097b 1ed95c097b82ee5f175e93f3fe62572abe064da6 - jimczi - 2018-05-03 16:16:13]
17:00:40   1> 	at org.elasticsearch.index.store.Store$MetadataSnapshot.checksumFromLuceneFile(Store.java:912) ~[main/:?]
17:00:40   1> 	at org.elasticsearch.index.store.Store$MetadataSnapshot.loadMetadata(Store.java:878) ~[main/:?]
17:00:40   1> 	at org.elasticsearch.index.store.Store$MetadataSnapshot.<init>(Store.java:797) ~[main/:?]
17:00:40   1> 	at org.elasticsearch.index.store.Store.getMetadata(Store.java:293) ~[main/:?]
17:00:40   1> 	at org.elasticsearch.index.store.Store.getMetadata(Store.java:258) ~[main/:?]
17:00:40   1> 	at org.elasticsearch.index.store.Store.cleanupAndVerify(Store.java:689) ~[main/:?]
17:00:40   1> 	at org.elasticsearch.indices.recovery.RecoveryTarget.cleanFiles(RecoveryTarget.java:440) [main/:?]
17:00:40   1> 	... 10 more

[elasticmachine]

Pinging @elastic/es-core-infra

[jdconrad]

Another (https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.x+multijob-windows-compatibility/1039/console) for 6.x this time.

[jdconrad]

Another (https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-windows-compatibility/1613/console)

[davidkyle]

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

gradlew :server:integTest \
  -Dtests.seed=9D3CC0E3B2497B08 \
  -Dtests.class=org.elasticsearch.action.admin.indices.create.SplitIndexIT \
  -Dtests.method="testSplitIndexPrimaryTerm" \
  -Dtests.security.manager=true \
  -Dtests.locale=ca \
  -Dtests.timezone=America/Kralendijk

But with different errors in the log file

  1> org.elasticsearch.indices.recovery.RecoveryFailedException: [target][6]: Recovery failed on {node_sd5}{UwGGEyGUT-iaqeKHzJBQew}{jkfgkAjwRTe6Y6bo1_B69w}{127.0.0.1}{127.0.0.1:58447}
  1> 	at org.elasticsearch.index.shard.IndexShard.lambda$startRecovery$8(IndexShard.java:2047) ~[main/:?]
  1> 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:625) [main/:?]
  1> 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_162]
  1> 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_162]
  1> 	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_162]
  1> Caused by: org.elasticsearch.index.shard.IndexShardRecoveryException: failed recovery
  1> 	at org.elasticsearch.index.shard.StoreRecovery.executeRecovery(StoreRecovery.java:343) ~[main/:?]
  1> 	at org.elasticsearch.index.shard.StoreRecovery.recoverFromLocalShards(StoreRecovery.java:123) ~[main/:?]
  1> 	at org.elasticsearch.index.shard.IndexShard.recoverFromLocalShards(IndexShard.java:1520) ~[main/:?]
  1> 	at org.elasticsearch.index.shard.IndexShard.lambda$startRecovery$8(IndexShard.java:2042) ~[main/:?]
  1> 	... 4 more
  1> Caused by: java.lang.IllegalArgumentException: Directory StatsDirectoryWrapper(HardlinkCopyDirectoryWrapper(store(ElasticsearchMockDirectoryWrapper(NIOFSDirectory@C:\Users\jenkins\workspace\elastic+elasticsearch+master+multijob-windows-compatibility\server\build\testrun\integTest\J1\temp\org.elasticsearch.action.admin.indices.create.SplitIndexIT_9D3CC0E3B2497B08-001\tempDir-002\data\nodes\5\indices\qIeJ_iYHRqeZf7hHC_U1jA\6\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@56824d1a)))) still has pending deleted files; cannot initialize IndexWriter
  1> 	at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:698) ~[lucene-core-7.4.0-snapshot-1ed95c097b.jar:7.4.0-snapshot-1ed95c097b 1ed95c097b82ee5f175e93f3fe62572abe064da6 - jimczi - 2018-05-03 16:16:13]
  1> 	at org.elasticsearch.index.shard.StoreRecovery.addIndices(StoreRecovery.java:169) ~[main/:?]
  1> 	at org.elasticsearch.index.shard.StoreRecovery.lambda$recoverFromLocalShards$3(StoreRecovery.java:131) ~[main/:?]
  1> 	at org.elasticsearch.index.shard.StoreRecovery.executeRecovery(StoreRecovery.java:301) ~[main/:?]
  1> 	at org.elasticsearch.index.shard.StoreRecovery.recoverFromLocalShards(StoreRecovery.java:123) ~[main/:?]
  1> 	at org.elasticsearch.index.shard.IndexShard.recoverFromLocalShards(IndexShard.java:1520) ~[main/:?]
  1> 	at org.elasticsearch.index.shard.IndexShard.lambda$startRecovery$8(IndexShard.java:2042) ~[main/:?]
  1> 	... 4 more
  1> [2018-05-08T09:10:38,856][WARN ][o.e.i.c.IndicesClusterStateService] [node_sd5] [[target][1]] marking and sending shard failed due to [failed recovery]