复盘一个Elasticsearch排序问题的剖析

最近线上的es查询的某个微服务接口，报了一个异常，如下：

```
nested: SearchParseException[No mapping found for [count] in order to sort on];
Caused by: SearchParseException[failed to parse search source 
```

直接从异常上看，可以得到是因为mapping里面不存在排序字段的时候，而抛出的异常，正常的情况，如果某个索引不存在并且还去查询该索引，我们可以通过对索引名字后面加*通配，来避免查询报错，如下：

```
        SearchRequestBuilder search=client.prepareSearch("log2019-07-11*");
        search.setQuery(QueryBuilders.queryStringQuery("uid:111"));
        search.addSort("count", SortOrder.DESC);
```

经询问，我们的代码里面已经加了*通配符，那么又为什么会出现这个问题呢？经过对场景的分析总结，对某个字段进行sort时，可能会报上述异常，主要在两种情况下：

（1）count字段在mapping中无定义，并没有在索引名字后缀加*通配符时，必定每次都报异常

（2）count字段在mapping中有定义，使用前面的排序方法，排序有时候报错，有时候不报

对于第一种情况，mapping里不存在定义，并且没有使用通配容错，直接使用该字段排序报错很正常。

接下来主要分析第二种情况，因为这里面有个概率事件，即大多数时候都没问题，但在少数时候会抛出异常。通过分析log发现在凌晨12点刚过的时候，会有几率出现这种问题，为了找到更多的排查线索，我让运维给出了线上当时服务端es的log文件，毕竟单纯从微服务的log里面，很难观察到这个异常前后，有没有更多的上下文log输出，想要找到这个，只能查看服务端部署es节点的log了，在拿到log之后，果然从上下文里面，发现了一些关键的信息，如下：

```
[2019-07-11 00:00:05,044][INFO ][cluster.metadata         ] [my_es] [log2019-07-11] creating index, cause [auto(index api)], templates [log], shards [3]/[2], mappings [_default_, log]
[2019-07-11 00:00:05,409][INFO ][cluster.routing.allocation] [my_es] Cluster health status changed from [RED] to [YELLOW] (reason: [shards started [[log2019-07-11][0], [log2019-07-11][2], [log2019-07-11][1]] ...]).
[2019-07-11 00:00:06,232][INFO ][cluster.routing.allocation] [my_es] Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[log2019-07-11][1], [log2019-07-11][1]] ...]).
[2019-07-11 00:00:06,374][INFO ][cluster.metadata         ] [my_es] [log2019-07-11] update_mapping [log]
[2019-07-11 00:00:07,153][DEBUG][action.search            ] [my_es] [log2019-07-11][0], node[QlHmfObMRg2K6FUuAaXXTw], [R], v[2], s[INITIALIZING], a[id=3aenuvbUQtGrFDBBxjJvCA], unassigned_info[[reason=INDEX_CREATED], at[2019-07-10T16:00:06.574Z]]: Failed to execute [org.elasticsearch.action.search.SearchRequest@22e9ea6f] lastShard [trueRemoteTransportException[[my_es_02][192.168.10.152:9300][indices:data/read/search[phase/query]]]; nested: SearchParseException[failed to parse search source [{"size":3,"query":{"bool":{"should":[{"term":{"uid":"44733065"}}]}},"sort":[{"count":{"order":"desc"}}]}]]; nested: SearchParseException[No mapping found for [count] in order to sort on];
Caused by: SearchParseException[failed to parse search source 

```

注意，在报这个异常之前，有两行关键的log：

```
[2019-07-11 00:00:05,409][INFO ][cluster.routing.allocation] [my_es] Cluster health status changed from [RED] to [YELLOW] (reason: [shards started [[log2019-07-11][0], [log2019-07-11][2], [log2019-07-11][1]] ...]).
[2019-07-11 00:00:06,232][INFO ][cluster.routing.allocation] [my_es] Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[log2019-07-11][1], [log2019-07-11][1]] ...]).

```

期间报异常的前2秒，es集群状态经历了从red到yellow再到green，虽然只有短暂的1秒，但却是排查问题非常关键的信息，我们知道出现这种信息的时候，代表的是es的主分片和副本分片正在做初始化或者出现了异常等待恢复，由此可以推论出这样一个场景，当凌晨12点刚过的第5秒，有写入该索引的es数据，触发了es动态索引的创建，由于这个索引有3个shard，每个shard分别有2个副本shard，也就是说共有6个shard需要初始化，假设初始化需要的时间为2秒，那么，恰巧在第6秒的时候，有个查询带排序的请求过来了，这个时候由于索引初始化并没有完成，所以在当天部分shard的mapping里面并没有查到该字段的信息，故产生了异常，之后当这个索引创建完成之后，再次收到的新查询请求是没有问题的。为了验证我们这个猜想，我们需要一段程序来做测试：

设计的复现场景有如下两步：

（1）A线程模拟查询请求，一直都在查询某一天的索引数据，起初这个索引并不存在，因为不存在所以查询使用通配符的方法，即使有排序字段，也并不会报错。
A线程的查询代码如下：

```
        SearchRequestBuilder search=client.prepareSearch("log2019-07-11*");
        search.setQuery(QueryBuilders.queryStringQuery("uid:111"));
        search.addSort("count", SortOrder.DESC);
        SearchResponse sr=search.get();
        for ( SearchHit hit: sr.getHits()){
            System.out.println(hit.getSource().toString());
        }
        System.out.println(Thread.currentThread().getName()+"=>query"+"   hit="+sr.getHits().getTotalHits());
```

（2）B线程在A线程启动3秒后执行，然后向这个不存在的索引插入一条数据，由于第一次插入数据，这天的索引会被自动创建，里面就会涉及shard的初始化过程，这个时候同时A线程在查询就会复现出问题：

```
[No mapping found for [count] in order to sort on]
```

B线程的写入代码如下：

```
        IndexRequestBuilder builder = client.prepareIndex("log2019-07-11", "log").setId("111");
        builder.setCreate(true);
        java.util.Map<String , Object> map=new HashMap<>();
        map.put("uid","111");
        map.put("count","3");
        builder.setSource(map);
        builder.execute().actionGet();
        System.out.println(Thread.currentThread().getName()+" => " + "create index finished. " );
```

知道问题后，那么如何解决这个问题呢？其实非常简单，我们只需要对于排序不存在的字段，作一下缺失容错即可，如下：

```
search.addSort("count", SortOrder.DESC);
```

改为

```
search.addSort(SortBuilders.fieldSort("count").unmappedType("integer").order(SortOrder.DESC));
```

上面的代码，告诉es如果在排序时，遇到一个不存在的字段，我们只需要给其设置正确的排序类型即可，这样就能避免前面提到的2个导致排序失败的原因：

（1）count排序字段在mapping中无定义，并没有在索引名字后缀加*通配符时，必定每次都报异常（查询一个不存在字段，是不会报异常的，不管索引名有无后缀通配符）

（2）count排序字段在mapping中有定义，使用前面的排序方法，排序有时候报错，有时候不报（真正原因是当时shard正在做初始化导致的）



es索引本身是shemeless的结构，对于正常查询一个不存在的字段，是不会报错的，但是对于排序的字段，则有可能出现异常，所以我们在写相关的代码时，可以对排序字段加个容错处理，以提高我们程序的健壮性。