Fluentd: Incosistentlty restart when fluentd start with arguments

[gianrubio]

• fluentd or td-agent version.
  fluentd-0.14.11

• Environment information, e.g. OS.
  coreos under kubernetes 1.4.7

• Your configuration

# input plugin that exports metrics
<source>
  @type prometheus
</source>

# input plugin that collects metrics from MonitorAgent
<source>
  @type prometheus_monitor
</source>

<source>
  @type tail
  path /var/log/containers/[a-za-z0-9]*.log
  pos_file /var/log/fluentd/docker.pos
  time_format %Y-%m-%dT%H:%M:%S.%NZ
  time_key time
  tag kubernetes.*
  format json
  read_from_head true
  encoding UTF-8
</source>

<filter kubernetes.var.log.containers.*.log>
  @type kubernetes_metadata
  #tag_to_kubernetes_name_regexp .*var\.log\.containers\.(?<pod_name>[a-z0-9]([-a-z0-9]*[a-z0-9])?(\.[a-z0-9]([-a-z0-9]*[a-z0-9])?)*)_(?<namespace>[^_]+)_(?<container_name>.+)-(?<docker_id>[a-z0-9]{64})\.log$
</filter>

<filter kubernetes.var.log.containers.*.log>
  @type prometheus
  # This just increments counter by 1
  <metric>
    name fluentd_record_counts
    type counter
    desc the number of emited records
  </metric>
</filter>

<match kubernetes.**>
    @type copy
    # copy/redirect everything with the tag gelf.app.* tag to the graylog input listening on port 12202
    <store>
        @type gelf
        host "#{ENV['GRAYLOG2_CONTAINER_HOST']}"
        port "#{ENV['GRAYLOG2_CONTAINER_PORT']}"
        protocol "#{ENV['GRAYLOG2_CONTAINER_PROTO']}"
        flush_interval 10s
    </store>
</match>

<match systemd.**>
    @type copy
    # copy/redirect everything with the tag gelf.app.* tag to the graylog input listening on port 12202
    <store>
        @type gelf
        host "#{ENV['GRAYLOG2_SYSTEMD_HOST']}"
        port "#{ENV['GRAYLOG2_SYSTEMD_PORT']}"
        protocol "#{ENV['GRAYLOG2_SYSTEMD_PROTO']}"
        flush_interval 10s
    </store>
</match>

• Your problem explanation. If you have an error logs, write it together.

I'm running fluentd 0.14.11 as daemonset, with fluent-plugin-kubernetes_metadata_filter, fluent-plugin-prometheus and fluent-plugin-systemd plugins enabled. Sometimes my node die with message Worker 0 finished unexpectedly with signal SIGKILL. The process successfully restart but using different arguments.

To simple illustrate the problem

• I'm running fluentd with supervision /usr/bin/ruby -Eascii-8bit:ascii-8bit /usr/bin/fluentd -c /fluentd/etc/fluent.conf --under-supervisor
• After the process die 017-01-18 09:42:01 +0000 [info]: Worker 0 finished unexpectedly with signal SIGKILL the fluentd restart without supervision 2017-01-18 09:44:34 +0000 [info]: starting fluentd-0.14.11 without supervision pid=9513.

Working node

Process

/home/fluent # ps auwxPID   USER     TIME   COMMAND
    1 root       0:00 /bin/sh -c fluentd -c /fluentd/etc/$FLUENTD_CONF $FLUENTD_OPT
    7 root       0:11 {fluentd} /usr/bin/ruby /usr/bin/fluentd -c /fluentd/etc/fluent.conf
   11 root       5:21 /usr/bin/ruby -Eascii-8bit:ascii-8bit /usr/bin/fluentd -c /fluentd/etc/fluent.conf --under-supervisor

Ports (24231) from prometheus plugin

/home/fluent # netstat -lpn
Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
tcp        0      0 0.0.0.0:24231           0.0.0.0:*               LISTEN      11/ruby
Active UNIX domain sockets (only servers)
Proto RefCnt Flags       Type       State         I-Node PID/Program name    Path
unix  2      [ ACC ]     STREAM     LISTENING     91971757 7/ruby              /tmp/SERVERENGINE_SOCKETMANAGER_2017-01-1710:41:02+0000_7
/home/fluent #

Broken Node

Proccess

/home/fluent # ps auwx
PID   USER     TIME   COMMAND
    1 root       0:00 /bin/sh -c fluentd -c /fluentd/etc/$FLUENTD_CONF $FLUENTD_OPT
    7 root       0:12 {fluentd} /usr/bin/ruby /usr/bin/fluentd -c /fluentd/etc/fluent.conf
 9443 root       0:00 sh
 9451 root       0:18 /usr/bin/ruby -Eascii-8bit:ascii-8bit /usr/bin/fluentd -c /fluentd/etc/fluent.conf --under-supervisor

Ports (port 24231 it's no longer listening)

# netstat -lpn
Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
Active UNIX domain sockets (only servers)
Proto RefCnt Flags       Type       State         I-Node PID/Program name    Path
unix  2      [ ACC ]     STREAM     LISTENING     107348161 7/ruby              /tmp/SERVERENGINE_SOCKETMANAGER_2017-01-1710:41:02+0000_7
/home/fluent #

Startup log (3rd line really strange because I'm using supervision)

017-01-18 09:42:01 +0000 [info]: Worker 0 finished unexpectedly with signal SIGKILL
2017-01-18 09:42:03 +0000 [info]: reading config file path="/fluentd/etc/fluent.conf"
2017-01-18 09:42:03 +0000 [info]: starting fluentd-0.14.11 without supervision pid=9485
2017-01-18 09:42:03 +0000 [info]: gem 'fluent-plugin-json-in-json' version '0.1.4'
2017-01-18 09:42:03 +0000 [info]: gem 'fluent-plugin-kubernetes_metadata_filter' version '0.26.2'
2017-01-18 09:42:03 +0000 [info]: gem 'fluent-plugin-prometheus' version '0.2.1'
2017-01-18 09:42:03 +0000 [info]: gem 'fluent-plugin-systemd' version '0.1.0'
2017-01-18 09:42:03 +0000 [info]: gem 'fluentd' version '0.14.11'
2017-01-18 09:42:03 +0000 [info]: adding filter pattern="kubernetes.var.log.containers.*.log" type="kubernetes_metadata"
2017-01-18 09:42:08 +0000 [info]: adding filter pattern="kubernetes.var.log.containers.*.log" type="prometheus"
2017-01-18 09:42:08 +0000 [info]: adding match pattern="kubernetes.**" type="copy"
2017-01-18 09:42:08 +0000 [info]: adding match pattern="systemd.**" type="copy"
2017-01-18 09:42:08 +0000 [info]: adding source type="prometheus"
2017-01-18 09:42:08 +0000 [info]: adding source type="prometheus_monitor"
2017-01-18 09:42:08 +0000 [info]: adding source type="tail"
2017-01-18 09:42:08 +0000 [info]: using configuration file: <ROOT>

[repeatedly]

Could you trace who send kill signal to fluentd?

[gianrubio]

I'm running fluentd inside a docker container on top of kubernetes. The container was never reinitialised by kubernetes. I'm not really sure, but probably the fluentd was sending the kill signal to yourself.

Docker command

CMD fluentd -c /fluentd/etc/$FLUENTD_CONF $FLUENTD_OPT

Log after starting

2017-01-18 15:59:31 +0000 [info]: Worker 0 finished unexpectedly with signal SIGKILL

[repeatedly]

I'm not familiar with k8s operation.
k8s doesn't check managing processes?

[gianrubio]

No, k8s take care of the process, if the container die k8s replace with a new one.

I enabled verbose mode, is serverengine killing the process?

2017-01-18 16:26:38 +0000 [info]: serverengine/multi_process_server.rb:136:alive?: Worker 0 finished unexpectedly with signal SIGKILL

[repeatedly]

It seems no.
This line checks child process alive or not.
If the serverengine itself sends kill signal to stop child process, unexpectedly should not be logged.
The log says serverengine detects process dead and it is caused by kill signal from other process.

[mumoshu]

Hi @gianrubio, I had been seeing the exact error in my setup but I had managed to fix it (at least no reproduction so far).

I suggest you to tune:

• buffer_chunk_limit
• buffer_queue_limit

so that buffer_chunk_limit * buffer_queue_limit * num of fluentd outputs using buffer goes below memory limit of the fluentd container / N where N is approx 3 for me.

My guess is that kubernetes_metadata_filter and your fluentd output plugins consumes too much memory and therefore your pod/container exceeds the memory limit set via the k8s pod spec and then gets OOM-killed.

[KYannick]

@mumoshu, I'm having the same problem, fluentd worker process getting OOM killed now and then. I'm trying to tune the buffer limits to prevent this. How did you determine the value of N in your calculation?

[salla2]

@KYannick , did you figured it out about N? could you helm me.I'm having same issue "2017-12-11 21:41:04 +0000 [info]: Worker 0 finished with signal SIGKILL"

[tech-talks-india]

I am still looking for the solution. Does anyone has a solution for it?

[Verhaeg]

Hi, we are using Fluentd v1.1.2 with the following plugins installed (but not all used):

• kubernetes_metadata_filter
• elasticsearch (not used)
• gcloud-pubsub-custom (not used)
• record-reformer
• record-serializer
• rewrite-tag-filter
• out-http
• bufferize (not used)
• prometheus
• kinesis

Our kinesis configuration (the only one that uses the buffer) is as follow:

<buffer>
      flush_interval 1s
      chunk_limit_size 1m
      flush_thread_interval 0.1
      flush_thread_burst_interval 0.01
      flush_thread_count 10
</buffer>

We run it on a Kubernetes 1.7.10 cluster as DaemonSet with now at 400Mb memory limit.
After starting Fluentd with the new limit, the memory went from ~100MB to 250MB in 1 hour or so.

We were receiving several SIGKILL before (when we had 200MB memory limit) and waiting so far to see if it will keep occurring.

Is the bug from tail not freeing memory still fixed? and can you think of any other reason for the memory to keep increasing?

[AjeetK]

This is happening with GKE as well. Fluentd receiving SIGTERM. Increasing the resources isn't helping.

fluentd-k6w5j fluentd 2018-09-09 14:56:13 +0000 [info]: #0 [apiserver_out_es] Detected ES 6.x: ES 7.x will only accept `_doc` in type_name.
fluentd-k6w5j fluentd 2018-09-09 14:56:13 +0000 [info]: fluent/log.rb:322:info: adding match pattern="**" type="elasticsearch_dynamic"
fluentd-hb8zq fluentd 2018-09-09 14:56:25 +0000 [info]: fluent/log.rb:322:info: Received graceful stop
fluentd-g8lzm fluentd 2018-09-09 14:56:25 +0000 [info]: fluent/log.rb:322:info: Received graceful stop
fluentd-k6w5j fluentd 2018-09-09 14:56:25 +0000 [info]: fluent/log.rb:322:info: Received graceful stop
fluentd-g8lzm fluentd 2018-09-09 14:56:26 +0000 [debug]: #0 fluent/log.rb:302:debug: fluentd main process get SIGTERM
fluentd-g8lzm fluentd 2018-09-09 14:56:26 +0000 [debug]: #0 fluent/log.rb:302:debug: getting start to shutdown main process
fluentd-k6w5j fluentd 2018-09-09 14:56:26 +0000 [debug]: #0 fluent/log.rb:302:debug: fluentd main process get SIGTERM
fluentd-k6w5j fluentd 2018-09-09 14:56:26 +0000 [debug]: #0 fluent/log.rb:302:debug: getting start to shutdown main process
fluentd-hb8zq fluentd 2018-09-09 14:56:26 +0000 [debug]: #0 fluent/log.rb:302:debug: fluentd main process get SIGTERM
fluentd-hb8zq fluentd 2018-09-09 14:56:26 +0000 [debug]: #0 fluent/log.rb:302:debug: getting start to shutdown main process
fluentd-hb8zq fluentd 2018-09-09 14:56:41 +0000 [debug]: #0 fluent/log.rb:302:debug: fluentd main process get SIGTERM
fluentd-g8lzm fluentd-k6w5j fluentd 2018-09-09 14:56:41 +0000 [debug]: #0 fluent/log.rb:302:debug: fluentd main process get SIGTERM
fluentd 2018-09-09 14:56:41 +0000 [debug]: #0 fluent/log.rb:302:debug: fluentd main process get SIGTERM
fluentd-hb8zq fluentd 2018-09-09 14:56:43 +0000 [info]: fluent/log.rb:322:info: adding source type="systemd"
fluentd-k6w5j fluentd 2018-09-09 14:56:43 +0000 [info]: fluent/log.rb:322:info: adding source type="systemd"
fluentd-g8lzm fluentd 2018-09-09 14:56:43 +0000 [info]: fluent/log.rb:322:info: adding source type="systemd"
fluentd-hb8zq fluentd 2018-09-09 14:56:43 +0000 [trace]: #0 fluent/log.rb:281:trace: registered input plugin 'systemd'
fluentd-hb8zq fluentd 2018-09-09 14:56:43 +0000 [warn]: #0 fluent/log.rb:342:warn: 'filters' parameter is deprecated: filters has been renamed as matches
fluentd-k6w5j fluentd 2018-09-09 14:56:43 +0000 [trace]: #0 fluent/log.rb:281:trace: registered input plugin 'systemd'
fluentd-g8lzm fluentd 2018-09-09 14:56:43 +0000 [trace]: #0 fluent/log.rb:281:trace: registered input plugin 'systemd'

[koooge]

Hi, Is this the same issue?

fluentd: 1.3.2

2019-01-17 02:19:49 +0000 [info]: #0 starting fluentd worker pid=15031 ppid=1 worker=0
2019-01-17 02:19:50 +0000 [info]: #0 following tail of /var/log/containers/fluentd-gdhgv_kube-system_fluentd-5528da47805e71f20fa2ea053bb7c3953162afb2c7b4c1178ca0b8ed73aee641.log
2019-01-17 02:19:51 +0000 [warn]: #0 chunk bytes limit exceeds for an emitted event stream: 15933502bytes
2019-01-17 02:19:53 +0000 [info]: Worker 0 finished unexpectedly with signal SIGKILL

and it does not seem OOM because the pod did not restart

$ kubectl get po
NAME                                       READY   STATUS      RESTARTS   AGE
...
fluentd-5xmhl                              1/1     Running     0          19h

[koooge]

Sorry, mine seemed to be solved by read_from_head true in in_tail. I'm not sure the reason why though...