Enhance BufferedChecksumIndexInput error when a state file is empty

[gmoskovicz]

Elasticsearch version (bin/elasticsearch --version): Any version

Plugins installed: [none]

JVM version (java -version): 1.8

OS version (uname -a if on a Unix-like system): Any

Provide logs (if relevant):

If a state file is empty after some issue (hardware issue, NFS issue and others) a node will fail to start and we will see something like the following in the logs:

[2018-04-03T18:12:25,227][ERROR][o.e.g.GatewayMetaState   ] [xxxx] failed to read local state, exiting...
org.elasticsearch.ElasticsearchException: java.io.IOException: failed to read [id:20, legacy:false, file:/xxx/elasticsearch/xxx/xxx/nodes/0/indices/indexname/_state/state-20.st]
	at org.elasticsearch.ExceptionsHelper.maybeThrowRuntimeAndSuppress(ExceptionsHelper.java:150) ~[elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.gateway.MetaDataStateFormat.loadLatestState(MetaDataStateFormat.java:334) ~[elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.common.util.IndexFolderUpgrader.upgrade(IndexFolderUpgrader.java:90) ~[elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.common.util.IndexFolderUpgrader.upgradeIndicesIfNeeded(IndexFolderUpgrader.java:128) ~[elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.gateway.GatewayMetaState.<init>(GatewayMetaState.java:87) [elasticsearch-5.4.3.jar:5.4.3]
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[?:?]
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) [?:1.8.0_161]
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [?:1.8.0_161]
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423) [?:1.8.0_161]
	at org.elasticsearch.common.inject.DefaultConstructionProxyFactory$1.newInstance(DefaultConstructionProxyFactory.java:49) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.common.inject.ConstructorInjector.construct(ConstructorInjector.java:86) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.common.inject.ConstructorBindingImpl$Factory.get(ConstructorBindingImpl.java:116) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.common.inject.ProviderToInternalFactoryAdapter$1.call(ProviderToInternalFactoryAdapter.java:47) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.common.inject.InjectorImpl.callInContext(InjectorImpl.java:825) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.common.inject.ProviderToInternalFactoryAdapter.get(ProviderToInternalFactoryAdapter.java:43) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.common.inject.Scopes$1$1.get(Scopes.java:59) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.common.inject.InternalFactoryToProviderAdapter.get(InternalFactoryToProviderAdapter.java:50) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.common.inject.InjectorBuilder$1.call(InjectorBuilder.java:191) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.common.inject.InjectorBuilder$1.call(InjectorBuilder.java:183) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.common.inject.InjectorImpl.callInContext(InjectorImpl.java:818) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.common.inject.InjectorBuilder.loadEagerSingletons(InjectorBuilder.java:183) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.common.inject.InjectorBuilder.loadEagerSingletons(InjectorBuilder.java:176) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.common.inject.InjectorBuilder.injectDynamically(InjectorBuilder.java:161) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.common.inject.InjectorBuilder.build(InjectorBuilder.java:96) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.common.inject.Guice.createInjector(Guice.java:96) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.common.inject.Guice.createInjector(Guice.java:70) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.common.inject.ModulesBuilder.createInjector(ModulesBuilder.java:43) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.node.Node.<init>(Node.java:491) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.node.Node.<init>(Node.java:242) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.bootstrap.Bootstrap$5.<init>(Bootstrap.java:232) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.bootstrap.Bootstrap.setup(Bootstrap.java:232) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.bootstrap.Bootstrap.init(Bootstrap.java:350) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.bootstrap.Elasticsearch.init(Elasticsearch.java:123) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.bootstrap.Elasticsearch.execute(Elasticsearch.java:114) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.cli.EnvironmentAwareCommand.execute(EnvironmentAwareCommand.java:67) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.cli.Command.mainWithoutErrorHandling(Command.java:122) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.cli.Command.main(Command.java:88) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.bootstrap.Elasticsearch.main(Elasticsearch.java:91) [elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.bootstrap.Elasticsearch.main(Elasticsearch.java:84) [elasticsearch-5.4.3.jar:5.4.3]
Caused by: java.io.IOException: failed to read [id:20, legacy:false, file:/xxx/elasticsearch/xxx/xxx/nodes/0/indices/indexname/_state/state-20.st]
	at org.elasticsearch.gateway.MetaDataStateFormat.loadLatestState(MetaDataStateFormat.java:327) ~[elasticsearch-5.4.3.jar:5.4.3]
	... 37 more
Caused by: java.lang.IllegalStateException: class org.apache.lucene.store.BufferedChecksumIndexInput cannot seek backwards (pos=-16 getFilePointer()=0)
	at org.apache.lucene.store.ChecksumIndexInput.seek(ChecksumIndexInput.java:50) ~[lucene-core-6.5.1.jar:6.5.1 cd1f23c63abe03ae650c75ec8ccb37762806cc75 - jimczi - 2017-04-21 12:17:15]
	at org.apache.lucene.codecs.CodecUtil.checksumEntireFile(CodecUtil.java:519) ~[lucene-core-6.5.1.jar:6.5.1 cd1f23c63abe03ae650c75ec8ccb37762806cc75 - jimczi - 2017-04-21 12:17:15]
	at org.elasticsearch.gateway.MetaDataStateFormat.read(MetaDataStateFormat.java:189) ~[elasticsearch-5.4.3.jar:5.4.3]
	at org.elasticsearch.gateway.MetaDataStateFormat.loadLatestState(MetaDataStateFormat.java:322) ~[elasticsearch-5.4.3.jar:5.4.3]
	... 37 more

Discussing it with @jpountz , (pos=-16 getFilePointer()=0) seems to indicate that the file is empty, but so far we return a IOException without explaining that a state file is empty.

So my question here is:

1. Does it make sense to add some extra content to the log to explicitly mention that the file is empty?
2. Perhaps we can mention in the logs that when this happens the shards get corrupted and you need to recreate it (or remove it)?
3. Do we see any other option than [2]? For example starting the node and have an option to disregard that shard (possibly delete it?- yes doesn't sounds like a very good idea, but worth discussing it).

[elasticmachine]

Pinging @elastic/es-core-infra

[jpountz]

I wonder that this might have improved thanks to LUCENE-7831, which is in Elasticsearch 5.6+ and 6.0+. This issue improved the error message (it would contain misplaced codec footer (file truncated?): length=0 but footerLength==16 now) but more importantly, made it a CorruptIndexException rather than an IllegalStateException. I believe this would make Elasticsearch fail the shard, wouldn't it?

[ywelsch]

@jpountz This is on startup where we read the index metadata (to possibly upgrade the index metadata). While a CorruptIndexException will better convey the issue, the overall behavior will still be the same (the node failing to start up). This is a good thing IMO, as it makes the user aware of file-system corruption. Ignoring this (while logging a warning) would be dangerous, as it could mean that the index just magically disappears from the cluster after a restart.

Does it make sense to add some extra content to the log to explicitly mention that the file is empty?

How will this help? Are we taking different actions based on whether the file is empty or corrupted otherwise?

Perhaps we can mention in the logs that when this happens the shards get corrupted and you need to recreate it (or remove it)?

In the above message it was not the shard that got corrupted, but the index metadata. If that index metadata is not available on any other node, the whole index will effectively be gone. I'm not sure what kind of generic recommendation we could give there. It's probably more on a case-by-case basis (restore from snapshot, reindex from primary source, ...).

Do we see any other option than [2]? For example starting the node and have an option to disregard that shard (possibly delete it?- yes doesn't sounds like a very good idea, but worth discussing it).

File system corruptions are serious, and the system should not try to automatically compensate for them, as this will hurt users even more further down the line.

[jpountz]

@ywelsch Thanks for clarifying! I see we are already doing the right thing at write time by writing to a temp file before renaming, so if I read you correctly there is nothing more to do since the error message was already improved via LUCENE-7831?

[ywelsch]

@jpountz yes, maybe worth adding a test case in ES?

[jpountz]

OK, making it a test adoptme.

[jasontedor]

@ywelsch Sorry, what is the test? That the exception message is that which comes from upstream? And the test breaks if upstream changes the message and we merely change the assertion? I am not following what the proposal is here.

[ywelsch]

@jasontedor That MetaDataStateFormat.read() throws a CorruptStateException if the file is truncated in any way (in particular as well when it is 0 bytes). We test this already in MetaDataStateFormatTests.testLoadState but the method that does the corruption (corruptFile) does not seem to generate a 0 length file as corruption possibility.

[DaveCTurner]

FAO @andrershov