output buffer files never closed (witk kafka_buffered_output)

[marqc]

Hi, I'm using fluentd in_tail plugin to follow logs from docker containers on kubernetes node. Logs are send to kafka topics. When using kafka_buffered_output with file buffers, buffer file handlers are not closed (and buffer files are not removed) until fluentd restart. Even when source file does not longer exist. This leads to increased number of open file handlers (expecially when lots of containers is created and removed).

td-agent version td-agent-2.3.5-1.el7.x86_64
fluent-plugin-kafka gem version 0.5.5
OS CentOS Linux release 7.3.1611 (Core)

My fluent config

<source>
    #scan for json output log of running docker containers
    @type tail
    path /var/log/containers/*.log
    pos_file /var/log/fluentd/fluentd-docker.pos
    time_format %Y-%m-%dT%H:%M:%S
    tag kubernetes.*
    format json
    read_from_head true
    time_key time 
    refresh_interval 3
</source>

<filter kubernetes.var.log.containers.*.log>
    type kubernetes_metadata
    kubernetes_url http://master.kubernetes.com:8080
</filter>

#send messages to kafka
<match **>
    @type kafka_buffered

    # list of seed brokers
    brokers kafkahost.com:9092

    # buffer settings
    buffer_type file
    buffer_path /var/log/fluentd/kafka-buffer
    buffer_chunk_limit 8m
    buffer_queue_limit 64
    max_send_limit_bytes 1000000
    kafka_agg_max_bytes 1000000
    flush_interval 10s

    # topic settings
    default_topic logs

    exclude_message_key true
    exclude_topic_key true
    exclude_partition_key true

    # data type settings
    output_data_type json
    compression_codec snappy

    # producer settings
    max_send_retries 1
    required_acks 1
</match>

Opened file handlers

 lsof /var/log/fluentd/kafka-buffer.*
COMMAND  PID USER   FD   TYPE DEVICE SIZE/OFF     NODE NAME
ruby    4764 root    8u   REG  253,5      606 81866540 /var/log/fluentd/kafka-buffer.kubernetes.var.log.containers.app1-34141-90w2q_default_app-85423bb04ffe6c5dff7c1556fb705538a2d3db2b0f77a714ac5cf6eab5b0235d.log.b558e8bb5f194d02c.log
ruby    4764 root    9u   REG  253,5      530 81866513 /var/log/fluentd/kafka-buffer.kubernetes.var.log.containers.app2-11226-rgnua_default_app-f89b5ede27cffb05f26ad975cff68c18b4c06c5e4c694314b68f982a3b18321c.log.b558e8bb065be24b7.log
...

Even when app container is removed (input file for in_tail does is removed), output buffers for kafka are kept open, which eventually leads to exceeding number of open file handlers per process/OS.

[repeatedly]

I first heard this problem.
In short, your kafka cluster receives buffer content correctly but flushed buffer chunks are not purged, right?

[marqc]

Yes, kafka receives all data. Buffer files are empty.

Currently i switched to memory buffers to avoid this problem.

[repeatedly]

Buffer files are empty.

Is empty file above /var/log/fluentd/kafka-buffer.kubernetes.var.log.containers.app1-34141-90w2q_default_app-85423bb04ffe6c5dff7c1556fb705538a2d3db2b0f77a714ac5cf6eab5b0235d.log.b558e8bb5f194d02c.log, right?
Hmm... that's weird. If buffers are flushed, the identifier in path should be started q, not b (b558e8bb5f194d02c.log).
Does other process touch these files?

[repeatedly]

BTW, do you edit td-agent related files?
By default, td-agent is runnging under td-agent user but your lsof shows user is root.

[jacoelho]

I seeing this behaviour too:

# ls -la /var/log/td-agent/buffer/td | wc -l
45074

# du -sh /var/log/td-agent/buffer/td
11M     /var/log/td-agent/buffer/td

# ls -la /var/log/td-agent/buffer/td 
...
-rw-r--r-- 1 td-agent td-agent        0 Feb  4 02:36 buffer.b56459cfbf267f3c01ce1c28bcdf17eb9.log
-rw-r--r-- 1 td-agent td-agent        0 Feb  4 02:36 buffer.b56459cfc5bc32449708ea4d36fb66503.log
-rw-r--r-- 1 td-agent td-agent        0 Feb  4 02:36 buffer.b56459cfc88809117c07f798c4bb90dfa.log
-rw-r--r-- 1 td-agent td-agent        0 Feb  4 02:36 buffer.b56459cfcb674203494ad0016259ae12c.log
-rw-r--r-- 1 td-agent td-agent        0 Feb  4 02:36 buffer.b56459cfce33b326a887a66549add2f0f.log
-rw-r--r-- 1 td-agent td-agent        0 Feb  4 02:36 buffer.b56459cfd0f738a9eb959321a565e7010.log
-rw-r--r-- 1 td-agent td-agent        0 Feb  4 02:36 buffer.b56459cfd46ef6e549f8d8e09918cd50c.log
-rw-r--r-- 1 td-agent td-agent        0 Feb  4 02:36 buffer.b56459cfd7317af5f59eb6c702756287e.log
-rw-r--r-- 1 td-agent td-agent        0 Feb  4 02:36 buffer.b56459cfda8b0c2a53ca801a1b28d4e80.log
-rw-r--r-- 1 td-agent td-agent       74 Feb  9 10:47 buffer.b564c541d7dde028e580365d79b6fa68b.log.meta

kafka configuration:

<match **>
  @type kafka_buffered
  brokers <brokers>
  buffer_type        file
  buffer_path        /var/log/td-agent/buffer/td
  buffer_queue_limit 16
  buffer_chunk_limit 64m
  flush_interval     5s
  flush_at_shutdown  true
  default_topic <topic>
  output_data_type  json
  compression_codec gzip
  max_send_retries 1
  required_acks    -1
  num_threads 2
</match>

[github-actions]

This issue has been automatically marked as stale because it has been open 90 days with no activity. Remove stale label or comment or this issue will be closed in 30 days

[github-actions]

This issue was automatically closed because of stale in 30 days