Log entries gathered by filebeat in EKS are occasionally joined

TL;DR

Some messages are merging when using filebeat container input.

Issue

When I'm using the filebeat container input, some log messages occasionally merge into a single message. I am running the filebeat in EKS, deploying via the Elastic helm chart, managed by Ansible.

So far, I've only found this issue with log messages that the filebeat pod captures from itself, however I would like to resolve it, in order to avoid it impacting anything else.

Using Elasticsearch/Logstash/Kibana 7.8.0, with filebeat 7.8.1.

filebeat.yml

Here's my filebeat.yml. Note that it is a logstash output, but there are no pipeline rules that modify the record before forwarding on to Elasticsearch.

filebeat:
  inputs:
    - type: 'container'
      paths:
        - '/var/lib/docker/containers/*/*.log'
      multiline:
        pattern: '^\{'
        negate: true
        match: 'after'
      processors:
        - add_kubernetes_metadata: ~
logging:
  # Minimum log level. One of debug, info, warning, or error. The
  # default log level is info.
  level: 'info'
output:
  logstash:
    hosts:
      - 'logstash'
    index: 'filebeat'
    ssl:
      enabled: true
      verification_mode: 'none'

Raw logs

Here are sample copies of raw log messages that are being joined. Note that this is the exception, not the rule, for log messages being gathered by this filebeat. So far the only joined messages I've found are these specific messages, at filebeat startup. However, these messages are joined at every filebeat startup.

{"log":"2020-08-06T15:04:17.229Z\u0009WARN\u0009beater/filebeat.go:156\u0009Filebeat is unable to load the Ingest Node pipelines for the configured modules because the Elasticsearch output is not configured/enabled. If you have already loaded the Ingest Node pipelines or are using Logstash pipelines, you can ignore this warning.\n","stream":"stderr","time":"2020-08-06T15:04:17.229286288Z"}
{"log":"2020-08-06T15:04:17.229Z\u0009WARN\u0009beater/filebeat.go:339\u0009Filebeat is unable to load the Ingest Node pipelines for the configured modules because the Elasticsearch output is not configured/enabled. If you have already loaded the Ingest Node pipelines or are using Logstash pipelines, you can ignore this warning.\n","stream":"stderr","time":"2020-08-06T15:04:17.229415355Z"}

Record _source

Here's the _source for the record, as shown by Kibana. As you can see, it merged the two messages (above) into a single message, in the "message" field:

{
  "_index": "filebeat-7.8.1-000001",
  "_type": "_doc",
  "_id": "h9pNxHMBvxuBFyrHPjXr",
  "_version": 1,
  "_score": null,
  "_source": {
    "ecs": {
      "version": "1.5.0"
    },
    "stream": "stderr",
    "input": {
      "type": "container"
    },
    "message": "2020-08-06T15:04:17.229Z\tWARN\tbeater/filebeat.go:156\tFilebeat is unable to load the Ingest Node pipelines for the configured modules because the Elasticsearch output is not configured/enabled. If you have already loaded the Ingest Node pipelines or are using Logstash pipelines, you can ignore this warning.\n2020-08-06T15:04:17.229Z\tWARN\tbeater/filebeat.go:339\tFilebeat is unable to load the Ingest Node pipelines for the configured modules because the Elasticsearch output is not configured/enabled. If you have already loaded the Ingest Node pipelines or are using Logstash pipelines, you can ignore this warning.",
    "@timestamp": "2020-08-06T15:04:17.229Z",
    "@version": "1",
    "host": {
      "name": "filebeat-88982"
    },
    "application": {
      "name": "elk",
      "env": "prod"
    },
    "kubernetes": {
      "container": {
        "image": "docker.elastic.co/beats/filebeat:7.8.1",
        "name": "filebeat"
      },
      "node": {
        "name": "ip-10-1-2-3.ec2.internal"
      },
      "namespace": "elk",
      "pod": {
        "uid": "6a1602e4-f5f0-4998-97b7-4013d31672b7",
        "name": "filebeat-88982"
      },
      "labels": {
        "controller-revision-hash": "66787f9d66",
        "release": "filebeat",
        "heritage": "Helm",
        "chart": "filebeat-7.8.1",
        "pod-template-generation": "9",
        "app": "filebeat"
      }
    },
    "agent": {
      "type": "filebeat",
      "name": "filebeat-88982",
      "version": "7.8.1",
      "hostname": "filebeat-88982",
      "ephemeral_id": "c5b8a14d-b134-4690-bb84-2267fc1ccf43",
      "id": "0c0615a3-18e3-44e6-ac21-6b3738752b68"
    },
    "tags": [
      "beats_input_codec_plain_applied"
    ],
    "log": {
      "flags": [
        "multiline"
      ],
      "level": "WARN",
      "offset": 0,
      "file": {
        "path": "/var/lib/docker/containers/74c219d9965950660c537643efa2b8065a3e9e8b5e329e68c3c5fc7a90b8c904/74c219d9965950660c537643efa2b8065a3e9e8b5e329e68c3c5fc7a90b8c904-json.log"
      }
    }
  },
  "fields": {
    "cef.extensions.flexDate1": [],
    "netflow.flow_end_microseconds": [],
    "netflow.system_init_time_milliseconds": [],
    "netflow.flow_end_nanoseconds": [],
    "misp.observed_data.last_observed": [],
    "netflow.max_flow_end_microseconds": [],
    "file.mtime": [],
    "aws.cloudtrail.user_identity.session_context.creation_date": [],
    "netflow.min_flow_start_seconds": [],
    "misp.intrusion_set.first_seen": [],
    "file.created": [],
    "misp.threat_indicator.valid_from": [],
    "process.parent.start": [],
    "azure.auditlogs.properties.activity_datetime": [],
    "crowdstrike.event.ProcessStartTime": [],
    "zeek.ocsp.update.this": [],
    "crowdstrike.event.IncidentStartTime": [],
    "netflow.observation_time_microseconds": [],
    "event.start": [],
    "cef.extensions.agentReceiptTime": [],
    "cef.extensions.oldFileModificationTime": [],
    "checkpoint.subs_exp": [],
    "event.end": [],
    "netflow.max_flow_end_milliseconds": [],
    "netflow.min_flow_start_nanoseconds": [],
    "zeek.smb_files.times.changed": [],
    "crowdstrike.event.StartTimestamp": [],
    "netflow.flow_start_nanoseconds": [],
    "netflow.flow_start_seconds": [],
    "crowdstrike.event.ProcessEndTime": [],
    "zeek.x509.certificate.valid.until": [],
    "misp.observed_data.first_observed": [],
    "netflow.exporter.timestamp": [],
    "netflow.monitoring_interval_start_milli_seconds": [],
    "cef.extensions.oldFileCreateTime": [],
    "event.ingested": [],
    "@timestamp": [
      "2020-08-06T15:04:17.229Z"
    ],
    "zeek.ocsp.update.next": [],
    "crowdstrike.event.UTCTimestamp": [],
    "tls.server.not_before": [],
    "cef.extensions.startTime": [],
    "netflow.min_flow_start_milliseconds": [],
    "azure.signinlogs.properties.created_at": [],
    "cef.extensions.endTime": [],
    "suricata.eve.tls.notbefore": [],
    "zeek.kerberos.valid.from": [],
    "cef.extensions.fileCreateTime": [],
    "misp.threat_indicator.valid_until": [],
    "crowdstrike.event.EndTimestamp": [],
    "misp.campaign.last_seen": [],
    "cef.extensions.deviceReceiptTime": [],
    "netflow.observation_time_seconds": [],
    "crowdstrike.metadata.eventCreationTime": [],
    "cef.extensions.fileModificationTime": [],
    "tls.client.not_before": [],
    "zeek.smb_files.times.created": [],
    "zeek.smtp.date": [],
    "netflow.collection_time_milliseconds": [],
    "zeek.pe.compile_time": [],
    "netflow.max_flow_end_seconds": [],
    "tls.client.not_after": [],
    "netflow.flow_start_milliseconds": [],
    "event.created": [],
    "package.installed": [],
    "zeek.kerberos.valid.until": [],
    "suricata.eve.flow.end": [],
    "netflow.observation_time_milliseconds": [],
    "netflow.flow_start_microseconds": [],
    "tls.server.not_after": [],
    "netflow.flow_end_seconds": [],
    "process.start": [],
    "suricata.eve.tls.notafter": [],
    "zeek.snmp.up_since": [],
    "azure.enqueued_time": [],
    "netflow.max_flow_end_nanoseconds": [],
    "misp.intrusion_set.last_seen": [],
    "netflow.min_flow_start_microseconds": [],
    "netflow.observation_time_nanoseconds": [],
    "cef.extensions.managerReceiptTime": [],
    "file.accessed": [],
    "netflow.flow_end_milliseconds": [],
    "misp.campaign.first_seen": [],
    "netflow.min_export_seconds": [],
    "suricata.eve.flow.start": [],
    "suricata.eve.timestamp": [
      "2020-08-06T15:04:17.229Z"
    ],
    "cef.extensions.deviceCustomDate1": [],
    "cef.extensions.deviceCustomDate2": [],
    "netflow.monitoring_interval_end_milli_seconds": [],
    "file.ctime": [],
    "crowdstrike.event.IncidentEndTime": [],
    "zeek.smb_files.times.accessed": [],
    "zeek.ocsp.revoke.time": [],
    "zeek.x509.certificate.valid.from": [],
    "netflow.max_export_seconds": [],
    "zeek.smb_files.times.modified": [],
    "kafka.block_timestamp": [],
    "misp.report.published": []
  },
  "highlight": {
    "kubernetes.pod.name": [
      "@kibana-highlighted-field@filebeat-88982@/kibana-highlighted-field@"
    ]
  },
  "sort": [
    1596726257229
  ]
}

Updates

Update #1

As I dive deeper into the raw logs, it appears that Kubernetes may actually be writing the individual lines of multi-line entries as individual lines in the output stream. I.e.:

{"log":"\"at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2276) [guava-25.1-jre.jar:?]\",\n","stream":"stdout","time":"2020-08-06T15:20:50.519566741Z"}
{"log":"\"at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2154) [guava-25.1-jre.jar:?]\",\n","stream":"stdout","time":"2020-08-06T15:20:50.519568996Z"}
{"log":"\"at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2044) [guava-25.1-jre.jar:?]\",\n","stream":"stdout","time":"2020-08-06T15:20:50.519571266Z"}
{"log":"\"at com.google.common.cache.LocalCache.get(LocalCache.java:3951) [guava-25.1-jre.jar:?]\",\n","stream":"stdout","time":"2020-08-06T15:20:50.519573523Z"}
{"log":"\"at com.google.common.cache.LocalCache$LocalManualCache.get(LocalCache.java:4870) [guava-25.1-jre.jar:?]\",\n","stream":"stdout","time":"2020-08-06T15:20:50.519575878Z"}

...and that my multi-line pattern (above) may be concatenating these into a single entry...but only if they're in a JSON structure. This leads to two questions:

  • Is this correct, does the multiline rule in filebeat operate on the contents of the log field?
  • If so, is there any way to resolve this, short of writing an individual container input for each container ID, which will change at every deployment anyway?

The solution here appears to be to use filebeat autodiscover. Individual configs can then be written, per normal filebeat config rules.

It's almost as if someone else has encountered this issue before. :smile:

My filebeat.yml looks like:

---
filebeat:
  autodiscover:
    providers:
      path: '${path.config}/providers.d/*.yml'
      reload:
        enabled: false

logging:
  # Minimum log level. One of debug, info, warning, or error. The
  # default log level is info.
  level: 'info'
output:
  logstash:
    hosts:
      - 'logstash'
    index: 'filebeat'
    ssl:
      enabled: true
      verification_mode: 'none'

and my provider.yml is:

---
- type: 'kubernetes'
  templates:
    - condition:
        and:
          - equals:
              kubernetes.namespace: 'mynamespace'
          - equals:
              kubernetes.container.image: 'myimage'
      config:
        - type: 'container'
          paths: '/var/lib/docker/containers/${data.docker.container.id}/*.log'
          multiline:
            pattern: '^[\{\[]'
            negate: true
            match: 'after'
      processors:
        - add_locale:
            format: 'offset'

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