Filebeat spamming errors when json.keys_under_root: true and message is not json

[felipejfc]

• Version: latest
• Operating System: kubernetes
• Steps to Reproduce: use json.keys_under_root: true and log a message that is not a json

I've a situation where I'ld like json logs to be parsed and expanded but non json logs also be logged, fluentd does that but with filebeat it keeps spamming stdout with an error:

into Go value of type map[string]interface {}
filebeat-30n8k filebeat 2018/01/10 23:58:27.817317 json.go:32: ERR Error decoding JSON: json: cannot unmarshal number into Go value of type map[string]interface {}
filebeat-rxfv0 filebeat 2018/01/10 23:58:27.824942 json.go:32: ERR Error decoding JSON: json: cannot unmarshal number into Go value of type map[string]interface {}
filebeat-1rxlp filebeat 2018/01/10 23:58:27.905065 json.go:32: ERR Error decoding JSON: json: cannot unmarshal number into Go value of type map[string]interface {}
filebeat-m374z filebeat 2018/01/10 23:58:27.885551 json.go:32: ERR Error decoding JSON: invalid character 'v' looking for beginning of value
filebeat-rxfv0 filebeat 2018/01/10 23:58:27.824981 json.go:32: ERR Error decoding JSON: json: cannot unmarshal number into Go value of type map[string]interface {}
filebeat-bgx48 filebeat 2018/01/10 23:58:27.575356 json.go:32: ERR Error decoding JSON: json: cannot unmarshal number into Go value of type map[string]interface {}
filebeat-30n8k filebeat 2018/01/10 23:58:27.817366 json.go:32: ERR Error decoding JSON: invalid character '-' after array element

Our kubernetes cluster logs a lot and all types of logging, json and not json messages... how do we solve this issue?

thanks

[ruflin]

Are these messages coming from the same log file?

Could you share some log output?

[felipejfc]

If your containers logs anything that is not a valid json, filebeat will log this error, our use case is that we log like 10k/s valid jsons and another 10k/s invalid json, and for each of these invalid jsons logged across multiple applications and containers, filebeat logs an error like that, imagine 10k logbeat errors/s... it's very annoying, take logstash json filter for example, when the message you are trying to parse is not a valid json it only tags the record with an "cannot parse" tag

[ruflin]

@felipejfc I definitively see the problem if in a single log file json logs and non json logs are mixed. Unfortunately this can be the case for docker as a docker image outputs logs from 2 different service in one stream. Is that your use case? But if the logs are in files, different prospectors with and without json decoding could be specified for example based on image name in auto discovery.

I think I understand the problem and I like your proposal to make it a config option, I just want to make sure we don't add this "feature" if there is an other way to solve it.

[magnusheino]

Example. Spring Boot java application running in docker with log-driver json-file logging json to stdout. This means that all output from the process will end up in /var/lib/docker/containers//-json.log

We have JAVA_TOOL_OPTIONS env set. This means that the JVM will pick up this env and log that when starting. After that, Spring Boot will send json logs. All these logs are printed on stdout and will end up in the same file... two first rows:

Picked up JAVA_TOOL_OPTIONS: -Dfile.encoding=UTF-8 -Djava.security.egd=file:/dev/./urandom {"@timestamp":"2018-02-16T09:49:31.633+01:00","@version":1,"message":"Refreshing org.springframework.context.annotation.AnnotationConfigApplicationContext@47f37ef1: startup date [Fri Feb 16 09:49:31 CET 2018]; root of context hierarchy","logger_name":"org.springframework.context.annotation.AnnotationConfigApplicationContext","thread_name":"main","level_value":20000,"caller_class_name":"org.springframework.context.support.AbstractApplicationContext","caller_method_name":"prepareRefresh","caller_file_name":"AbstractApplicationContext.java","caller_line_number":583}

Running filebeat with config:

filebeat.prospectors:
- type: docker
paths:
- '/var/lib/docker/containers/*/*-json.log'
containers.ids: '*'
json.keys_under_root: true
json.add_error_key: true

2018-02-16T08:55:07.558Z ERROR reader/json.go:32 Error decoding JSON: invalid character 'P' looking for beginning of value

Expected behaviour would be to try json extraction, and log the message as it is if it fails... imho.

Change of prospector from docker to logs and use processor decode_json_fields doesn't work since the when condition isnt evaluated before it tries to parse it as json... it seems.

[ruflin]

Sounds like we should add a config option ignore_errors to not have the log file spammed?

[magnusheino]

Sounds great. I also get many of these:

{"level":"error","timestamp":"2018-02-19T08:40:33.968Z","caller":"reader/json.go:32","message":"Error decoding JSON: EOF"}

But thats the same thing I guess, and will be handled by ignore_errors?

[ruflin]

@magnusheino Looks like almost the same error. Do you get them in two different places?

[gmoskovicz]

@ruflin ++ on adding a ignore_errors to ignore things like JSON parsing . Perhaps we can set an array of errors to ignore ?

[ruflin]

@gmoskovicz You mean ignore_errors would contain a list of the type of errors that should be ignored? What are the types you had in mind?

[Tapppi]

So this is a regression from 5.x, where this error wasn't thrown.. Not a nice surprise when upgrading filebeat. We have a single prospector deployed as a daemonset (one filebeat per machine picking up all logs for that machine) to a kubernetes cluster, picking up all logs and preprocessing multiline from both json and non-json logs:

json.message_key: log
json.add_error_key: true
multiline.pattern: '^\s'
multiline.match: after

This is a direct replacement for fluentd, and allows nice logs to be persisted to kafka for logstash to later process. We cannot really use autodiscovery as we would have to document all components (100+) with whether they log json, and IMHO that's up to the containers, some of which are system components we don't have control over. The only possibility for us is to completely turn off logging in filebeat 😞

@ruflin some way to disable json errors e.g. json.ignore_errors: true is pretty critical for this use case. Now we are left with monitoring log output and then enabling logging if we suspect a problem with filebeat.

[ruflin]

I opened #6547 which introduces json.ignore_decoding_error config option. This should solve the log spamming. I made the config very specific to make it clear the decoding error is ignored. If there are other issues down the road, we can perhaps introduce a more generic config option.

[gmoskovicz]

Nice. Thanks for the heads up. Great addition!

[Tapppi]

🎉 Thanks for the quick turnaround!

[Tapppi]

@ruflin will that option be released in 6.2.5 or 6.3 or 7.x?

[ruflin]

@Tapppi 6.3 and 7.x

[joshuabaird]

@ruflin Is there any workaround in 6.2.4? These logs are killing my filebeat instances. I'm using the docker prospector:

filebeat.prospectors:
- type: docker
  containers.ids:
    - '*'
  json.ignore_decoding_error: true
  processors:
  - add_docker_metadata: ~
  - decode_json_fields:
      fields: ["message"]

I'm not even sure why these errors are being generated because all of my logs are JSON (using the json-files log driver):

2018-05-21T17:39:31.019Z	ERROR	reader/json.go:32	Error decoding JSON: json: cannot unmarshal number into Go value of type map[string]interface {}
2018-05-21T17:39:31.019Z	ERROR	reader/json.go:32	Error decoding JSON: json: cannot unmarshal number into Go value of type map[string]interface {}
2018-05-21T17:39:31.019Z	ERROR	reader/json.go:32	Error decoding JSON: json: cannot unmarshal number into Go value of type map[string]interface {}
2018-05-21T17:39:31.019Z	ERROR	reader/json.go:32	Error decoding JSON: json: cannot unmarshal number into Go value of type map[string]interface {}
2018-05-21T17:39:31.019Z	ERROR	reader/json.go:32	Error decoding JSON: json: cannot unmarshal number into Go value of type map[string]interface {}

If I use the log prospector instead of docker and specify the path as /var/lib/docker/containers/*/*.log, I do not get spammed with these messages. This is my workaround at the moment. Does this indicate an issue with the docker prospector?

Are Docker images for non-production releases (like 6.3) available?

[ruflin]

@joshuabaird There is unfortunately no workaround for 6.2 here. I'm wondering why you get the error you see. Could you open a topic on discuss for this, share what you shared above and add some example log lines? https://discuss.elastic.co/c/beats/filebeat

[joshuabaird]

Sure - https://discuss.elastic.co/t/problem-with-docker-prospector-and-error-decoding-json-logs/132828.

[n-forbes]

Hi @ruflin. I'm running version 6.4 of filebeat and have added json.ignore_decoding_error: true to my config but I'm still seeing JSON decoding error messages in my logs. We also enable json.add_error_key: true.

Should the code in the link below be an if-else statement, rather than two separate 'if' statements, to cater for the above scenario?

https://github.com/amomchilov/Filebeat/blob/master/harvester/reader/json.go#L32

[lucas-dehandschutter]

Hi,
I'm on the latest 6.5.4 version of filebeat and json.ignore_decoding_error: true is also not working.
I keep getting decoding errors.

[roysG]

Any fix or update?

[kvch]

I have tested it and cannot reproduce with the following configuration and input:

filebeat.inputs:
- type: log
  enabled: true

  paths:
    - test.log

  json.add_error_key: false
  json.ignore_decoding_error: true

output.console:
  enabled: true
  codec.json:
    pretty: true

test.json:

{"key": "value", "key2": "val

The code is also correct. json.ignore_decoding_error and json.add_error_key does not depend on each other, so separate if statements are correct.

My guess the problem is that ignor_decoding_error is missing from the reference configuration. Thus, you did not know that json. prefix is needed for all JSON-related options in the log input.

[n-forbes-SB]

@kvch Thank you for investigating. Our setup is slightly different; both json.add_error_key and json.ignore_decoding_error are set to true, which means that the error will be written to our logs. Is this an invalid setup?

[joshuabaird]

This still seems to be an issue with 6.6.1:

  "error": {
    "message": "Error decoding JSON: json: cannot unmarshal string into Go value of type map[string]interface {}",
    "type": "json"
  },

This is produced with the following config:

filebeat.inputs:
- type: docker
  containers.ids: '*'
  json.keys_under_root: true
  json.add_error_key: true
  json.message_key: log
  json.ignore_decoding_error: true
  processors:
  - add_docker_metadata: ~
  - add_cloud_metadata: ~
  - decode_json_fields:
      fields: ["log"]

Is the consensus here that json.add_error_key should be set to false as well as json.ignore_decoding_error: true?

[kvch]

@joshuabaird You have set json.add_error_key to true, thus the error is added to the event with the key "error". To eliminate all error messages, json.add_error_key needs to set to false and json.ignore_encoding_error to true so the errors don't show up in the logs.

On the other hand, I don't think you need the decode_json_fields processor in your configuration. You have already configured the JSON reader to parse everything under the key log.

[kvch]

@n-forbes-SB No, it is a valid setup. That's why we have two configuration options. Some people prefer to see errors in the event, some would like to see it in the logs.