Fluentd memory leak in Kubernetes with "buffer_type file"

[qingling128]

[Fluentd version]
v1.2.5

[Environment]
Kubernetes

[Configuration]
https://github.com/kubernetes/kubernetes/blob/master/cluster/addons/fluentd-gcp/fluentd-gcp-configmap.yaml

[Problems]
We are seeing Fluentd memory leaks with Kubernetes versions >= v1.10. After some investigation, we realized the log rotation mechanism changed from Kubernetes v1.9 and v1.10, which might trigger the memory leak. Guess the logs are rotated in a way that Fluentd does not support / handle well.

Some experiment with exactly the same Fluentd version, output plugin version but different Kubernetes versions are shown below:

Is there any known limitation for log rotation mechanism that might trigger this? We report a similar issue before, but I've verified that we are using a Fluentd version with that fix.

[The log rotation manager]
In case it helps, the log rotation mechanism is https://github.com/kubernetes/kubernetes/blob/a3ccea9d8743f2ff82e41b6c2af6dc2c41dc7b10/pkg/kubelet/logs/container_log_manager.go#L150.

[repeatedly]

Is the problem klog implementation, right?
I want to know the differences between older logger and newer logger to debug the problem.
Do we reproduce the problem with https://github.com/kubernetes/klog ?
Or need some k8s or gke specific setting?

[qingling128]

I haven't managed to reproduce it outside the k8s world.

Does Fluentd support copytruncate? I noticed some of the logs are rotated with copytruncate (https://github.com/kubernetes/kubernetes/blob/8ab955f82dddd3725b543a4bb01c367a4c4a2286/cluster/gce/gci/configure-helper.sh#L365).

I just set up a regular VM and some logs with copytruncate. Will report back when I get some memory data.

[repeatedly]

in_tail itself considers truncated case:

fluentd/lib/fluent/plugin/in_tail.rb

Line 589 in 35ef6c7

if inode == @pe.read_inode # truncated

But I will re-check object management for truncated case.

I just set up a regular VM and some logs with copytruncate. Will report back when I get some memory data.

Good. I want to know which point causes this problem, configuration, klog, k8s or gke.
I checked klog diff but it doesn't contains the changes for log generation.
So I assume k8s or something setting causes this problem: golang/glog@master...kubernetes:master

[qingling128]

Still waiting for the memory trend to show up. I haven't seen an obvious leaking pattern. But I realized I forgot to specify read_from_head true so I just turn that on. In GKE, we are using the Fluentd read_from_head true config together with copytruncate. Wondering if that somehow messes with pos_file and leave objects hanging around.

[jkohen]

Hi, I work with @qingling128. We had a customer report high CPU usage with fluentd, running outside Kubernetes, and it had in common with this issue that they were using read_from_head true together with copytruncate.

I reached the same conclusion as you that in_tail should handle this correctly, but I was able to confirm the CPU spikes in the Ruby interpreter (so not logrotate or the user application) where no spikes were expected based on the configuration, which had fluentd watch a single file (not *).

[qingling128]

@repeatedly

For the reference, the related logrotation config and in_tail config that has logrotation CPU issue are like below:

Log Rotation Setting

/etc/logrotate.d $ cat my-app
/var/log/my-app/*.log
{
  prerotate
    rm -f /var/log/my-app/access.*.log
    rm -f /var/log/my-app/access_log.*.log
  endscript
  rotate 0
  maxsize 10M
  missingok
  notifempty
  nocompress
  copytruncate
  postrotate
    rm -f /var/log/my-app/access.*.log
    rm -f /var/log/my-app/access_log.*.log
  endscript
}

In Tail Config

$ cat my-app-fluentd.conf
<source>
  @type tail
  format none
  path /var/log/my-app/access.log
  pos_file /var/lib/pos/service.access.pos
  read_from_head true
  tag service_log
</source>

<source>
  @type tail
  format none
  path /var/log/my-app/service.log
  pos_file /var/lib/pos/service.output.pos
  read_from_head true
  tag service_output_log
</source>

<source>
  @type tail
  format none
  path /var/log/my-app/gc.log
  pos_file /var/lib/pos/service.gc.pos
  read_from_head true
  tag service_gc_log
</source>

[repeatedly]

So no spike without copytruncate, right?
I will test with your logrotation script.

[qingling128]

@repeatedly Correct.

[qingling128]

@repeatedly Any luck with reproducing the memory leak or CPU spike?

[repeatedly]

Sorry for the late. I took new year holidays. I will start working tomorrow.

[qingling128]

@repeatedly Cool cool. Thanks for the heads up!

[repeatedly]

I tested simple truncate case several hours but no memory leak.

5.times.map { |i|
  Thread.new {
    loop {
      f = File.open("./output_#{i}.log", "a")
      10.times {
        f.puts "hello"
        f.flush
        sleep 1
      }
      f.truncate(0)
      f.close
    }
  }
}.each { |t| t.join }

I will test more complicated truncate case.

[repeatedly]

Now testing on my Ubuntu 18.04 box with fluentd v1.3.2 and ruby 2.4.5.
Currently, no memory leak. Continue to run script...

[repeatedly]

I tested several hours but no memory leak and cpu spike.
Any other information for the issue?

Env:

OS: Ubuntu 18.04
fluentd: v1.3.3
ruby: 2.4.5

conf:

<source>
  @type tail
  format none
  path /home/repeatedly/tail/log/output1.log
  pos_file /home/repeatedly/tail/application-log_1.pos
  read_from_head true
  tag test
</source>

<source>
  @type tail
  format none
  path /home/repeatedly/tail/log/output2.log
  pos_file /home/repeatedly/tail/application-log_2.pos
  read_from_head true
  tag test
</source>

<source>
  @type tail
  format none
  path /home/repeatedly/tail/log/output3.log
  pos_file /home/repeatedly/tail/application-log_3.pos
  read_from_head true
  tag test
</source>

<match test>
  @type null
</match>

logrotate:

/home/repeatedly/tail/log/*.log
{
  prerotate
    rm -f /home/repeatedly/tail/log/output1.*.log
    rm -f /home/repeatedly/tail/log/output1_log.*.log
  endscript
  rotate 0
  maxsize 2M  # smaller size for testing
  missingok
  notifempty
  nocompress
  copytruncate
  postrotate
    rm -f /home/repeatedly/tail/log/output1.*.log
    rm -f /home/repeatedly/tail/log/output1_log.*.log
  endscript
}

Call logrotate every 10 seconds:

$ while sleep 10; do logrotate -f /etc/logrotate.conf ; done

Generate logs by following script:

paths = 3.times.map { |i| "./log/output#{i + 1}.log" }
ths = paths.map { |path|
  Thread.new {
    f = File.open(path, "a")
    loop {
      f.puts "hello fluuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuend world! " * 10
      f.flush
      sleep 0.01
    }
    f.close
  }
}

ths.each { |t| t.join }

[repeatedly]

I'm not sure filter/output plugins. Does using null output plugin also have a memory leak issue?