Underlying file changed by an external force

derekkl · October 13, 2020, 2:29pm

Using the latest “sonarqube” image, we are getting repeated messages and warnings about failing shards. Seeing the message Underlying file changed by an external force.

We are running inside of OpenShift 3.11. After an unexpected shutdown of the node this was running on, it failed to pass health and readiness checks and would begin crash looping. I took the health and readiness checks away so the container would stay running. Now we are seeing these types of errors in the logs. Is there a way to purge or clean the elasticsearch shards? I will add the log in a new note.

derekkl · October 13, 2020, 2:30pm

2020.10.05 17:31:14 ERROR web[][o.s.s.es.BulkIndexer] index [rules], type [rule], id [ar_AXT5vC_CU7z9XgkL8lh9], message [UnavailableShardsException[[rules][1] primary shard is not active Timeout: [1m], request: [BulkShardRequest [[rules][1]] containing [867] requests]]]
2020.10.05 17:31:14 ERROR web[][o.s.s.es.BulkIndexer] index [rules], type [rule], id [ar_AXT5vC_GU7z9XgkL8liO], message [UnavailableShardsException[[rules][1] primary shard is not active Timeout: [1m], request: [BulkShardRequest [[rules][1]] containing [867] requests]]]
2020.10.05 17:31:14 ERROR web[][o.s.s.es.BulkIndexer] index [rules], type [rule], id [ar_AXT5vC_GU7z9XgkL8liP], message [UnavailableShardsException[[rules][0] primary shard is not active Timeout: [1m], request: [BulkShardRequest [[rules][0]] containing [826] requests]]]
2020.10.05 17:31:14 ERROR web[][o.s.s.es.BulkIndexer] index [rules], type [rule], id [ar_AXT5vC_GU7z9XgkL8liQ], message [UnavailableShardsException[[rules][1] primary shard is not active Timeout: [1m], request: [BulkShardRequest [[rules][1]] containing [867] requests]]]
2020.10.05 17:31:14 ERROR web[][o.s.s.es.BulkIndexer] index [rules], type [rule], id [ar_AXT5vC_IU7z9XgkL8liY], message [UnavailableShardsException[[rules][0] primary shard is not active Timeout: [1m], request: [BulkShardRequest [[rules][0]] containing [826] requests]]]
2020.10.05 17:31:14 ERROR web[][o.s.s.es.BulkIndexer] index [rules], type [rule], id [ar_AXT5vC_JU7z9XgkL8liZ], message [UnavailableShardsException[[rules][0] primary shard is not active Timeout: [1m], request: [BulkShardRequest [[rules][0]] containing [826] requests]]]
2020.10.05 17:31:14 ERROR web[][o.s.s.es.BulkIndexer] index [rules], type [rule], id [ar_AXT5vC_JU7z9XgkL8lia], message [UnavailableShardsException[[rules][0] primary shard is not active Timeout: [1m], request: [BulkShardRequest [[rules][0]] containing [826] requests]]]
2020.10.05 17:31:14 ERROR web[][o.s.s.es.BulkIndexer] index [rules], type [rule], id [ar_AXT5vC_JU7z9XgkL8lib], message [UnavailableShardsException[[rules][1] primary shard is not active Timeout: [1m], request: [BulkShardRequest [[rules][1]] containing [867] requests]]]
2020.10.05 17:31:14 ERROR web[][o.s.s.es.BulkIndexer] index [rules], type [rule], id [ar_AXT5vC_JU7z9XgkL8lic], message [UnavailableShardsException[[rules][0] primary shard is not active Timeout: [1m], request: [BulkShardRequest [[rules][0]] containing [826] requests]]]
2020.10.05 17:31:14 ERROR web[][o.s.s.es.BulkIndexer] index [rules], type [rule], id [ar_AXT5vC_JU7z9XgkL8lid], message [UnavailableShardsException[[rules][1] primary shard is not active Timeout: [1m], request: [BulkShardRequest [[rules][1]] containing [867] requests]]]
2020.10.05 17:31:14 ERROR web[][o.s.s.es.BulkIndexer] index [rules], type [rule], id [ar_AXT5vC_MU7z9XgkL8lil], message [UnavailableShardsException[[rules][1] primary shard is not active Timeout: [1m], request: [BulkShardRequest [[rules][1]] containing [867] requests]]]
2020.10.05 17:31:14 ERROR web[][o.s.s.es.BulkIndexer] index [rules], type [rule], id [ar_AXT5vC_MU7z9XgkL8lim], message [UnavailableShardsException[[rules][1] primary shard is not active Timeout: [1m], request: [BulkShardRequest [[rules][1]] containing [867] requests]]]
2020.10.05 17:31:14 ERROR web[][o.s.s.es.BulkIndexer] index [rules], type [rule], id [ar_AXT5vC_MU7z9XgkL8lio], message [UnavailableShardsException[[rules][1] primary shard is not active Timeout: [1m], request: [BulkShardRequest [[rules][1]] containing [867] requests]]]
2020.10.05 17:31:14 ERROR web[][o.s.s.es.BulkIndexer] index [rules], type [rule], id [ar_AXT5vC_QU7z9XgkL8li2], message [UnavailableShardsException[[rules][1] primary shard is not active Timeout: [1m], request: [BulkShardRequest [[rules][1]] containing [867] requests]]]
2020.10.05 17:31:14 ERROR web[][o.s.s.es.BulkIndexer] index [rules], type [rule], id [ar_AXT5vC_QU7z9XgkL8li3], message [UnavailableShardsException[[rules][0] primary shard is not active Timeout: [1m], request: [BulkShardRequest [[rules][0]] containing [826] requests]]]
2020.10.05 17:31:14 ERROR web[][o.s.s.es.BulkIndexer] index [rules], type [rule], id [ar_AXT5vC_QU7z9XgkL8li4], message [UnavailableShardsException[[rules][0] primary shard is not active Timeout: [1m], request: [BulkShardRequest [[rules][0]] containing [826] requests]]]
2020.10.05 17:31:14 ERROR web[][o.s.s.es.BulkIndexer] index [rules], type [rule], id [ar_AXT5vC_QU7z9XgkL8li5], message [UnavailableShardsException[[rules][0] primary shard is not active Timeout: [1m], request: [BulkShardRequest [[rules][0]] containing [826] requests]]]
2020.10.05 17:32:14 ERROR web[][o.s.s.e.RecoveryIndexer] Elasticsearch recovery - too many failures [1693/1693 documents], waiting for next run
2020.10.05 17:32:14 INFO  web[][o.s.s.e.RecoveryIndexer] Elasticsearch recovery - 1693 documents processed [1693 failures] | time=120280ms
2020.10.05 17:34:33 DEBUG es[][o.e.i.s.IndexShard] shard is now inactive
2020.10.05 17:34:33 DEBUG es[][o.e.i.t.Translog] translog closed
2020.10.05 17:34:33 DEBUG es[][o.e.i.e.Engine] engine closed [engine failed on: [lucene commit failed]]
2020.10.05 17:34:33 WARN  es[][o.e.i.e.Engine] failed engine [lucene commit failed]
org.apache.lucene.store.AlreadyClosedException: Underlying file changed by an external force at 2020-10-05T16:34:44.159322Z, (lock=NativeFSLock(path=/opt/sonarqube/data/es6/nodes/0/indices/LorsKfR6QdW-8CsIokljBQ/0/index/write.lock,impl=sun.nio.ch.FileLockImpl[0:9223372036854775807 exclusive valid],creationTime=2020-10-05T16:34:44.157752Z))
	at org.apache.lucene.store.NativeFSLockFactory$NativeFSLock.ensureValid(NativeFSLockFactory.java:191) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
	at org.apache.lucene.store.LockValidatingDirectoryWrapper.syncMetaData(LockValidatingDirectoryWrapper.java:61) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
	at org.apache.lucene.index.SegmentInfos.prepareCommit(SegmentInfos.java:771) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
	at org.apache.lucene.index.IndexWriter.startCommit(IndexWriter.java:4809) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
	at org.apache.lucene.index.IndexWriter.prepareCommitInternal(IndexWriter.java:3297) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
	at org.apache.lucene.index.IndexWriter.commitInternal(IndexWriter.java:3465) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
	at org.apache.lucene.index.IndexWriter.commit(IndexWriter.java:3430) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
	at org.elasticsearch.index.engine.InternalEngine.commitIndexWriter(InternalEngine.java:2465) [elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.index.engine.InternalEngine.syncFlush(InternalEngine.java:1718) [elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.index.shard.IndexShard.syncFlush(IndexShard.java:1090) [elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.indices.flush.SyncedFlushService.performSyncedFlush(SyncedFlushService.java:519) [elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.indices.flush.SyncedFlushService.access$600(SyncedFlushService.java:74) [elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.indices.flush.SyncedFlushService$SyncedFlushTransportHandler.messageReceived(SyncedFlushService.java:825) [elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.indices.flush.SyncedFlushService$SyncedFlushTransportHandler.messageReceived(SyncedFlushService.java:821) [elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.transport.TransportRequestHandler.messageReceived(TransportRequestHandler.java:30) [elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:66) [elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.transport.TransportService$7.doRun(TransportService.java:692) [elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:751) [elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [elasticsearch-6.8.4.jar:6.8.4]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:?]
	at java.lang.Thread.run(Unknown Source) [?:?]
2020.10.05 17:34:33 DEBUG es[][o.e.i.IndexService] [0] closing... (reason: [shard failure, reason [lucene commit failed]])
2020.10.05 17:34:33 DEBUG es[][o.e.i.s.IndexShard] state: [STARTED]->[CLOSED], reason [shard failure, reason [lucene commit failed]]
2020.10.05 17:34:33 DEBUG es[][o.e.i.s.Store] store reference count on close: 0
2020.10.05 17:34:33 DEBUG es[][o.e.i.IndexService] [0] closed (reason: [shard failure, reason [lucene commit failed]])
2020.10.05 17:34:33 WARN  es[][o.e.i.c.IndicesClusterStateService] [[users][0]] marking and sending shard failed due to [shard failure, reason [lucene commit failed]]
org.apache.lucene.store.AlreadyClosedException: Underlying file changed by an external force at 2020-10-05T16:34:44.159322Z, (lock=NativeFSLock(path=/opt/sonarqube/data/es6/nodes/0/indices/LorsKfR6QdW-8CsIokljBQ/0/index/write.lock,impl=sun.nio.ch.FileLockImpl[0:9223372036854775807 exclusive valid],creationTime=2020-10-05T16:34:44.157752Z))
	at org.apache.lucene.store.NativeFSLockFactory$NativeFSLock.ensureValid(NativeFSLockFactory.java:191) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
	at org.apache.lucene.store.LockValidatingDirectoryWrapper.syncMetaData(LockValidatingDirectoryWrapper.java:61) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
	at org.apache.lucene.index.SegmentInfos.prepareCommit(SegmentInfos.java:771) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
	at org.apache.lucene.index.IndexWriter.startCommit(IndexWriter.java:4809) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
	at org.apache.lucene.index.IndexWriter.prepareCommitInternal(IndexWriter.java:3297) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
	at org.apache.lucene.index.IndexWriter.commitInternal(IndexWriter.java:3465) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
	at org.apache.lucene.index.IndexWriter.commit(IndexWriter.java:3430) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
	at org.elasticsearch.index.engine.InternalEngine.commitIndexWriter(InternalEngine.java:2465) ~[elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.index.engine.InternalEngine.syncFlush(InternalEngine.java:1718) ~[elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.index.shard.IndexShard.syncFlush(IndexShard.java:1090) ~[elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.indices.flush.SyncedFlushService.performSyncedFlush(SyncedFlushService.java:519) ~[elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.indices.flush.SyncedFlushService.access$600(SyncedFlushService.java:74) ~[elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.indices.flush.SyncedFlushService$SyncedFlushTransportHandler.messageReceived(SyncedFlushService.java:825) ~[elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.indices.flush.SyncedFlushService$SyncedFlushTransportHandler.messageReceived(SyncedFlushService.java:821) ~[elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.transport.TransportRequestHandler.messageReceived(TransportRequestHandler.java:30) ~[elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:66) ~[elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.transport.TransportService$7.doRun(TransportService.java:692) ~[elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:751) ~[elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) ~[elasticsearch-6.8.4.jar:6.8.4]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:?]
	at java.lang.Thread.run(Unknown Source) [?:?]
2020.10.05 17:34:33 DEBUG es[][o.e.c.a.s.ShardStateAction] sending [internal:cluster/shard/failure] to [okUjIqHZS3iOjIacg-XCfA] for shard entry [shard id [[users][0]], allocation id [uj_GsY8ATLG6tWyuGdy8Eg], primary term [0], message [shard failure, reason [lucene commit failed]], failure [AlreadyClosedException[Underlying file changed by an external force at 2020-10-05T16:34:44.159322Z, (lock=NativeFSLock(path=/opt/sonarqube/data/es6/nodes/0/indices/LorsKfR6QdW-8CsIokljBQ/0/index/write.lock,impl=sun.nio.ch.FileLockImpl[0:9223372036854775807 exclusive valid],creationTime=2020-10-05T16:34:44.157752Z))]], markAsStale [true]]
2020.10.05 17:34:33 DEBUG es[][o.e.c.a.s.ShardStateAction] [users][0] received shard failed for shard id [[users][0]], allocation id [uj_GsY8ATLG6tWyuGdy8Eg], primary term [0], message [shard failure, reason [lucene commit failed]], failure [AlreadyClosedException[Underlying file changed by an external force at 2020-10-05T16:34:44.159322Z, (lock=NativeFSLock(path=/opt/sonarqube/data/es6/nodes/0/indices/LorsKfR6QdW-8CsIokljBQ/0/index/write.lock,impl=sun.nio.ch.FileLockImpl[0:9223372036854775807 exclusive valid],creationTime=2020-10-05T16:34:44.157752Z))]], markAsStale [true]
org.apache.lucene.store.AlreadyClosedException: Underlying file changed by an external force at 2020-10-05T16:34:44.159322Z, (lock=NativeFSLock(path=/opt/sonarqube/data/es6/nodes/0/indices/LorsKfR6QdW-8CsIokljBQ/0/index/write.lock,impl=sun.nio.ch.FileLockImpl[0:9223372036854775807 exclusive valid],creationTime=2020-10-05T16:34:44.157752Z))
	at org.apache.lucene.store.NativeFSLockFactory$NativeFSLock.ensureValid(NativeFSLockFactory.java:191) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
	at org.apache.lucene.store.LockValidatingDirectoryWrapper.syncMetaData(LockValidatingDirectoryWrapper.java:61) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
	at org.apache.lucene.index.SegmentInfos.prepareCommit(SegmentInfos.java:771) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
	at org.apache.lucene.index.IndexWriter.startCommit(IndexWriter.java:4809) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
	at org.apache.lucene.index.IndexWriter.prepareCommitInternal(IndexWriter.java:3297) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
	at org.apache.lucene.index.IndexWriter.commitInternal(IndexWriter.java:3465) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
	at org.apache.lucene.index.IndexWriter.commit(IndexWriter.java:3430) ~[lucene-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:30:25]
	at org.elasticsearch.index.engine.InternalEngine.commitIndexWriter(InternalEngine.java:2465) ~[elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.index.engine.InternalEngine.syncFlush(InternalEngine.java:1718) ~[elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.index.shard.IndexShard.syncFlush(IndexShard.java:1090) ~[elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.indices.flush.SyncedFlushService.performSyncedFlush(SyncedFlushService.java:519) ~[elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.indices.flush.SyncedFlushService.access$600(SyncedFlushService.java:74) ~[elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.indices.flush.SyncedFlushService$SyncedFlushTransportHandler.messageReceived(SyncedFlushService.java:825) ~[elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.indices.flush.SyncedFlushService$SyncedFlushTransportHandler.messageReceived(SyncedFlushService.java:821) ~[elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.transport.TransportRequestHandler.messageReceived(TransportRequestHandler.java:30) ~[elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:66) ~[elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.transport.TransportService$7.doRun(TransportService.java:692) ~[elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:751) ~[elasticsearch-6.8.4.jar:6.8.4]
	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) ~[elasticsearch-6.8.4.jar:6.8.4]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:?]
	at java.lang.Thread.run(Unknown Source) [?:?]

Colin · October 13, 2020, 4:43pm

Trashing /opt/sonarqube/data/es6 and restarting is probably your safest bet!

derekkl · October 15, 2020, 1:02pm

The did the trick. Can you tell me what that elasticsearch storage is being used for? Thanks, Colin!

system · October 22, 2020, 1:02pm

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.