how do I troubleshoot this warning: failed to flush chunk '1-1712830947.947063732.flb'

[henkoch]

Hi

How do I troubleshoot this error: [2024/04/11 10:22:28] [ warn] [engine] failed to flush chunk '1-1712830947.947063732.flb', retry in 9 seconds: task_id=3, input=tail.0 > output=es.0 (out_id=0)

I think it might be related starting a container with a log format that fluent-bit is unable to dissect.

Is there anything I can search for in the fluent-bit logs?

This is a default helm installation on k8s.

running the fluent-bit container at the debug level:

[2024/04/11 10:22:26] [debug] [input chunk] update output instances with new chunk size diff=990, records=1, input=tail.0
[2024/04/11 10:22:26] [debug] [task] created task=0x7fb55a239f20 id=3 OK
[2024/04/11 10:22:26] [debug] [upstream] KA connection #125 to elasticsearch-master:9200 has been assigned (recycled)
[2024/04/11 10:22:26] [debug] [output:es:es.0] task_id=3 assigned to thread #0
[2024/04/11 10:22:26] [debug] [http_client] not using http_proxy for header
[2024/04/11 10:22:26] [debug] [output:es:es.0] HTTP Status=200 URI=/_bulk
[2024/04/11 10:22:26] [debug] [output:es:es.0] Elasticsearch response
{"errors":false,"took":51,"items":[{"create":{"_index":"logstash-2024.04.11","_id":"vUWuzI4B-yGqFaeXHvYb","_version":1,"result":"created","_shards":{"total":2,"successful":1,"failed":0},"_seq_no":556031,"_primary_term":2,"status":201}}]}
[2024/04/11 10:22:26] [debug] [upstream] KA connection #125 to elasticsearch-master:9200 is now available
[2024/04/11 10:22:26] [debug] [out flush] cb_destroy coro_id=183
[2024/04/11 10:22:26] [debug] [task] destroy task=0x7fb55a239f20 (task_id=3)
[2024/04/11 10:22:27] [debug] [output:es:es.0] task_id=2 assigned to thread #1
[2024/04/11 10:22:27] [debug] [upstream] KA connection #122 to elasticsearch-master:9200 has been assigned (recycled)
[2024/04/11 10:22:27] [debug] [http_client] not using http_proxy for header
[2024/04/11 10:22:27] [debug] [output:es:es.0] HTTP Status=200 URI=/_bulk
[2024/04/11 10:22:27] [debug] [upstream] KA connection #122 to elasticsearch-master:9200 is now available
[2024/04/11 10:22:27] [debug] [out flush] cb_destroy coro_id=183
[2024/04/11 10:22:27] [debug] [retry] re-using retry for task_id=2 attempts=2
[2024/04/11 10:22:27] [ warn] [engine] failed to flush chunk '1-1712830937.946819883.flb', retry in 9 seconds: task_id=2, input=tail.0 > output=es.0 (out_id=0)
[2024/04/11 10:22:27] [debug] [input:tail:tail.0] inode=312543, /var/log/containers/vanilla-log-7c7bdb9545-jvrqt_default_vanilla-log-58da14eb59c2e88f5dd1389f42fd80de64c21d14804a5c166d0bca5be163305d.log, events: IN_MODIFY 
[2024/04/11 10:22:27] [debug] [input chunk] update output instances with new chunk size diff=818, records=1, input=tail.0
[2024/04/11 10:22:28] [debug] [task] created task=0x7fb55a239c00 id=3 OK
[2024/04/11 10:22:28] [debug] [upstream] KA connection #123 to elasticsearch-master:9200 has been assigned (recycled)
[2024/04/11 10:22:28] [debug] [output:es:es.0] task_id=3 assigned to thread #0
[2024/04/11 10:22:28] [debug] [http_client] not using http_proxy for header
[2024/04/11 10:22:28] [debug] [output:es:es.0] HTTP Status=200 URI=/_bulk
[2024/04/11 10:22:28] [debug] [upstream] KA connection #123 to elasticsearch-master:9200 is now available
[2024/04/11 10:22:28] [debug] [out flush] cb_destroy coro_id=184
[2024/04/11 10:22:28] [debug] [retry] new retry created for task_id=3 attempts=1
[2024/04/11 10:22:28] [ warn] [engine] failed to flush chunk '1-1712830947.947063732.flb', retry in 9 seconds: task_id=3, input=tail.0 > output=es.0 (out_id=0)

[henkoch]

I added

        Trace_Error       On
        Trace_Output      On

to custom_parsers.conf

{
  "@timestamp": "2024-04-11T21:12:27.823Z",
  "log": "2024-04-11T21:12:27.822733033Z stderr F {\"level\":\"Info\",\"ts\":1712869947822,\"msg\":\"Hello from logs-basic-example\"}",
  "kubernetes": {
    "pod_name": "log-json-simple-7996b6c769-pdnb9",
    "namespace_name": "default",
    "pod_id": "39c7e953-7648-4d4a-99ee-45ff147e6c69",
    "labels": {
      "app": "log-json-simple",
      "pod-template-hash": "7996b6c769"
    },
    "annotations": {
      "cni.projectcalico.org/containerID": "1064c90cebfad72b17cb9abee89ed5e1c1965df1cffbe7b6c5ef309ea0fae422",
      "cni.projectcalico.org/podIP": "10.42.235.138/32",
      "cni.projectcalico.org/podIPs": "10.42.235.138/32"
    },
    "host": "worker1",
    "container_name": "log-json-simple",
    "docker_id": "0f06eff0c18da53700b06390f264163aac4652e4ae3acf6de395b1911dbc92f8",
    "container_hash": "192.168.1.102:5000/log-json-simple@sha256:2bf291c81781a92c5ad7a5bbbfc7ba80974d928d07a681cd51a8708ff5100687",
    "container_image": "192.168.1.102:5000/log-json-simple:0.1.0"
  }
}
[2024/04/11 21:23:09] [error] [output:es:es.0] error: Output
{
  "errors": true,
  "took": 0,
  "items": [
    {
      "create": {
        "_index": "logstash-2024.04.11",
        "_id": "O2ALz44B-yGqFaeXBX95",
        "status": 400,
        "error": {
          "type": "document_parsing_exception",
          "reason": "[1:325] object mapping for [kubernetes.labels.app] tried to parse field [app] as object, but found a concrete value"
        }
      }
    }
  ]
}
[2024/04/11 21:23:09] [ warn] [engine] failed to flush chunk '1-1712869947.823072138.flb', retry in 1949 seconds: task_id=9, input=tail.0 > output=es.0 (out_id=0)

Any ideas of what the problem might be?