ES-5x : JsonGenerationException in slow logs

dimalini · November 21, 2017, 5:20am

Hi,
As part of slow query investigation, we enabled search slow logs in our production environment[ES version - 5.4.1]. In few cases, i do see the original slow query getting logged. But there were many occurrences of JsonGenerationException as seen below. Could someone help understand the cases when we would encounter this?

[2017-11-20T11:35:32,917][WARN ][index.search.slowlog.query] [es-d11-rm] [sharedindex][10] took[12.5s], took_millis[12544], types[documentcontract], stats, search_type[QUERY_THEN_FETCH], total_shards[6], source[{ "error" : "JsonGenerationException[Can not start an object, expecting field name (context: Object)]"}],
[2017-11-20T11:35:42,521][WARN ][index.search.slowlog.query] [es-d11-rm] [sharedindex][3] took[22.1s], took_millis[22158], types[documentcontract], stats, search_type[QUERY_THEN_FETCH], total_shards[6], source[{ "error" : "JsonGenerationException[Can not start an object, expecting field name (context: Object)]"}],
[2017-11-20T11:47:26,846][INFO ][index.search.slowlog.query] [es-d11-rm] [sharedindex][3] took[6.3s], took_millis[6330], types[documentcontract], stats, search_type[QUERY_THEN_FETCH], total_shards[6], source[{ "error" : "JsonGenerationException[Can not start an object, expecting field name (context: Object)]"}],
[2017-11-20T11:48:27,842][INFO ][index.search.slowlog.query] [es-d11-rm] [sharedindex][3] took[6.9s], took_millis[6932], types[documentcontract], stats, search_type[QUERY_THEN_FETCH], total_shards[6], source[{ "error" : "JsonGenerationException[Can not start an object, expecting field name (context: Object)]"}],
[2017-11-20T11:48:45,656][INFO ][index.search.slowlog.query] [es-d11-rm] [sharedindex][6] took[9.1s], took_millis[9168], types[documentcontract], stats, search_type[QUERY_THEN_FETCH], total_shards[6], source[{ "error" : "JsonGenerationException[Can not start an object, expecting field name (context: Object)]"}],
[2017-11-20T11:48:57,620][WARN ][index.search.slowlog.query] [es-d11-rm] [sharedindex][9] took[21.1s], took_millis[21121], types[documentcontract], stats, search_type[QUERY_THEN_FETCH], total_shards[6], source[{ "error" : "JsonGenerationException[Can not start an object, expecting field name (context: Object)]"}],
[2017-11-20T11:49:08,569][WARN ][index.search.slowlog.query] [es-d11-rm] [sharedindex][2] took[32s], took_millis[32080], types[documentcontract], stats, search_type[QUERY_THEN_FETCH], total_shards[6], source[{ "error" : "JsonGenerationException[Can not start an object, expecting field name (context: Object)]"}],
[2017-11-20T11:50:59,729][INFO ][index.search.slowlog.query] [es-d11-rm] [sharedindex][3] took[6.8s], took_millis[6898], types[documentcontract], stats, search_type[QUERY_THEN_FETCH], total_shards[6], source[{ "error" : "JsonGenerationException[Can not start an object, expecting field name (context: Object)]"}],
[2017-11-20T11:56:02,530][WARN ][index.search.slowlog.query] [es-d11-rm] [sharedindex][9] took[10.1s], took_millis[10146], types[documentcontract], stats, search_type[QUERY_THEN_FETCH], total_shards[6], source[{ "error" : "JsonGenerationException[Can not start an object, expecting field name (context: Object)]"}],
[2017-11-20T11:56:05,265][WARN ][index.search.slowlog.query] [es-d11-rm] [sharedindex][2] took[12.8s], took_millis[12872], types[documentcontract], stats, search_type[QUERY_THEN_FETCH], total_shards[6], source[{ "error" : "JsonGenerationException[Can not start an object, expecting field name (context: Object)]"}],
[2017-11-20T11:56:17,629][WARN ][index.search.slowlog.query] [es-d11-rm] [sharedindex][3] took[25.2s], took_millis[25239], types[documentcontract], stats, search_type[QUERY_THEN_FETCH], total_shards[6], source[{ "error" : "JsonGenerationException[Can not start an object, expecting field name (context: Object)]"}],
[2017-11-20T11:56:17,629][WARN ][index.search.slowlog.query] [es-d11-rm] [sharedindex][3] took[10.7s], took_millis[10724], types[documentcontract], stats, search_type[QUERY_THEN_FETCH], total_shards[6], source[{ "error" : "JsonGenerationException[Can not start an object, expecting field name (context: Object)]"}],
[2017-11-20T11:56:25,755][INFO ][index.search.slowlog.query] [es-d11-rm] [sharedindex][10] took[5.3s], took_millis[5360], types[documentcontract], stats, search_type[QUERY_THEN_FETCH], total_shards[6], source[{ "error" : "JsonGenerationException[Can not start an object, expecting field name (context: Object)]"}],
[2017-11-20T12:08:41,808][WARN ][index.search.slowlog.query] [es-d11-rm] [sharedindex][2] took[16.2s], took_millis[16216], types[documentcontract], stats, search_type[QUERY_THEN_FETCH], total_shards[6], source[{ "error" : "JsonGenerationException[Can not start an object, expecting field name (context: Object)]"}],
[2017-11-20T12:08:47,168][WARN ][index.search.slowlog.query] [es-d11-rm] [sharedindex][9] took[21.5s], took_millis[21578], types[documentcontract], stats, search_type[QUERY_THEN_FETCH], total_shards[6], source[{ "error" : "JsonGenerationException[Can not start an object, expecting field name (context: Object)]"}],
[2017-11-20T12:08:58,130][INFO ][index.search.slowlog.query] [es-d11-rm] [sharedindex][3] took[5.3s], took_millis[5330], types[documentcontract], stats, search_type[QUERY_THEN_FETCH], total_shards[6], source[{ "error" : "JsonGenerationException[Can not start an object, expecting field name (context: Object)]"}]

Thanks,
Divya Malini

jpountz · November 21, 2017, 1:46pm

This looks like a bug. By any chance, would you be able to find one query that triggers this bug? It would help identify it and then fix it.

dimalini · November 22, 2017, 1:19am

I enabled the logs to get the actual query. Anyway i ll try to get the query and share, even otherwise could you please take a look ?

dimalini · November 27, 2017, 10:28am

Hi Adrien,
I am unable to get the original query yet. Could the number of chars in the request contribute to this exception? Our request would easily exceed 32767 in some cases, if this would help you narrow to the bug causing this exception.

Thanks,
Divya

dimalini · November 29, 2017, 6:09pm

Any help here? I was expecting to get the original query by enabling the slow logs. But I am constantly getting this exception.
To add details - we are in NEST 2.x and ES 5.4.1

dimalini · November 30, 2017, 10:08am

I did the following to reproduce the exception locally.

Had the search slow logs settings as follows

PUT _all/_settings
{
"index.search.slowlog.threshold.query.warn": "1ms",
"index.search.slowlog.threshold.query.info": "1ms",
"index.search.slowlog.threshold.fetch.warn": "1ms",
"index.search.slowlog.threshold.fetch.info": "1ms"
}

And executed a sample query that mimics our actual query. Please find the query below

gist.github.com

https://gist.github.com/DivyaMalini/489f158a01a988ff7e725832fb03beb4

SampleQuery.txt

POST sharedindex/_search
{
   "from": 0,
   "size": 50,
   "sort": [],
   "highlight": {
      "fields": {
         "field1": {
            "type": "customhighlight_1"
         }

This file has been truncated. show original

system · December 28, 2017, 10:18am

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