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 infilebeat
operate on the contents of thelog
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?