After restart elasticsearch reads double as array of string #5705

alexey-medvedchikov · 2014-04-07T09:24:13Z

Hello, first of all I want to say you making crazy useful things, guys, thank you!

I have two elasticsearch twin (versions, configuration, everything) servers with the same data, replicated by logstash: ES1 and ES2. ES1 I restarted for a few hours ago and now I have a problems.

My mapping for logstash type, same for both servers.

"nginx_accesslog": {
        "dynamic_templates": [
                {
                        "string_template": {
                                "mapping": { "index": "not_analyzed", "type": "string" },
                                "match": "*",
                                "match_mapping_type": "string"
                        }
                }
        ],
        "_all": { "enabled": false },
        "_source": { "compress": true },
        "properties": { 
                "@timestamp": { "type": "date", "format": "dateOptionalTime" },
                "@version": { "type": "long" },
                "api_key": { "type": "string", "index": "not_analyzed" },
                "body_bytes_sent": { "type": "long" },
                "host": { "type": "string", "index": "not_analyzed" },
                "http_host": { "type": "string", "index": "not_analyzed" },
                "http_method": { "type": "string", "index": "not_analyzed" },
                "http_referer": { "type": "string", "index": "not_analyzed" },
                "http_user_agent": { "type": "string", "index": "not_analyzed" },
                "http_version": { "type": "string", "index": "not_analyzed" },
                "http_x_forwarded_for": { "type": "string", "index": "not_analyzed" },
                "message": { "type": "string", "index": "not_analyzed" },
                "path": { "type": "string", "index": "not_analyzed" },
                "remote_addr": { "type": "string", "index": "not_analyzed" },
                "remote_user": { "type": "string", "index": "not_analyzed" },
                "request": { "type": "string", "index": "not_analyzed" },
                "request_time": { "type": "double" },
                "status": { "type": "long" },
                "tags": { "type": "string", "index": "not_analyzed" },
                "type": { "type": "string", "index": "not_analyzed" }
        }
}

Query (I'm using Sense add-on)

POST /logstash-2014.04.07/_search
{
    "script_fields": {
       "s_request_time": {
          "script": "doc['request_time'].value"
       }
    },
    "size": 20
}

ES2, everything is normal:

{
   "took": 63,
   "timed_out": false,
   "_shards": {
      "total": 4,
      "successful": 4,
      "failed": 0
   },
   "hits": {
      "total": 17041240,
      "max_score": 1,
      "hits": [
         {
            "_index": "logstash-2014.04.07",
            "_type": "nginx_accesslog",
            "_id": "LSfAaBwSSDS5rL6utSHQJA",
            "_score": 1,
            "fields": {
               "s_request_time": 0.014
            }
         },
...

ES1: Ooops!

{
   "took": 51,
   "timed_out": false,
   "_shards": {
      "total": 4,
      "successful": 4,
      "failed": 0
   },
   "hits": {
      "total": 17041131,
      "max_score": 1,
      "hits": [
         {
            "_index": "logstash-2014.04.07",
            "_type": "nginx_accesslog",
            "_id": "tjZo1_JmRpOu5kE2WRfURw",
            "_score": 1,
            "fields": {
               "s_request_time": [
                  " \u0001?PZ\u000e+\u0001\u0003\t\u001c" <-- WAT?!
               ]
            }
         },

It's most obvious demonstration of my problem. Another thing is when I'm using data_histogram facet (in kibana) I got ClassCastException[org.elasticsearch.index.fielddata.plain.PagedBytesIndexFieldData cannot be cast to org.elasticsearch.index.fielddata.IndexNumericFieldData.

Purging all indexes fixes problem. Not only new, but old data too misenterpreted as arrays of one string.
Well, I want my doubles back. :)

The text was updated successfully, but these errors were encountered:

imotov · 2014-04-07T19:32:39Z

This might be related to #5623.

s1monw · 2014-04-14T20:52:38Z

@imotov can you try to verify with @AleXeyMedVed that this is fixed now?

imotov · 2014-04-15T00:16:31Z

@AleXeyMedVed could you try reproducing this issue to see if it was fixed in the latest nightly build?

alexey-medvedchikov · 2014-04-15T06:32:14Z

@s1monw @imotov With elasticsearch-1.1.1-20140415.001904-55.deb seems everything works fine. Thank you!

alexey-medvedchikov · 2014-04-15T09:42:15Z

I can break it again:

run long-running query like

/_all/_search {
    "facets": {
      "terms": {
          "terms": {
             "script_field": "doc['request_time'].value <= 0.5 ? true : false",
             "size": 10
          }
      }
    }
}

Insert big bunch of new items (by logstash for example)
Send SIGTERM

Voila:

POST /logstash-2014.04.15.08/_search
{
    "script_fields": {
       "s_request_time": {
          "script": "doc['request_time'].getValues()"
       }
    }
}
...
         {
            "_index": "logstash-2014.04.15.08",
            "_type": "nginx_accesslog",
            "_id": "tjZ9fIqLQWedynr4mBhdEw",
            "_score": 1,
            "fields": {
               "s_request_time": [
                  [
                     " \u0001?Kc)}ymHZ",
                     "$\u000b|^\u001aOoNlE",
                     "(_eqT~|vd",
                     ",\u0005~/\r'wg6",
                     "0/rxj?>;",
                     "4\u0002�\u0017FS{s",
                     "8\u0017y<5\u001f_",
                     "<\u0001?Kc)}",
                     "@\u000b|^\u001aO",
                     "D_eqT",
                     "H\u0005~/\r",
                     "L/rx",
                     "P\u0002�\u0017",
                     "T\u0017y",
                     "X\u0001?",
                     "\\\u000b"
                  ]
               ]
            }
         },
...

imotov · 2014-04-15T11:03:27Z

@AleXeyMedVed do you see any exceptions in the log files?

alexey-medvedchikov · 2014-04-15T11:29:41Z

Exception for query like mentioned in my prev comment:

[2014-04-15 17:05:24,563][DEBUG][action.search.type       ] [Hobgoblin] [logstash-2014.04.14.10][3], node[JrhBvFHpRgyT5RXv8O9HwA], [P], s[STARTED]: Failed to execute [org.elasticsearch.action.search.
org.elasticsearch.search.query.QueryPhaseExecutionException: [logstash-2014.04.14.10][3]: query[ConstantScore(*:*)],from[0],size[0]: Query Failed [Failed to execute main query]
        at org.elasticsearch.search.query.QueryPhase.execute(QueryPhase.java:127)
        at org.elasticsearch.search.SearchService.executeQueryPhase(SearchService.java:257)
        at org.elasticsearch.search.action.SearchServiceTransportAction.sendExecuteQuery(SearchServiceTransportAction.java:202)
        at org.elasticsearch.action.search.type.TransportSearchQueryThenFetchAction$AsyncAction.sendExecuteFirstPhase(TransportSearchQueryThenFetchAction.java:80)
        at org.elasticsearch.action.search.type.TransportSearchTypeAction$BaseAsyncAction.performFirstPhase(TransportSearchTypeAction.java:216)
        at org.elasticsearch.action.search.type.TransportSearchTypeAction$BaseAsyncAction.performFirstPhase(TransportSearchTypeAction.java:203)
        at org.elasticsearch.action.search.type.TransportSearchTypeAction$BaseAsyncAction$2.run(TransportSearchTypeAction.java:186)
        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:724)
Caused by: java.lang.RuntimeException: uncomparable values << ^A?WoNlEPrX>> and <<0.05>>
        at org.elasticsearch.common.mvel2.math.MathProcessor.doOperationNonNumeric(MathProcessor.java:321)
        at org.elasticsearch.common.mvel2.math.MathProcessor._doOperations(MathProcessor.java:234)
        at org.elasticsearch.common.mvel2.math.MathProcessor.doOperations(MathProcessor.java:79)
        at org.elasticsearch.common.mvel2.ast.BinaryOperation.getReducedValueAccelerated(BinaryOperation.java:114)
        at org.elasticsearch.common.mvel2.MVELRuntime.execute(MVELRuntime.java:86)
        at org.elasticsearch.common.mvel2.compiler.CompiledExpression.getDirectValue(CompiledExpression.java:123)
        at org.elasticsearch.common.mvel2.compiler.CompiledExpression.getValue(CompiledExpression.java:119)
        at org.elasticsearch.script.mvel.MvelScriptEngineService$MvelSearchScript.run(MvelScriptEngineService.java:191)
        at org.elasticsearch.search.facet.terms.strings.ScriptTermsStringFieldFacetExecutor$Collector.collect(ScriptTermsStringFieldFacetExecutor.java:147)
        at org.elasticsearch.common.lucene.search.FilteredCollector.collect(FilteredCollector.java:61)
        at org.elasticsearch.common.lucene.MultiCollector.collect(MultiCollector.java:60)
        at org.apache.lucene.search.Scorer.score(Scorer.java:65)
        at org.apache.lucene.search.ConstantScoreQuery$ConstantScorer.score(ConstantScoreQuery.java:256)
        at org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:621)
        at org.elasticsearch.search.internal.ContextIndexSearcher.search(ContextIndexSearcher.java:173)
        at org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:309)
        at org.elasticsearch.search.query.QueryPhase.execute(QueryPhase.java:111)
        ... 9 more
Caused by: java.lang.ClassCastException: java.lang.Double cannot be cast to java.lang.String
        at java.lang.String.compareTo(String.java:108)
        at org.elasticsearch.common.mvel2.math.MathProcessor.doOperationNonNumeric(MathProcessor.java:318)
        ... 25 more

Exceptions appeared on restart mentioned in prev comment:

[2014-04-15 15:45:45,129][WARN ][index.engine.internal    ] [Condor] [logstash-2014.04.14.11][0] Searcher was released twice
org.elasticsearch.ElasticsearchIllegalStateException: Double release
        at org.elasticsearch.index.engine.internal.InternalEngine$EngineSearcher.release(InternalEngine.java:1510)
        at org.elasticsearch.search.internal.DefaultSearchContext.release(DefaultSearchContext.java:212)
        at org.elasticsearch.search.SearchService.freeContext(SearchService.java:551)
        at org.elasticsearch.search.SearchService.executeQueryPhase(SearchService.java:268)
        at org.elasticsearch.search.action.SearchServiceTransportAction.sendExecuteQuery(SearchServiceTransportAction.java:202)
        at org.elasticsearch.action.search.type.TransportSearchQueryThenFetchAction$AsyncAction.sendExecuteFirstPhase(TransportSearchQueryThenFetchAction.java:80)
        at org.elasticsearch.action.search.type.TransportSearchTypeAction$BaseAsyncAction.performFirstPhase(TransportSearchTypeAction.java:216)
        at org.elasticsearch.action.search.type.TransportSearchTypeAction$BaseAsyncAction.performFirstPhase(TransportSearchTypeAction.java:203)
        at org.elasticsearch.action.search.type.TransportSearchTypeAction$BaseAsyncAction$2.run(TransportSearchTypeAction.java:186)
        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:724)

Maybe I can provide you a trace of execution or broken index file somehow?

imotov · 2014-04-15T11:48:41Z

@AleXeyMedVed was index logstash-2014.04.15.08 created with the nightly build or before you upgraded? Could you run curl localhost:9200/logstash-2014.04.15.08/_mapping and post the result here? Are you using percolator on this cluster?

alexey-medvedchikov · 2014-04-15T12:35:25Z

@imotov

index was created by nightly build
https://gist.github.com/alexeymedved/dc7a3fb376e6f3c80f23#file-logstash-2014-04-15-08_mapping
no, i'm not using percolator

imotov · 2014-04-15T13:43:22Z

@AleXeyMedVed your mapping looks fine after restart, so I am thinking it might be actually an MVEL issue. For some reason MVEL thinks that it should compare two doubles as strings in your case. I tried to reproduce this issue locally but didn't succeed so far. Any chance you can try reproducing it using javascript instead of MVEL?

alexey-medvedchikov · 2014-04-15T15:35:04Z

MVEL just helps me to show what data actually we operating on. Sorry for misleading queries. It's not an MVEL issue for sure because of:

Another thing is when I'm using data_histogram facet (in kibana) I got ClassCastException[org.elasticsearch.index.fielddata.plain.PagedBytesIndexFieldData cannot be cast to org.elasticsearch.index.fielddata.IndexNumericFieldData.

Exception for this kind of query:

[2014-04-15 15:02:49,538][DEBUG][action.search.type       ] [Condor] [logstash-2014.04.14.09][0], node[OS96wzBvT5WTcPgzKrAHlw], [P], s[STARTED]: Failed to execute [org.el
asticsearch.action.search.SearchRequest@906a63f] lastShard [true]
org.elasticsearch.search.SearchParseException: [logstash-2014.04.14.09][0]: from[-1],size[-1]: Parse Failure [Failed to parse source [{"facets":{"0":{"date_histogram":{"k
ey_field":"@timestamp","value_field":"request_time","interval":"10m"},"global":true,"facet_filter":{"fquery":{"query":{"filtered":{"query":{"query_string":{"query":"type:
nginx_accesslog  AND request:\\/search\\?*"}},"filter":{"bool":{"must":[{"range":{"@timestamp":{"from":1397462569513,"to":1397548969513}}}]}}}}}}}},"size":0}]]
        at org.elasticsearch.search.SearchService.parseSource(SearchService.java:634)
        at org.elasticsearch.search.SearchService.createContext(SearchService.java:507)
        at org.elasticsearch.search.SearchService.createAndPutContext(SearchService.java:480)
        at org.elasticsearch.search.SearchService.executeQueryPhase(SearchService.java:252)
        at org.elasticsearch.search.action.SearchServiceTransportAction.sendExecuteQuery(SearchServiceTransportAction.java:202)
        at org.elasticsearch.action.search.type.TransportSearchCountAction$AsyncAction.sendExecuteFirstPhase(TransportSearchCountAction.java:70)
        at org.elasticsearch.action.search.type.TransportSearchTypeAction$BaseAsyncAction.performFirstPhase(TransportSearchTypeAction.java:216)
        at org.elasticsearch.action.search.type.TransportSearchTypeAction$BaseAsyncAction.performFirstPhase(TransportSearchTypeAction.java:203)
        at org.elasticsearch.action.search.type.TransportSearchTypeAction$BaseAsyncAction$2.run(TransportSearchTypeAction.java:186)
        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:724)
Caused by: java.lang.ClassCastException: org.elasticsearch.index.fielddata.plain.PagedBytesIndexFieldData cannot be cast to org.elasticsearch.index.fielddata.IndexNumericFieldData
        at org.elasticsearch.search.facet.datehistogram.DateHistogramFacetParser.parse(DateHistogramFacetParser.java:188)
        at org.elasticsearch.search.facet.FacetParseElement.parse(FacetParseElement.java:93)
        at org.elasticsearch.search.SearchService.parseSource(SearchService.java:622)
        ... 11 more

imotov · 2014-04-15T16:00:56Z

@AleXeyMedVed this is different. Here you are searching the yesterday's index logstash-2014.04.14.09 that most likely contains data indexed while mapping for this index was messed up due to #5623. So you have numbers indexed as numbers and as strings. I would also suspect that mapping for this index is still messed up. Can you run curl localhost:9200/logstash-2014.04.14.09/_mapping to see if fields are mapped correctly? Can you also try reproducing this failure while searching only indices created with the nightly build and without using MVEL?

imotov · 2014-04-18T14:09:32Z

That looks like a duplicate of #5623 after all. Please, feel free to reopen if you have any additional data points.

alexey-medvedchikov · 2014-04-21T06:52:07Z

Well, I fixed this problem for myself by using long for time fields :)

UnderGreen · 2015-03-13T10:22:28Z

Have same problem with Elastic 1.4.4. Query result without scripting:

{
    "took": 7,
    "timed_out": false,
    "_shards": {
        "total": 2,
        "successful": 2,
        "failed": 0
    },
    "hits": {
        "total": 33,
        "max_score": null,
        "hits": [{
            "_index": "logstash-2015.03.13",
            "_type": "gelf_photo",
            "_id": "AUwSeR5Mf_J86mgo9hKZ",
            "_score": null,
            "_source": {
                "version": "1.0",
                "type": "gelf_photo",
                "time_done_full": "0.0009758472442627",
                "time_done": 0.0,
                "@version": "1",
                "@timestamp": "2015-03-13T09:31:09.067Z",
                "_class__": "",
                "_method__": "",
                "_extra__": "null",
                "_request_id__": "45e21fc5e190de6269567c57c5f2177f0009e188"
            },
            "sort": [1426239069067]
        }]
    }
}

Query result with scripting:

{
    "took": 11,
    "timed_out": false,
    "_shards": {
        "total": 2,
        "successful": 2,
        "failed": 0
    },
    "hits": {
        "total": 33,
        "max_score": null,
        "hits": [{
            "_index": "logstash-2015.03.13",
            "_type": "gelf_photo",
            "_id": "AUwSeR5Mf_J86mgo9hKZ",
            "_score": null,
            "fields": {
                "s_time_done": [" \u0001\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000"]
            },
            "sort": [1426239069067]
        }]
    }
}

Result ofhttp://logstash.test:9200/logstash-2015.03.13/_mappings:

...
"time_done": {
"type": "double"
},
...

clintongormley · 2015-04-05T19:54:12Z

@UnderGreen please can you open a new issue with all the details. Although I have a sneaking suspicion that this is an issue with dynamic mappings being applied asynchronously. See #8688 for more

s1monw added bug labels Apr 14, 2014

imotov self-assigned this Apr 14, 2014

alexey-medvedchikov closed this as completed Apr 15, 2014

alexey-medvedchikov reopened this Apr 15, 2014

imotov closed this as completed Apr 18, 2014

clintongormley removed v1.2.0 v2.0.0-beta1 labels Jun 7, 2015

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

After restart elasticsearch reads double as array of string #5705

After restart elasticsearch reads double as array of string #5705

alexey-medvedchikov commented Apr 7, 2014

imotov commented Apr 7, 2014

s1monw commented Apr 14, 2014

imotov commented Apr 15, 2014

alexey-medvedchikov commented Apr 15, 2014

alexey-medvedchikov commented Apr 15, 2014

imotov commented Apr 15, 2014

alexey-medvedchikov commented Apr 15, 2014

imotov commented Apr 15, 2014

alexey-medvedchikov commented Apr 15, 2014

imotov commented Apr 15, 2014

alexey-medvedchikov commented Apr 15, 2014

imotov commented Apr 15, 2014

imotov commented Apr 18, 2014

alexey-medvedchikov commented Apr 21, 2014

UnderGreen commented Mar 13, 2015

clintongormley commented Apr 5, 2015

After restart elasticsearch reads double as array of string #5705

After restart elasticsearch reads double as array of string #5705

Comments

alexey-medvedchikov commented Apr 7, 2014

imotov commented Apr 7, 2014

s1monw commented Apr 14, 2014

imotov commented Apr 15, 2014

alexey-medvedchikov commented Apr 15, 2014

alexey-medvedchikov commented Apr 15, 2014

imotov commented Apr 15, 2014

alexey-medvedchikov commented Apr 15, 2014

imotov commented Apr 15, 2014

alexey-medvedchikov commented Apr 15, 2014

imotov commented Apr 15, 2014

alexey-medvedchikov commented Apr 15, 2014

imotov commented Apr 15, 2014

imotov commented Apr 18, 2014

alexey-medvedchikov commented Apr 21, 2014

UnderGreen commented Mar 13, 2015

clintongormley commented Apr 5, 2015