Why Fluentd does not update pos_file when use in_tail plugin after runing few hours or days later?

zhuzhen...@gmail.com

unread,

Jan 18, 2017, 8:31:23 AM1/18/17

to Fluentd Google Group

Hi, Groups

I use EFK as Kubernetes logging system, which use in_tail for logs.

I met an odd strange phenomenon that fluentd did not update pos_file after running few hours or days later, there is nothing wrong in fluent's log, no hints, just like the process td-agent is sleep or block. Before it stopped update pos_file, everything is ok, container logs are sent to ES correctly.

When I resatrt the fluentd Pod, it continues to collect log, but after few hours or days, things happen again: pos_file stopped update and no logs send to ES.

So I don't know why fluentd does not update pos_file and stop to read container's logs?

Please give me some advices.

Mr. Fiber

unread,

Jan 18, 2017, 10:49:34 AM1/18/17

to Fluentd Google Group

Could you check which point is blocked?

http://docs.fluentd.org/articles/trouble-shooting#dump-fluentd-internal-information

Masahiro

--
You received this message because you are subscribed to the Google Groups "Fluentd Google Group" group.
To unsubscribe from this group and stop receiving emails from it, send an email to fluentd+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Mr. Fiber

unread,

Jan 18, 2017, 10:49:49 AM1/18/17

to Fluentd Google Group

Of course, paste your configuration is needed.

zhuzhen...@gmail.com

unread,

Jan 18, 2017, 8:58:07 PM1/18/17

to Fluentd Google Group

hi, Masahiro

Thanks for your quickly reply.

I'll do some check base the url you provide.

Here is my fluentd configuration:

type null

</match>

type tail

path /var/log/containers/*.log

pos_file /var/log/es-containers.log.pos

time_format %Y-%m-%dT%H:%M:%S.%N%Z

tag kubernetes.*

format json

read_from_head true

enable_watch_timer false

refresh_interval 30

read_lines_limit 200

rotate_wait 15

</source>

type tail

format /^(?<time>[^ ]* [^ ,]*)[^\[]*\[[^\]]*\]\[(?<severity>[^ \]]*) *\] (?<message>.*)$/

time_format %Y-%m-%d %H:%M:%S

path /var/log/salt/minion

pos_file /var/log/es-salt.pos

tag salt

rotate_wait 15

</source>

type tail

format syslog

path /var/log/startupscript.log

pos_file /var/log/es-startupscript.log.pos

tag startupscript

rotate_wait 15

</source>

type tail

format /^time="(?<time>[^)]*)" level=(?<severity>[^ ]*) msg="(?<message>[^"]*)"( err="(?<error>[^"]*)")?( statusCode=($<status_code>\d+))?/

time_format %Y-%m-%dT%H:%M:%S.%N%Z

path /var/log/docker.log

pos_file /var/log/es-docker.log.pos

tag docker

rotate_wait 15

</source>

type tail

format none

path /var/log/etcd.log

pos_file /var/log/es-etcd.log.pos

tag etcd

rotate_wait 15

</source>

type tail

format multiline

format_firstline /^\w\d{4}/

format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/

time_format %m%d %H:%M:%S.%N

path /var/log/kubelet.log

pos_file /var/log/es-kubelet.log.pos

tag kubelet

rotate_wait 15

</source>

type tail

format multiline

format_firstline /^\w\d{4}/

format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/

time_format %m%d %H:%M:%S.%N

path /var/log/kube-apiserver.log

pos_file /var/log/es-kube-apiserver.log.pos

tag kube-apiserver

rotate_wait 15

</source>

type tail

format multiline

format_firstline /^\w\d{4}/

format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/

time_format %m%d %H:%M:%S.%N%Z

path /var/log/kube-controller-manager.log

pos_file /var/log/es-kube-controller-manager.log.pos

tag kube-controller-manager

rotate_wait 15

</source>

type tail

format multiline

format_firstline /^\w\d{4}/

format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/

time_format %m%d %H:%M:%S.%N

path /var/log/kube-scheduler.log

pos_file /var/log/es-kube-scheduler.log.pos

tag kube-scheduler

rotate_wait 15

</source>

type kubernetes_metadata

</filter>

type tail

format multiline

multiline_flush_interval 5s

format_firstline /^\w\d{4}/

format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/

time_format %m%d %H:%M:%S.%N

path /var/log/glbc.log

pos_file /var/log/es-glbc.log.pos

tag glbc

rotate_wait 15

</source>

type tail

format multiline

multiline_flush_interval 5s

format_firstline /^\w\d{4}/

format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/

time_format %m%d %H:%M:%S.%N

path /var/log/cluster-autoscaler.log

pos_file /var/log/es-cluster-autoscaler.log.pos

tag cluster-autoscaler

rotate_wait 15

</source>

@type elasticsearch

log_level info

include_tag_key true

host elasticsearch-logging

port 9200

logstash_format true

buffer_type memory

flush_interval 10

num_threads 4

queued_chunk_flush_interval 1

retry_limit 17

disable_retry_limit false

retry_wait 1.0

buffer_chunk_limit 4M

buffer_queue_limit 256

flush_at_shutdown true

request_timeout 60

reload_connections false

reload_on_failure true

</match>

在 2017年1月18日星期三 UTC+8下午11:49:49，repeatedly写道：

To unsubscribe from this group and stop receiving emails from it, send an email to fluentd+u...@googlegroups.com.

Mr. Fiber

unread,

Jan 18, 2017, 9:21:26 PM1/18/17

to Fluentd Google Group

Which pos_file is not updated?

To unsubscribe from this group and stop receiving emails from it, send an email to fluentd+unsubscribe@googlegroups.com.

zhuzhen...@gmail.com

unread,

Jan 18, 2017, 9:28:11 PM1/18/17

to Fluentd Google Group

Hi，

Thanks for reply.

I'm focus on the first <source> part.

The pos_file I said is /var/log/es-containers.log.pos.

Flunetd is running as a Pod on k8s node.

BTW, Is the sigdump install on flentd's image or install on k8s node which running fluentd Pod?

Thanks again!

type tail

path /var/log/containers/*.log

pos_file /var/log/es-containers.log.pos

time_format %Y-%m-%dT%H:%M:%S.%N%Z

tag kubernetes.*

format json

read_from_head true

enable_watch_timer false

refresh_interval 30

read_lines_limit 200

rotate_wait 15

</source>

在 2017年1月19日星期四 UTC+8上午10:21:26，repeatedly写道：

zhuzhen...@gmail.com

unread,

Jan 18, 2017, 10:58:34 PM1/18/17

to Fluentd Google Group

Hi, Masahiro

The picture below is show that pos_file stopped update about 15 hours .

I use sigdump get fluentd parent and child process sigdump info. Where sigdump-1.log for parent fluentd process, sigdump-8.log for child fluentd process. But I have no idea how to get useful info I want, I need sometime to get it. So if possible, please check my sigdump log info. Thank you.

content of sigdump-1.log as follow:

root@fluentd-elasticsearch-v0:/tmp# cat sigdump-1.log

Sigdump at 2017-01-19 11:43:01 +0800 process 1 (/usr/sbin/td-agent)

Thread #<Thread:0x00000000f3a660> status=run priority=0

/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:52:in `backtrace'

/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:52:in `dump_backtrace'

/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:34:in `block in dump_all_thread_backtrace'

/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:33:in `each'

/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:33:in `dump_all_thread_backtrace'

/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:16:in `block in dump'

/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:136:in `open'

/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:136:in `_open_dump_path'

/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:14:in `dump'

/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:7:in `block in setup'

/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/lib/fluent/supervisor.rb:350:in `call'

/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/lib/fluent/supervisor.rb:350:in `waitpid'

/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/lib/fluent/supervisor.rb:350:in `supervise'

/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/lib/fluent/supervisor.rb:156:in `start'

/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/lib/fluent/command/fluentd.rb:173:in `<top (required)>'

/opt/td-agent/embedded/lib/ruby/site_ruby/2.1.0/rubygems/core_ext/kernel_require.rb:54:in `require'

/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.29/bin/fluentd:5:in `<top (required)>'

/opt/td-agent/embedded/bin/fluentd:23:in `load'

/opt/td-agent/embedded/bin/fluentd:23:in `<top (required)>'

/usr/sbin/td-agent:7:in `load'

/usr/sbin/td-agent:7:in `<main>'

GC stat:

count: 19

heap_used: 261

heap_length: 261

heap_increment: 0

heap_live_slot: 104773

heap_free_slot: 1615

heap_final_slot: 0

heap_swept_slot: 34025

heap_eden_page_length: 261

heap_tomb_page_length: 0

total_allocated_object: 400646

total_freed_object: 295873

malloc_increase: 1088856

malloc_limit: 16777216

minor_gc_count: 14

major_gc_count: 5

remembered_shady_object: 683

remembered_shady_object_limit: 794

old_object: 41129

old_object_limit: 68392

oldmalloc_increase: 5541472

oldmalloc_limit: 16777216

Built-in objects:

106,388: TOTAL

43,909: T_STRING

37,252: T_NODE

11,583: T_ARRAY

5,629: T_DATA

2,472: T_OBJECT

2,016: T_CLASS

1,525: FREE

737: T_REGEXP

714: T_HASH

137: T_MODULE

129: T_ICLASS

127: T_MATCH

59: T_RATIONAL

44: T_FILE

41: T_STRUCT

9: T_FLOAT

4: T_BIGNUM

1: T_COMPLEX

content of sigdump-8.log as follow:

root@fluentd-elasticsearch-v0:/tmp# cat sigdump-8.log

Sigdump at 2017-01-19 11:43:18 +0800 process 8 (/usr/sbin/td-agent)