JSON parsing issue and mis-reported JSON_ERROR

[kpam]

Hi all,

I am using Filebeat 5.0 rc and shipping logs directly to ES/Kibana.

I am currently trying to use the JSON option to decode my JSON object log message. The behavior I'm seeing is that when I include the JSON config and send a request to my server that usually generates 40 log messages, Filebeat is able to parse the message and export the JSON object fields to root level, but it also reports a parsing issue and doesn't ship the rest of the logs afterwards. If I hit it again, it only again only parse the first message.

If I remove the JSON configs and send a request, all 40 log messages will appear on Kibana (instead of just 1).

Here's is my JSON config:

json.message_key: message
json.keys_under_root: true
json.add_error_key: true

And here are two examples of a particular log record with JSON off, and then JSON on:

OFF

{
"_index": "fb-ehrmantraut",
"_type": "log",
"_id": "AVfEfwwm-d2cWVXzsgPe",
"_score": null,
"_source": {
"@timestamp": "2016-10-14T18:40:38.049Z",
"beat": {
"hostname": "ip-10-199-145-7",
"name": "ip-10-199-145-7"
},
"input_type": "log",
"message": "{"AdSessionID":"testadsessionid-tp-redefine-protobuf","level":"info","msg":"received playback event of type: MIDPOINT","time":"2016-10-14T18:40:34Z"}",
"offset": 421320,
"source": "/var/log/ehrmantraut.log",
"type": "log"
},
"fields": {
"@timestamp": [
1476470438049
]
},
"sort": [
1476470438049
]
}

ON

{
"_index": "fb-ehrmantraut",
"_type": "log",
"_id": "AVfEg9WE-d2cWVXzsgP4",
"_score": null,
"_source": {
"@timestamp": "2016-10-14T18:45:46.683Z",
"AdSessionID": "testadsessionid-tp-redefine-protobuf",
"beat": {
"hostname": "ip-10-199-145-7",
"name": "ip-10-199-145-7"
},
"input_type": "log",
"json_error": "Key 'message' not found",
"level": "info",
"message": "",
"msg": "received playback event of type: MIDPOINT",
"offset": 435703,
"source": "/var/log/ehrmantraut.log",
"time": "2016-10-14T18:45:39Z",
"type": "log"
},
"fields": {
"@timestamp": [
1476470746683
],
"time": [
1476470739000
]
},
"sort": [
1476470746683
]
}

I'm also confused why a JSON_ERROR of key 'message' not found is being reported when it is in fact able to export all those fields to root. And then when this parse error occurs, the rest of my logs are not being shipped. Any ideas?

[andrewkroh]

The configuration that I suggested for the example you gave had json.message_key: msg because the JSON being parsed has a msg field. It does not have a message field and that's why there is an error.

The json.message configuration option specifies what key to apply filtering and mutliline to. The configuration setting isn't required per the documentation.

[kpam]

Hey @andrewkroh,

I set json.message_key: msg as you suggested, and now all of the expected 40 or so log msg's are being sent in one giant request:

{
"_index": "fb-ehrmantraut",
"_type": "log",
"_id": "AVfEwnFh-d2cWVXzsgVg",
"_score": null,
"_source": {
"@timestamp": "2016-10-14T19:54:09.807Z",
"AdSessionID": "testadsessionid-tp-redefine-protobuf",
"beat": {
"hostname": "ip-10-199-145-7",
"name": "ip-10-199-145-7"
},
"input_type": "log",
"level": "info",
"msg": "received playback event of type: MIDPOINT\nsending event to Spade\nSuccessfully handled at least one request\nreceived playback event of type: START\nhandling event: impression\nhandling DFP Impression\nsending request to DFP: &{GET http://pubads.g.doubleclick.net/pcs/view?xai=AKAOjsuHbrP9LbuTms-kg61SZC2Wm_PYm3e2s1rt4er2tPRzT9-pe7yCqJU4VC8uJ8w2ONwG4u6lkie20Oz4DcGOVLQfB6oo2eiYmPRuWL9Na2fOhhiJrFRC0gmni0qfDpGBAGPY2ggMy414w2hJq0F3FZ72UDqe3JdynaxBa5GS23FuGx_Ty2UPkG2tXxB9BnsDYwBkDobvHzAQmUgAmHHuQAInCriA_yt7ZCLa0eP7yir9J8EipN1Pjs3zru0cJIEwsBZOpWkp7H868Q&sig=Cg0ArKJSzNMT2zeaniFkEAE&adurl= HTTP/1.1 1 1 map[Header1:[value1] Header2:[value2]] 0 false pubads.g.doubleclick.net map map map }\nDFP Request\nreceived response from DFP: 200 OK\nDFP success!\nhandling event: impression\nhandling third-party impression\nsending request to third-party: &{GET Prime Gaming HTTP/1.1 1 1 map[Header1:[value1] Header2:[value2]] 0 false twitch.amazon.com map map map }\nreceived playback event of type: THIRD_QUARTILE\nsending event to Spade\nSuccessfully handled at least one request\nreceived playback event of type: FIRST_QUARTILE\nsending event to Spade\nSuccessfully handled at least one request\nreceived playback event of type: COMPLETE\nsending event to Spade\nsending event to Spade\nSuccessfully handled at least one request\nThird-Party Request\nreceived response from third-party: 200 OK\nThird-Party success!\nreceived playback event of type: ERROR\nhandling event: error\nhandling DFP Impression\nsending request to DFP: &{GET http://pubads.g.doubleclick.net/pagead/conversion/?ai=BYM1NHY-3V7HCBISr-gPkl6HwApH11eYJAAAAEAEgADgAWKnToqutA2DJ9viGyKOgGYIBF2NhLXB1Yi04Njc3ODg3NTc4ODk2OTI5sgENd3d3LnR3aXRjaC50droBCzY0MHg0ODBfeG1syAEF2gEjaHR0cHM6Ly93d3cudHdpdGNoLnR2L3R3aXRjaG1lZGlhMjTAAgLgAgDqAikvMzU3NjEyMS90d2l0Y2guc3MvY2hhbm5lbHMvdHdpdGNobWVkaWEyNPgChNIegAMBkAOsApgD4AOoAwHgBAHSBQYQkejjzQKQBgGgBiPYBwHgBws&sigh=0d6jdw7n5jk&label=videoplayfailed[ERRORCODE] HTTP/1.1 1 1 map[Header2:[value2] Header1:[value1]] 0 false pubads.g.doubleclick.net map map map }\nDFP Request\nreceived response from DFP: 200 OK\nDFP success!\nsending event to Spade\nSuccessfully handled at least one request\nhandling event: impression\nhandling third-party impression\nsending request to third-party: &{GET Prime Gaming HTTP/1.1 1 1 map[Header1:[value1] Header2:[value2]] 0 false twitch.amazon.com map map map }\nThird-Party Request\nreceived response from third-party: 200 OK\nThird-Party success!\nsending event to Spade\nsending event to Spade\nSuccessfully handled at least one request",
"offset": 453845,
"source": "/var/log/ehrmantraut.log",
"time": "2016-10-14T19:54:08Z",
"type": "log"
},
"fields": {
"@timestamp": [
1476474849807
],
"time": [
1476474848000
]
},
"sort": [
1476474849807
]
}

My multi-line config:

multiline:
pattern: '^['
negate: true
match: after

The pattern field is actually: ' ^ \ [ ' without spaces but the forward slash is not showing up.

Example log messages look like:

{"AdSessionID":"testadsessionid-tp-redefine-protobuf","level":"info","msg":"received response from DFP: 200 OK","time":"2016-10-14T20:07:31Z"}
{"AdSessionID":"testadsessionid-tp-redefine-protobuf","level":"debug","msg":"DFP success!","time":"2016-10-14T20:07:31Z"}
{"eventName":"video_ad_error","level":"info","msg":"sending event to Spade","time":"2016-10-14T20:07:31Z"}
{"AdSessionID":"testadsessionid-tp-redefine-protobuf","level":"debug","msg":"Successfully handled at least one request","time":"2016-10-14T20:07:31Z"}