# Log entries gathered by filebeat in EKS are occasionally joined

**URL:** <https://discuss.elastic.co/t/log-entries-gathered-by-filebeat-in-eks-are-occasionally-joined/244074>\
**Category:** Beats\
**Tags:** filebeat\
**Created:** [August 6, 2020, 5:37pm UTC](https://discuss.elastic.co/t/log-entries-gathered-by-filebeat-in-eks-are-occasionally-joined/244074 "2020-08-06T17:37:53Z")\
**Posts on this page:** 3\
**Page:** 1

<div class="post-metadata">

**Author:** ![DougR](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/dougr/32/48095_2.png) [@DougR](https://discuss.elastic.co/u/DougR)\
**Post date:** [August 6, 2020, 5:37pm UTC](https://discuss.elastic.co/t/log-entries-gathered-by-filebeat-in-eks-are-occasionally-joined/244074/1 "2020-08-06T17:37:54Z")

</div>

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

```auto
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.

```json
{"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:

```json
{
  "_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.:

```json
{"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?

---

<div class="post-metadata">

**Author:** ![DougR](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/dougr/32/48095_2.png) [@DougR](https://discuss.elastic.co/u/DougR)\
**Post date:** [August 25, 2020, 2:57pm UTC](https://discuss.elastic.co/t/log-entries-gathered-by-filebeat-in-eks-are-occasionally-joined/244074/3 "2020-08-25T14:57:47Z")

</div>

The solution here appears to be to use [filebeat autodiscover](https://www.elastic.co/guide/en/beats/filebeat/current/configuration-autodiscover.html). Individual configs can then be written, per normal filebeat config rules.

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

My `filebeat.yml` looks like:

```auto
---
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:

```auto
---
- 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'

```

---

<div class="post-metadata">

**Author:** ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)\
**Post date:** [September 22, 2020, 4:57pm UTC](https://discuss.elastic.co/t/log-entries-gathered-by-filebeat-in-eks-are-occasionally-joined/244074/4 "2020-09-22T16:57:49Z")

</div>

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