Filebeat does not preserve `log.level` field of the event

[flexoid]

After switching to Elastic Cloud 7 we changed our logging schema to conform to Elastic Common Schema. Specifically, the original log level from the application goes to log.level instead of level (according to https://www.elastic.co/guide/en/ecs/current/ecs-log.html).

But looks like Filebeat completely replaces log object with the following and doesn't leave log.level.

log.file.path
log.offset

• Version: filebeat 7.0.1, elastic cloud 7.0.1
• Operating System: debian stretch
• Steps to Reproduce:
  1. Log event with log.level, e.g.

  { 
    "log":  { 
      "level": "DEBUG" 
    }
  }

  2. Find this document in ES - no log.level inside.

    { 
      "log":  { 
        "offset": 123456,
        "file": {
          "path": "/home/some/path.log"
        } 
      }
    }

[ruflin]

As we have here a "DeepUpdate" I would not expect this to happen: https://github.com/elastic/beats/blob/master/filebeat/input/log/harvester.go#L319

@flexoid Could you share your Filebeat config and an example log line?

[flexoid]

@ruflin
Just reproduced on simplified config:

filebeat.config.modules:
  path: ${path.config}/modules.d/*.yml
  reload.enabled: false

setup.template.settings:
  index.number_of_shards: 1

processors:
  - add_host_metadata: ~
  - add_cloud_metadata: ~

cloud.id: ***
cloud.auth: ***

filebeat.inputs:
- type: log
  enabled: true
  paths:
    - "/tmp/logs/*"
  fields_under_root: true
  json.keys_under_root: true
  json.add_error_key: true
  json.message_key: message
  json.ignore_decoding_error: true

setup.ilm.enabled: false

output.elasticsearch:
  enabled: true

logging.level: debug

Example log line:

echo '{"message":"hello elk","log":{"level": "debug"}}' >> /tmp/logs/test.log

Here is the part of filebeat log:

2019-05-04T11:38:25.007+0300	DEBUG	[processors]	processing/processors.go:183	Publish event: {
  "@timestamp": "2019-05-04T08:38:25.007Z",
  "@metadata": {
    "beat": "",
    "type": "_doc",
    "version": ""
  },
  "host": {
    "name": "***.local",
    "id": "E58FEE39-67C8-5276-816E-C56687B535EF",
    "hostname": "***.local",
    "architecture": "x86_64",
    "os": {
      "name": "Mac OS X",
      "kernel": "18.5.0",
      "build": "18E226",
      "platform": "Darwin",
      "version": "10.14.4",
      "family": "darwin"
    }
  },
  "agent": {
    "hostname": "***.local",
    "id": "89e0661e-3ed5-4a99-8f73-7056d637db33",
    "version": "7.0.1",
    "type": "filebeat",
    "ephemeral_id": "5f117ff0-881e-4abd-bb12-1c43b7a6b800"
  },
  "log": {
    "offset": 0,
    "file": {
      "path": "/tmp/logs/test.log"
    }
  },
  "message": "hello elk",
  "input": {
    "type": "log"
  },
  "ecs": {
    "version": "1.0.0"
  }
}

[ruflin]

I did a quick investigation into this as I think the problem lies here:

beats/libbeat/common/jsontransform/jsonhelper.go

Lines 33 to 35 in dcce078

	if _, exists := event.Fields[k]; !exists && k != "@timestamp" && k != "@metadata" {
	event.Fields[k] = v
	}

It checks if the key exists and if it is there, it will skip it. The check is correct as log indeed exists (it checks the top level object).

I think the logic here must be modified to check also sub keys. And then how the events are created must be modified: https://github.com/elastic/beats/blob/master/libbeat/common/jsontransform/jsonhelper.go#L34 and https://github.com/elastic/beats/blob/master/libbeat/common/jsontransform/jsonhelper.go#L88 Instead of overwriting the full object it should do a deep update or similar. Tried a quick fix which didn't work unfortunately.

[flexoid]

Hi. Is there any progress on this? It stops us from switching to ECS, which is the recommended logging schema for the filebeat now.

[pimjansen]

Agree, missing a lot of data here

[pimjansen]

@ruflin @andrewkroh any update on this? Its a bug which is there since march already. Is this going to be patched or will it be kept and patched at the beats agent? Since for now we cant properly log according the ECS schema

[ruflin]

@urso @andresrc Perhaps you can chime in here?