Investigate number of debug messages of add_kubernetes_metadata processor

[gizas]

Filebeat in logging debug mode was reported that returns erroneous number of debug messages. Investigate why we report so many messages and see if we can remove some of them

• Filebeat Input: input.filestream
• Beats version reported: 7.17.0

Filebeat sample config:

filebeat.config:
      modules:
        path: ${path.config}/modules.d/*.yml
        reload.enabled: false
    filebeat.inputs:
    - file_identity.fingerprint: null
      id: cinit-app-filebeat-containers
      type: filestream
      prospector.scanner:
        check_interval: 2s
        fingerprint:
          enabled: true
          length: 512
          offset: 0
        symlinks: true
      paths:
      - /var/log/containers/dtp-log-gen*.log
      parsers:
      - container:
          format: cri
          stream: all 

[belimawr]

I just remembered this issue and PR:

• https://github.com/elastic/beats/issues/34717
• https://github.com/elastic/beats/pull/35645

Could they be the root cause for this behaviour? At least the PR did not get backported to 7.17 because it looked like a 8.x issue.

[belimawr]

I was running the a build from Elastic-Agent + Beats from last week, and when setting the log level to debug, the add_kubernetes_metadata processor from Filebeat flooded the logs.

In a 20s window, 35286 log entries were generated by Filebeat, from those 35200 were:

Skipping add_kubernetes_metadata processor as kubernetes metadata already exist

Full log entry

{
  "log.level": "debug",
  "@timestamp": "2024-05-31T16:06:17.262Z",
  "message": "Skipping add_kubernetes_metadata processor as kubernetes metadata already exist",
  "component": {
    "binary": "filebeat",
    "dataset": "elastic_agent.filebeat",
    "id": "filestream-default",
    "type": "filestream"
  },
  "log": {
    "source": "filestream-default"
  },
  "log.logger": "kubernetes",
  "log.origin": {
    "file.line": 314,
    "file.name": "add_kubernetes_metadata/kubernetes.go",
    "function": "github.com/elastic/beats/v7/libbeat/processors/add_kubernetes_metadata.(*kubernetesAnnotator).Run"
  },
  "service.name": "filebeat",
  "libbeat.processor": "add_kubernetes_metadata",
  "ecs.version": "1.6.0"
}

I tested and saw the same behaviour from the latest release, v8.13.4.

If needed, I can provide the diagnostics and logs.

[cmacknz]

Skipping add_kubernetes_metadata processor as kubernetes metadata already exist

This log message seems like it should just be removed or replaced with a counter.

[belimawr]

Skipping add_kubernetes_metadata processor as kubernetes metadata already exist

This log message seems like it should just be removed or replaced with a counter.

But what would we do with this counter?

I don't know much about this processor, but it feels like the message could be removed.

I'm still puzzled by the number of messages on a cluster I had just started. I had other cases with even more messages in a 20s time period. I wonder if that is causing Filebeat to go into a loop of logging something, collecting it, logging more lines about that event, and so on. :thinking: