Filebeat json formatted messages being indexed with 'null' message body

Graylog Central (peer support)
1

Graylog seems to be eating incoming messages from filebeat agents when the messages are formatted as json.

Here’s an example message that I extracted from the Graylog journal, so I know that filebeat is sending something sane:

{
  "@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"
  }
}

When I look at the message in Graylog, the message field is ‘null’. All other fields look normal.

My filebeat.yml prospectors & overall config looks like this:

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

If I turn off all the json.* options in the prospector, then I see the json message, formatted as a quoted string.

Graylog version is 2.3.1+9f2c6ef on Ubuntu 16.04. I’m happy to share any more details that might be relevant.

2

What’s in the logs of your Graylog nodes?
http://docs.graylog.org/en/2.4/pages/configuration/file_location.html

3

Not much, though I don’t have debug logging on:

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.
4

I tried an upgrade to the latest 2.4.3 and the same issue happens there.

I’ll file a bug on github to track this.

5

I filed a bug over in https://github.com/Graylog2/graylog2-server/issues/4667 to track this.

6

The issue I filed is in https://github.com/Graylog2/graylog2-server/issues/4667 - but as @jochen pointed out, it isn’t a Graylog issue.

7

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