Filebeat json formatted messages being indexed with ‘null’ message body

[jamonation]

Expected Behavior

Graylog should extract and display the contents on json formatted messages from a filebeat prospector source. I posted over in https://community.graylog.org/t/filebeat-json-formatted-messages-being-indexed-with-null-message-body/4570/4 but I think there's a bug somewhere.

Current Behavior

When I look at a filebeat originated log entry in Graylog, the message field is ‘null’. All other fields look normal. If I change the prospector to disable json, then I see the whole message contents in Graylog as a quoted string.

I can see the incoming messages from remote filebeat inputs in the local graylog journal, so I know the issue is somewhere on the graylog side of things, e.g.:

{
  "@timestamp":"2018-03-14T15:27:15.620Z",
  "@metadata":
  {"beat":"filebeat",
   "type":"doc",
   "version":"6.2.0"
  },
  "source":"/var/log/containers/nginx-ingress-controller-4t8tj_default_nginx-ingress-lb-55e1711059a4e25263dc776efa6e6b196bfe48b36358ee03c2b42d0bee9d3f0c.log",
  "offset":4544121886,
  "message":"{\"log\":\"<snip> - [<snip>] - - [14/Mar/2018:15:27:15 +0000] \\\"GET <snip> HTTP/1.1\\\" 301 194 \\\"-\\\" \\\"-\\\" 205 0.002 [<snip>] 10.86.103.88:80 194 0.002 301\\n\",\"stream\":\"stdout\",\"time\":\"2018-03-14T15:27:15.578592705Z\"}",
  "type":"kube-logs",
  "beat":
  {"version":"6.2.0",
   "name":"kubernetes-worker/0",
   "hostname":"kubernetes-worker-0"
  }
}

Steps to Reproduce (for bugs)

filebeat.yml contents, note the json.message_key: log json.keys_under_root: true and json.add_error_key: true lines. If any are enabled, the message is 'null'.

filebeat:
  prospectors:
    -
      paths:
        - /var/log/*.log
        - /var/log/syslog
        - /var/log/*/*.log        
      input_type: log
      exclude_files: [".gz$"]
      exclude_lines: []
      scan_frequency: 10s
      harvester_buffer_size: 16384
      max_bytes: 10485760
    -
      paths:
        - /var/log/containers/*.log
      exclude_files: ["filebeat.*log", "kube.*log"]
      scan_frequency: 10s
      harvester_buffer_size: 16384
      max_bytes: 10485760
      fields_under_root: true
      symlinks: true
      json.message_key: log
      json.keys_under_root: true
      json.add_error_key: true
      multiline.pattern: '^\s'
      multiline.match: after
      fields:
        type: kube-logs
 registry_file: /var/lib/filebeat/registry

logging:
  to_syslog: true
  metrics.enabled: false

output:
  logstash:
    hosts:
      - "<snip>:5044"      
    worker: 1
    compression_level: 3
    loadbalance: true

name: kubernetes-worker/0

Context

Trying to aggregate and view logs from a kubernetes cluster using filebeat to ship logs.

Your Environment

• Graylog Version: 2.3.1+9f2c6ef, and tested with 2.4.3, same issue
• Elasticsearch Version: 2.4.5
• MongoDB Version: 2.6.10-0ubuntu1
• Operating System: Ubuntu 16.04.4 LTS
• Browser version: Firefox 60.0b4 developer edition

Logs from graylog:

2018-03-14T11:32:10.454Z INFO  [MongoIndexSet] Cycling from <graylog_49> to <graylog_50>.
2018-03-14T11:32:10.454Z INFO  [MongoIndexSet] Creating target index <graylog_50>.
2018-03-14T11:32:10.509Z INFO  [Indices] Successfully created index template graylog-internal
2018-03-14T11:32:10.653Z INFO  [MongoIndexSet] Waiting for allocation of index <graylog_50>.
2018-03-14T11:32:10.753Z INFO  [MongoIndexSet] Index <graylog_50> has been successfully allocated.
2018-03-14T11:32:10.754Z INFO  [MongoIndexSet] Pointing index alias <graylog_deflector> to new index <graylog_50>.
2018-03-14T11:32:10.777Z INFO  [SystemJobManager] Submitted SystemJob <55bdc180-277b-11e8-b3f6-42fa67b8e8eb> [org.graylog2.indexer.indices.jobs.SetIndexReadOnlyAndCalculateRangeJob]
2018-03-14T11:32:10.777Z INFO  [MongoIndexSet] Successfully pointed index alias <graylog_deflector> to index <graylog_50>.
2018-03-14T11:32:30.459Z INFO  [AbstractIndexCountBasedRetentionStrategy] Number of indices (8) higher than limit (7). Running retention for 1 indices.
2018-03-14T11:32:30.493Z INFO  [AbstractIndexCountBasedRetentionStrategy] Running retention strategy [org.graylog2.indexer.retention.strategies.DeletionRetentionStrategy] for index <graylog_43>
2018-03-14T11:32:30.721Z INFO  [DeletionRetentionStrategy] Finished index retention strategy [delete] for index <graylog_43> in 227ms.
2018-03-14T11:32:40.807Z INFO  [SetIndexReadOnlyJob] Flushing old index <graylog_49>.
2018-03-14T11:32:41.300Z INFO  [SetIndexReadOnlyJob] Setting old index <graylog_49> to read-only.
2018-03-14T11:32:41.327Z INFO  [SystemJobManager] Submitted SystemJob <67f377f0-277b-11e8-b3f6-42fa67b8e8eb> [org.graylog2.indexer.indices.jobs.OptimizeIndexJob]
2018-03-14T11:32:41.333Z INFO  [CreateNewSingleIndexRangeJob] Calculating ranges for index graylog_49.
2018-03-14T11:32:41.334Z INFO  [OptimizeIndexJob] Optimizing index <graylog_49>.
2018-03-14T11:32:42.747Z INFO  [MongoIndexRangeService] Calculated range of [graylog_49] in [1411ms].
2018-03-14T11:32:42.749Z INFO  [CreateNewSingleIndexRangeJob] Created ranges for index graylog_49.
2018-03-14T11:32:42.749Z INFO  [SystemJobManager] SystemJob <55bdc180-277b-11e8-b3f6-42fa67b8e8eb> [org.graylog2.indexer.indices.jobs.SetIndexReadOnlyAndCalculateRangeJob] finished in 1972ms.
2018-03-14T11:36:47.331Z INFO  [SystemJobManager] SystemJob <67f377f0-277b-11e8-b3f6-42fa67b8e8eb> [org.graylog2.indexer.indices.jobs.OptimizeIndexJob] finished in 246003ms.

I tried with debug level logging, but a) volume was enormous, and b) nothing seemed amiss (no warnings or errors).

There are no pipelines setup for these logs, and as I mentioned, entries do show up if json is disabled.

[joschi]

@jamonation json.keys_under_root: true isn't supported by version 2.x of the Beats plugin because it expects a field named "message" in the root of the JSON payload (which isn't there when you enable the json.keys_under_root setting).
You'll have to disable that setting if you want to ingest these messages into Graylog.

Refs Graylog2/graylog-plugin-beats#3

[axinojolais]

@joschi this is actually incorrect. json.keys_under_root has no impact on the existence of the message field. As soon as you set json.message_key, the message field gets replaced, either by the json field (if json.keys_under_root is false), or by the key specified in json.message_key (if json.keys_under_root is true).

That's a problem on the filebeat side though. Thanks for the update !