[Filebeat] Elasticsearch Module w/ Kubernetes Autodiscover Causes Logs in Incorrect Fieldsets

[SpencerLN]

Issue: Using the Filebeat Elasticsearch module in combination with Kubernetes autodiscover results in logs in the incorrect filesets or duplicate filesets:

Expected behavior: Each log message should only appear in the destination a single time, and it should have the appropriate fields associated with the fileset of that log (i.e. server, audit, deprecation, gc, etc.)

• Version: 7.6.0
• Operating System: GKE Container Optimized OS
• Steps to Reproduce:
  Deploying Filebeat using Filebeat Helm chart with values.yaml:

filebeat: 
  # Allows you to add any config files in /usr/share/filebeat
  # such as filebeat.yml
  filebeatConfig:
    filebeat.yml: |-
      filebeat.autodiscover:
       providers:
         - type: kubernetes
           node: ${NODE_NAME}
           hints.enabled: true

      processors:
        - add_cloud_metadata:
        - add_host_metadata:

      output.elasticsearch:
          hosts: 'http://${ELASTICSEARCH_ADDRESS}'
          username: ${ELASTICSEARCH_USERNAME}
          password: ${ELASTICSEARCH_PASSWORD}

  extraEnvs:
    - name: ELASTICSEARCH_USERNAME
      valueFrom: { secretKeyRef: { name: beats-elasticsearch, key: username } }
    - name: ELASTICSEARCH_PASSWORD
      valueFrom: { secretKeyRef: { name: beats-elasticsearch, key: password } }
    - name: ELASTICSEARCH_ADDRESS
      valueFrom: { secretKeyRef: { name: beats-elasticsearch, key: address } }

  imageTag: 7.6.0
  extraVolumeMounts: 
    - name: varlog
      mountPath: /var/log/
      readOnly: true

  extraVolumes: 
    - name: varlog
      hostPath:
        path: /var/log/

In this case Elasticsearch was deployed using ECK, with annotations in the podTemplate to enable the Elasticsearch module:

    podTemplate:
      metadata:
        annotations:
          co.elastic.logs/module: "elasticsearch"

I am attaching the filebeat.log file, the json of the documents from the above screenshot, and the contents of the bulk request that show the documents are being to the corresponding pipelines for each fileset (4 copies of the same document).

The appropriate pipelines were installed in Elasticsearch prior to these logs being ingested:

filebeat.log
bulk_request.txt
sample-docs.txt

[ycombinator]

As a first step it would be good to try to reproduce this with Elasticsearch simply running in a Docker container and pointing Filebeat to it's logs. That is, if we can reproduce this without k8s or autodisovery in the picture, it might let us narrow down the source of the problem.

[blakerouse]

Can you try 7.x or master? I believe you might get a different behavior with this change #16450, but I could be wrong. I remember when working on that change that multiple filesets where getting merged.

I think the issue here is that autodiscovery only reads from the container log, which is a single log file, it will not read from logs inside of the container. With merging the paths are replaced with the container log path and not the actual path inside of the container.

[SpencerLN]

@ycombinator I can spin up an Elasticsearch node and point Filebeat to it's logs, but I am having trouble figuring out what the filebeat.yml config file to accomplish that would look like without using autodiscover.

Is this what you are suggesting for the test?

filebeat.yml:

filebeat.inputs:
- type: log
  enabled: false
  paths:
    - /var/log/*.log
filebeat.config.modules:
  path: ${path.config}/modules.d/*.yml
  reload.enabled: false
output.elasticsearch:
  hosts: ["https://elasticsearch:9200"]
  username: "username"
  password: "password"

modules.d/elasticsearch.yml:

- module: elasticsearch
  # Server log
  server:
    input:
      type: container
      paths:
	- '/var/lib/docker/containers/*/*.log'
    enabled: true

  gc:
    input:
      type: container
      paths:
	- '/var/lib/docker/containers/*/*.log'
    enabled: true

  audit:
    input:
      type: container
      paths:
	- '/var/lib/docker/containers/*/*.log'
    enabled: true

  slowlog:
    input:
      type: container
      paths:
	- '/var/lib/docker/containers/*/*.log'
    enabled: true

  deprecation:
    input:
      type: container
      paths:
	- '/var/lib/docker/containers/*/*.log'
    enabled: true

[SpencerLN]

Ok, I did some testing with the above config and got better results than I was seeing in Kubernetes. The only fileset that ended up with unexpected data was the gc fileset:

Log output from yml based module config:

Feb 25 17:41:17 spencer-docker-test-rhel7 filebeat[9743]: 2020-02-25T17:41:17.751Z        INFO        log/input.go:152        Configured paths: [/var/lib/docker/containers/*/*.log /var/log/elasticsearch/gc.log]
Feb 25 17:41:17 spencer-docker-test-rhel7 filebeat[9743]: 2020-02-25T17:41:17.759Z        INFO        log/input.go:152        Configured paths: [/var/lib/docker/containers/*/*.log /var/log/elasticsearch/*_server.json]
Feb 25 17:41:17 spencer-docker-test-rhel7 filebeat[9743]: 2020-02-25T17:41:17.767Z        INFO        log/input.go:152        Configured paths: [/var/lib/docker/containers/*/*.log /var/log/elasticsearch/*_index_indexing_slowlog.log /var/log/elasticsearch/*_index_search_slowlog.json /var/log/elasticsearch/*_index_indexing_slowlog.json]
Feb 25 17:41:17 spencer-docker-test-rhel7 filebeat[9743]: 2020-02-25T17:41:17.773Z        INFO        log/input.go:152        Configured paths: [/var/lib/docker/containers/*/*.log /var/log/elasticsearch/*_audit.log /var/log/elasticsearch/*_audit.json]
Feb 25 17:41:17 spencer-docker-test-rhel7 filebeat[9743]: 2020-02-25T17:41:17.780Z        INFO        log/input.go:152        Configured paths: [/var/lib/docker/containers/*/*.log /var/log/elasticsearch/*_deprecation.json]

I then tested using the docker autodiscover provider:

filebeat.autodiscover:
  providers:
    - type: docker
      hints.enabled: true

Log output from docker autodiscover config:

Feb 25 17:03:41 spencer-docker-test-rhel7 filebeat[7830]: 2020-02-25T17:03:41.382Z        INFO        log/input.go:152        Configured paths: [/var/lib/docker/containers/8ac09baaa513a56e4a6e7d10dbf42324936ee129dfaa645cf87ca3e40ff5974d/*-json.log /var/log/elasticsearch/*_audit.log /var/log/elasticsearch/*_audit.json]
Feb 25 17:03:41 spencer-docker-test-rhel7 filebeat[7830]: 2020-02-25T17:03:41.383Z        INFO        log/input.go:152        Configured paths: [/var/lib/docker/containers/8ac09baaa513a56e4a6e7d10dbf42324936ee129dfaa645cf87ca3e40ff5974d/*-json.log /var/log/elasticsearch/*_deprecation.json]
Feb 25 17:03:41 spencer-docker-test-rhel7 filebeat[7830]: 2020-02-25T17:03:41.384Z        INFO        log/input.go:152        Configured paths: [/var/lib/docker/containers/8ac09baaa513a56e4a6e7d10dbf42324936ee129dfaa645cf87ca3e40ff5974d/*-json.log /var/log/elasticsearch/gc.log]
Feb 25 17:03:41 spencer-docker-test-rhel7 filebeat[7830]: 2020-02-25T17:03:41.384Z        INFO        log/input.go:152        Configured paths: [/var/lib/docker/containers/8ac09baaa513a56e4a6e7d10dbf42324936ee129dfaa645cf87ca3e40ff5974d/*-json.log /var/log/elasticsearch/*_server.json]
Feb 25 17:03:41 spencer-docker-test-rhel7 filebeat[7830]: 2020-02-25T17:03:41.385Z        INFO        log/input.go:152        Configured paths: [/var/lib/docker/containers/8ac09baaa513a56e4a6e7d10dbf42324936ee129dfaa645cf87ca3e40ff5974d/*-json.log /var/log/elasticsearch/*_index_indexing_slowlog.log /var/log/elasticsearch/*_index_search_slowlog.json /var/log/elasticsearch/*_ind
ex_indexing_slowlog.json]

For the Docker autodiscover provider I got the same results as I did with manually configuring the module in the previous test, where only the gc fileset contained data that it shouldn't.

Taking this same config, I deployed it to Kubernetes:

filebeat.autodiscover:
 providers:
   - type: kubernetes
     node: ${NODE_NAME}
     hints.enabled: true

This resulted in again seeing log entries in random filesets in Elasticsearch:

Log output from kubernetes autodiscover config:

2020-02-25T17:31:42.276Z	INFO	log/input.go:152	Configured paths: [/var/lib/docker/containers/0cb79921b0530ae342e032560da511e1478a2ff6aa02d01a69038c1fdfe93da8/*-json.log /var/log/elasticsearch/*_index_indexing_slowlog.log /var/log/elasticsearch/*_index_search_slowlog.json /var/log/elasticsearch/*_index_indexing_slowlog.json]
2020-02-25T17:31:42.276Z	INFO	log/input.go:152	Configured paths: [/var/lib/docker/containers/0cb79921b0530ae342e032560da511e1478a2ff6aa02d01a69038c1fdfe93da8/*-json.log /var/log/elasticsearch/*_audit.log /var/log/elasticsearch/*_audit.json]
2020-02-25T17:31:42.277Z	INFO	log/input.go:152	Configured paths: [/var/lib/docker/containers/0cb79921b0530ae342e032560da511e1478a2ff6aa02d01a69038c1fdfe93da8/*-json.log /var/log/elasticsearch/*_deprecation.json]
2020-02-25T17:31:42.278Z	INFO	log/input.go:152	Configured paths: [/var/lib/docker/containers/0cb79921b0530ae342e032560da511e1478a2ff6aa02d01a69038c1fdfe93da8/*-json.log /var/log/elasticsearch/gc.log]
2020-02-25T17:31:42.278Z	INFO	log/input.go:152	Configured paths: [/var/lib/docker/containers/0cb79921b0530ae342e032560da511e1478a2ff6aa02d01a69038c1fdfe93da8/*-json.log /var/log/elasticsearch/*_server.json]

In all 3 cases, the GC logs were an issue and logs that were not GC logs ended up in the GC fileset. Only the Kubernetes autodiscover test resulted in the additional issues where we saw the log entries erroneously appear in the deprecation, audit, server, etc. filesets.

[ycombinator]

Thanks for the superbly detailed breakdown, @SpencerLN — appreciate it!

So it seems like there are two distinct issues here we need to address:

• Teach the elasticsearch/gc fileset to only ingest GC logs. Filed [Filebeat] Elasticsearch gc fileset collects non-GC logs in container environment #16583 to separately track and resolve this.
• Look into why k8s autodiscover is causing random logs to "crossover" to other Elasticsearch module filesets. For this one, it might be good to also understand if this behavior is specific to the Elasticsearch module or if it happens with any Filebeat modules.

[SpencerLN]

@ycombinator I did some additional testing tonight and found that if I disable the default_config for Kubernetes autodiscover, I no longer see the unexpected behavior, and have identical results as I did in Docker.

      filebeat.autodiscover:
       providers:
         - type: kubernetes
           node: ${NODE_NAME}
           hints.enabled: true
           hints.default_config.enabled: false

Unfortunately, this isn't an ideal configuration, since we do want to collect logs from Pods that we don't necessarily control and cannot always annotate. That said, hopefully it helps in narrowing the cause of the issue.

We are also running the Kibana module via Kubernetes autodiscover and don't seem to see the same problems there, but the Kibana module only has one fileset, so I am not sure if that is a factor or not.

Let me know if there is more verbose logging level for a certain component of filebeat that would provide additional helpful information.

Thanks!

[ycombinator]

Thanks again @SpencerLN, this does help narrow it down!

@blakerouse Do you want to tackle the k8s bits or file an issue for it and reference it in #16540 (comment)? Then we can treat this issue here as a meta issue for the two separate issues referenced from that comment.

[blakerouse]

I think this bug covers the issue for the autodiscover, so lets keep this issue open.