Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Shard initialization fails with DocValues exception #8009

Closed
egueidan opened this issue Oct 7, 2014 · 21 comments
Closed

Shard initialization fails with DocValues exception #8009

egueidan opened this issue Oct 7, 2014 · 21 comments
Assignees

Comments

@egueidan
Copy link

egueidan commented Oct 7, 2014

Hi,

we have been running into strange errors lately. We get a lot of exceptions of the type:

[2014-10-07 06:41:26,235][WARN ][cluster.action.shard     ] [Madcap] [my_index][1] sending failed shard for [my_index][1], node[-QGTVk8RRcuKuBwdqD8l1A], [P], s[INITIALIZING], indexUUID [u68VqfHsRii16gYXtPj1cQ], reason [Failed to start shard, message [IndexShardGatewayRecoveryException[[my_index][1] failed recovery]; nested: IllegalArgumentException[cannot change DocValues type from BINARY to SORTED_SET for field "custom.my_field"]; ]]
[2014-10-07 06:41:26,587][WARN ][indices.cluster          ] [Madcap] [my_index][1] failed to start shard
org.elasticsearch.index.gateway.IndexShardGatewayRecoveryException: [my_index][1] failed recovery
  at org.elasticsearch.index.gateway.IndexShardGatewayService$1.run(IndexShardGatewayService.java:185)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
  at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.IllegalArgumentException: cannot change DocValues type from BINARY to SORTED_SET for field "custom.my_field"
  at org.apache.lucene.index.FieldInfos$FieldNumbers.addOrGet(FieldInfos.java:198)
  at org.apache.lucene.index.IndexWriter.getFieldNumberMap(IndexWriter.java:868)
  at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:819)
  at org.elasticsearch.index.engine.internal.InternalEngine.createWriter(InternalEngine.java:1420)
  at org.elasticsearch.index.engine.internal.InternalEngine.start(InternalEngine.java:271)
  at org.elasticsearch.index.shard.service.InternalIndexShard.postRecovery(InternalIndexShard.java:692)
  at org.elasticsearch.index.gateway.local.LocalIndexShardGateway.recover(LocalIndexShardGateway.java:217)
  at org.elasticsearch.index.gateway.IndexShardGatewayService$1.run(IndexShardGatewayService.java:132)
  ... 3 more

We are in a daily index situation so the index is quite new. It contains 10 to 20 millions of documents spread over 10 shards and 5 nodes. At some point (after hours of the index being green), one of the shards becomes INITALIZING and can never start (because of the aforementioned exception). The index is then in red state and we cannot set it back on track... In this case the only solution we have found is to scroll over the whole index and reindex the data into a new index (but we most likely have lost the data from the failing shard). The field that causes the issue has the following definition {"type":"long","doc_values":true,"include_in_all":false}. This mapping is inferred from a dynamic template {"mapping":{"index":"not_analyzed","include_in_all":false,"doc_values":true,"type":"{dynamic_type}"},"match":"*"}.
One important note is that this part of the data is free-form (ie user input) and it is possible that some documents have conflicting types (one document having the field as string, the other as long); that's why the index has the setting index.mapping.ignore_malformed set to true.
Also, it might not be relevant, but this only happened on days when we had at least one node that was restarted.
We have noticed this issue since running ElasticSearch 1.3.4 (but can't be 100% sure that it did not happen before).

We cannot isolate and reproduce the issue but have faced it several times over the past few days. Feel free to suggest actions we can undertake should it happen again, to get more details to help fix it. Also, if you have suggestions to help bypass the issue when it happens (so that we can avoid reindexing the data), that'd be great.

Thanks,
Emmanuel

@jpountz
Copy link
Contributor

jpountz commented Oct 7, 2014

@egueidan Thanks for reporting this issue.

One important note is that this part of the data is free-form (ie user input) and it is possible that some documents have conflicting types (one document having the field as string, the other as long); that's why the index has the setting index.mapping.ignore_malformed set to true.

This could indeed be the cause of the issue. Can you please provide us with all the mappings that you have on the my_index index?

@jpountz jpountz self-assigned this Oct 7, 2014
@egueidan
Copy link
Author

egueidan commented Oct 7, 2014

Hi @jpountz,

thanks for looking into this. Sadly I'm not at liberty to share the full mapping here as it contains sensitive data... Here is a dummied down and anonymized version which I hope will help you get going.

{
  "my_index": {
    "mappings": {
      "my_type": {
        "dynamic_templates": [
          {
            "custom_message": {
              "mapping": {
                "include_in_all": true,
                "analyzer": "simple",
                "type": "string"
              },
              "path_match": "custom.message"
            }
          },
          {
            "subpart_bytes": {
              "mapping": {
                "index": "not_analyzed",
                "include_in_all": false,
                "doc_values": true,
                "type": "byte"
              },
              "match_pattern": "regex",
              "path_match": "subpart\\.(fieldbyte1|fieldbyte2)"
            }
          },
          {
            "subpart_short": {
              "mapping": {
                "index": "not_analyzed",
                "include_in_all": false,
                "doc_values": true,
                "type": "short"
              },
              "match_pattern": "regex",
              "path_match": "subpart\\.(fieldshort1|fieldshort2)"
            }
          },
          {
            "dyn_fields": {
              "mapping": {
                "index": "not_analyzed",
                "include_in_all": false,
                "doc_values": true,
                "type": "{dynamic_type}"
              },
              "match": "*"
            }
          }
        ],
        "properties": {
          "custom": {
            "include_in_all": false,
            "properties": {
              ... many many fields (hundreds), of all types, all inferred from the dyn_fields template ...
              "my_field": {
                "type": "long",
                "doc_values": true,
                "include_in_all": false
              }
            }
          },
          "basic": {
            "properties": {
              "date": {
                "type": "date",
                "doc_values": true,
                "format": "dateOptionalTime",
                "include_in_all": false
              }
            }
          },
          "message": {
            "type": "string",
            "analyzer": "simple",
            "include_in_all": true
          },
          "subpart": {
            "include_in_all": false,
            "properties": {
              ... a few fields (<10) like 'other' inferred via dyn_field as well ...
              "other": {
                "type": "string",
                "index": "not_analyzed",
                "doc_values": true,
                "include_in_all": false
              },
              ... the subpart_bytes and subpart_short inferred fields ...
              "fieldbyte1": {
                "type": "byte",
                "doc_values": true,
                "include_in_all": false
              },
              "fieldshort1": {
                "type": "short",
                "doc_values": true,
                "include_in_all": false
              },
              "fieldbyte2": {
                "type": "byte",
                "doc_values": true,
                "include_in_all": false
              },
              "fieldshort2": {
                "type": "short",
                "doc_values": true,
                "include_in_all": false
              }
            }
          }
        }
      }
    }
  }
}

Cheers,
Emmanuel

@jpountz
Copy link
Contributor

jpountz commented Oct 7, 2014

The thing I was looking for in your mappings is whether you have two types on the same index that have the custom.my_field field with doc values, but once as a string and once as a numeric? If it is the case, there is not much that can be done, I have plans to improve the situation in the future by failing mapping updates that introduce incompatible types, but that would only help discover the problem earlier, not solve it. The fix would be to index into several indices instead of several types, or to ensure at a higher level that two different types cannot get incompatible mappings (eg. by prefixing field names by the type name).

@jpountz
Copy link
Contributor

jpountz commented Oct 7, 2014

Another question: do you know on which elasticsearch version the problematic index has been created?

@egueidan
Copy link
Author

egueidan commented Oct 7, 2014

Concerning your first question, no, we only have one type on those indices.
Concerning your second question, this happened on indices created with 1.3.2 and indices created with 1.3.4.
We have many indices but it only happened on the largest indices (> 10 million docs) with active indexing (40/50k docs/min).

@s1monw
Copy link
Contributor

s1monw commented Oct 8, 2014

would it be possilbe to get the segments_N and *.si files from this index / shard? Are you 100% sure you are not running any 1.4.0.Beta1 nodes or you downgraded somehow?

@egueidan
Copy link
Author

egueidan commented Oct 8, 2014

Sorry but the index is gone now but I'll get the files if we run into the issue again. All the nodes are running 1.3.4 (build_hash a70f3cc) and we haven't started testing 1.4.0.Beta1 (yet!).
If my memory serves me correctly the first time it happened was when I upgraded from 1.3.2 to 1.3.4 (ie rolling restart). Then when I added a new machine to the cluster (from 4 to 5). The last time one of our nodes went rogue (cluster was split 4/1 and we restarted the node). That's why I mentioned it only happened after some node (re)start (ie some recovery/relocation happened). Bare in mind we use daily indices and the issue only happened on the current day index - which is the only one receiving index requests. Also we recreate the indices from scratch (reindexing everything) when the issue happens, so this never happened on an index more than a few hours old.

@egueidan
Copy link
Author

egueidan commented Oct 8, 2014

Guys, as I was writing my last comment we had to restart one of our nodes... Immediately after we have started seing this exception again. At the moment, the cluster is green but we have lots of exceptions at indexation:

java.lang.IllegalArgumentException: cannot change DocValues type from SORTED_SET to BINARY for field "custom.xxxxxxxxxx"
  at org.apache.lucene.index.FieldInfos$FieldNumbers.addOrGet(FieldInfos.java:198)
  at org.apache.lucene.index.FieldInfos$Builder.addOrUpdateInternal(FieldInfos.java:304)
  at org.apache.lucene.index.FieldInfos$Builder.addOrUpdate(FieldInfos.java:289)
  at org.apache.lucene.index.DefaultIndexingChain.getOrAddField(DefaultIndexingChain.java:484)
  at org.apache.lucene.index.DefaultIndexingChain.processField(DefaultIndexingChain.java:373)
  at org.apache.lucene.index.DefaultIndexingChain.processDocument(DefaultIndexingChain.java:301)
  at org.apache.lucene.index.DocumentsWriterPerThread.updateDocument(DocumentsWriterPerThread.java:241)
  at org.apache.lucene.index.DocumentsWriter.updateDocument(DocumentsWriter.java:451)
  at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1539)
  at org.elasticsearch.index.engine.internal.InternalEngine.innerIndex(InternalEngine.java:572)
  at org.elasticsearch.index.engine.internal.InternalEngine.index(InternalEngine.java:492)
  at org.elasticsearch.index.shard.service.InternalIndexShard.index(InternalIndexShard.java:409)
  at org.elasticsearch.action.bulk.TransportShardBulkAction.shardIndexOperation(TransportShardBulkAction.java:446)
  at org.elasticsearch.action.bulk.TransportShardBulkAction.shardOperationOnPrimary(TransportShardBulkAction.java:157)
  at org.elasticsearch.action.support.replication.TransportShardReplicationOperationAction$AsyncShardOperationAction.performOnPrimary(TransportShardReplicationOperationAction.java:535)
  at org.elasticsearch.action.support.replication.TransportShardReplicationOperationAction$AsyncShardOperationAction$1.run(TransportShardReplicationOperationAction.java:434)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
  at java.lang.Thread.run(Thread.java:745)

This happens for example on a field which has been discovered as double in the mapping yet we try to index a document with "Infinity" as value for that field.

I have the segment* and *.si files from the shard/node reporting the exception, but for privacy reasons, I can't attach them on github. What would be the best way to share them privately with you?

@s1monw
Copy link
Contributor

s1monw commented Oct 8, 2014

This is actually a different exception. Your first exception (the original you opened the issue with) happens during IndexWriter creation so there somehow is a conflicting segment on that node and it might be related to problems that we fixed in 1.3.4 where due to hash collisions on recovery we didn't transfer alll the files needed.

Yet, lemme ask a couple of more questions to get closer to the source of the problem.

  • do I understand your correctly that this problem occurred after recovery to the node that was taken out of the cluster and later rejoined?
  • where there nodes with version 1.3.2 in the cluster while this node joined
  • do you still know if you recovered from a node of version 1.3.2 or from a newer node?
  • the node that failed with the first exception did it run 1.3.4 or 1.3.2?

This second failure is due to the fact that you are trying to index the same field as string while it's a double which obviously doesn't work. Are you using dynamic mappings for this?

@jpountz jpountz assigned s1monw and unassigned jpountz Oct 8, 2014
@egueidan
Copy link
Author

egueidan commented Oct 8, 2014

Yes, sorry, it is indeed a different exception. I mentioned it because it never happened before the restart of the machine this morning, although I know for a fact that there were similar messages (with string instead of a double) being inserted. Note that we are using index.mapping.ignore_malformed: true and the field mappings are discovered via dynamic templating.

I had a gut feeling it could be related and funny thing is right now the index with those exceptions is yellow with one replica shard perpetually initializing with many exceptions like:

[2014-10-08 15:37:40,085][WARN ][cluster.action.shard     ] [Fafnir] [index_xxxxx][6] received shard failed for [index_xxxxx][6], node[pwGu7LZWQ5e1mHjmiWyeVw], [R], s[INITIALIZING], indexUUID [LZGZL-kKS66nVPU7pFRCtA], reason [Failed to start shard, message [RecoveryFailedException[[index_xxxxx][6]: Recovery failed from [Rocket Racer][PdxQHUbMSY2h7co9Zg0xUw][server-4][inet[/10.0.0.16:9300]] into [Squirrel Girl][pwGu7LZWQ5e1mHjmiWyeVw][server-1][inet[/10.0.0.13:9300]]]; nested: RemoteTransportException[[Rocket Racer][inet[/10.0.0.16:9300]][index/shard/recovery/startRecovery]]; nested: RecoveryEngineException[[index_xxxxx][6] Phase[2] Execution failed]; nested: RemoteTransportException[[Squirrel Girl][inet[/10.0.0.13:9300]][index/shard/recovery/prepareTranslog]]; nested: IllegalArgumentException[cannot change DocValues type from BINARY to SORTED_SET for field "custom.field_xxx"]; ]]

To answer your questions this happens on a fully 1.3.4 cluster. The index was created on 1.3.4. There is no 1.3.2 node involved. To summarize what we see, it goes:

  1. No issue, No exception about doc_values (none at all)
  2. Restart of one machine
  3. Exceptions about doc_values start to come in (the second one I reported that happens at document insert), Cluster back to green
  4. After a few hours at least one shard cannot initialize (index red yesterday, index yellow right now)

Let me know if you need more info.

@clintongormley
Copy link

Hi @egueidan

Are the segment files small enough to email? In which case you can send them to: clinton dot gormley at elasticsearch dot com.

thanks for the detailed info

@egueidan
Copy link
Author

Hi @clintongormley,
Actually it's tiny. It should be in your inbox. Let me know if it does not go through.
Thanks

@egueidan
Copy link
Author

Hi,
just to keep you updated, this issue keeps happening. We have just restarted a few servers and looking at the logs I have found this third variant of the exception:

[2014-10-22 12:12:28,525][WARN ][index.merge.scheduler    ] [Defensor] [some_index][1] failed to merge java.lang.IllegalArgumentException: cannot change DocValues type from SORTED_SET to BINARY for field "custom.durationInMs"
       at org.apache.lucene.index.FieldInfos$FieldNumbers.addOrGet(FieldInfos.java:198)
       at org.apache.lucene.index.FieldInfos$Builder.addOrUpdateInternal(FieldInfos.java:304)
       at org.apache.lucene.index.FieldInfos$Builder.add(FieldInfos.java:332)
       at org.apache.lucene.index.SegmentMerger.mergeFieldInfos(SegmentMerger.java:316)
       at org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:94)
       at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4225)
       at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3820)
       at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:405)
       at org.apache.lucene.index.TrackingConcurrentMergeScheduler.doMerge(TrackingConcurrentMergeScheduler.java:106)
       at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:482)

Thought it might be relevant.

Regards,
Emmanuel

@clintongormley
Copy link

Hi @egueidan

To answer your questions this happens on a fully 1.3.4 cluster. The index was created on 1.3.4. There is no 1.3.2 node involved.

When we look at the segment files that you sent, some of them are from Lucene 4.9 (1.3.2), not Lucene 4.9.1. So 1.3.2 is involved somewhere here - either you have mixed nodes in your cluster, or the index was originally created with 1.3.2.

Can you clarify?

thanks

@egueidan
Copy link
Author

Hi @clintongormley,
I've checked again all my nodes are running 1.3.4 (build hash a70f3cc). In the cluster there exists some indices created in 1.3.2. But the issue definitely happens on indices created with 1.3.4. Maybe I mixed up the files, I'm sending you another set (based on other indices).
Thanks

@s1monw
Copy link
Contributor

s1monw commented Oct 22, 2014

I opened a lucene issue for this https://issues.apache.org/jira/browse/LUCENE-6019

@egueidan
Copy link
Author

@s1monw Glad you were able to pinpoint the issue and thanks a lot for taking the time. Any idea (even ballpark) of what version/when this will be integrated into elasticsearch? Regards.

@mikemccand
Copy link
Contributor

@egueidan the Lucene issue is fixed, and we're going to spin a new Lucene release with this fix. This will prevent mis-use of Lucene's APIs from causing index corruption.

But we will also separately to fix Elasticsearch "handle" the same field name across types having different settings (since Elasticsearch currently stores multiple types in one Lucene index), likely by refusing mappings of the same field name across different types with different index settings (such as doc values type).

Net/net, even once we've fixed Elasticsearch/Lucene to not corrupt the index on inconsistent doc values types, you'll still have to fix your usage of Elasticsearch to not allow the same field name across different types to have different mappings settings.

@egueidan
Copy link
Author

Hi @mikemccand and thanks for the quick fix.
To be honest I'm a bit puzzled as we only have one type across all of our indices... Does this mean there might be more to the problem we are experiencing? Just to be more precise, we are in a situation where we index "user" data into elasticsearch (ie we don't have full control over its content). We have dynamic templates so that the fields have doc_values enabled. Sometimes the data will be inconsistent (user submits conflicting field types). In case we receive a string after receiving a number for the same field, we have enabled index.mapping.ignore_malformed. When it's a string instead of an object or vice-versa then we get a mapper exception and deal with it. Anything wrong with that scenario?

@mikemccand
Copy link
Contributor

Hi @egueidan I don't fully understand what {{index.mapping.ignore_malformed}} should do; maybe someone else can chime in here. It sounds like a spooky setting: it seems dangerous to ignore serious errors like a type change.

@clintongormley
Copy link

Closing this in favour of #8688

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants