Errors with in_tail plugin in 0.14.6 #1229

jchauncey · 2016-09-12T15:16:38Z

Seeing the following error in my kubernetes fluentd pod

Version:0.14.6 running as a gem
OS: Debian

2016-09-12 14:56:43 +0000 [error]: can't modify string; temporarily locked
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:563:in `readpartial'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:563:in `on_notify'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:444:in `on_notify'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin_helper/timer.rb:76:in `on_timer'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run_once'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin_helper/event_loop.rb:71:in `block in start'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin_helper/thread.rb:66:in `block in thread_create'
2016-09-12 14:56:43 +0000 [error]: closed stream
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:563:in `readpartial'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:563:in `on_notify'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:444:in `on_notify'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:425:in `attach'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:210:in `setup_watcher'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:231:in `block in start_watchers'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:218:in `each'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:218:in `start_watchers'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:204:in `refresh_watchers'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:156:in `start'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/root_agent.rb:138:in `block in start'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/root_agent.rb:127:in `block (2 levels) in lifecycle'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/root_agent.rb:126:in `each'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/root_agent.rb:126:in `block in lifecycle'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/root_agent.rb:113:in `each'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/root_agent.rb:113:in `lifecycle'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/root_agent.rb:137:in `start'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/engine.rb:211:in `start'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/engine.rb:175:in `run'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/supervisor.rb:677:in `run_engine'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/supervisor.rb:436:in `block in run_worker'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/supervisor.rb:606:in `main_process'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/supervisor.rb:431:in `run_worker'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/command/fluentd.rb:271:in `<top (required)>'
  2016-09-12 14:56:43 +0000 [error]: /usr/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb:68:in `require'
  2016-09-12 14:56:43 +0000 [error]: /usr/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb:68:in `require'
  2016-09-12 14:56:43 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/bin/fluentd:5:in `<top (required)>'
  2016-09-12 14:56:43 +0000 [error]: /usr/local/bin/fluentd:23:in `load'
  2016-09-12 14:56:43 +0000 [error]: /usr/local/bin/fluentd:23:in `<main>'

The text was updated successfully, but these errors were encountered:

tagomoris · 2016-09-13T04:15:29Z

Is it a problem what you can reproduce? Is it only about Fluentd v0.14.6, or not?
Could you paste your configuration files?

jchauncey · 2016-09-13T04:18:38Z

<source>
  @type tail
  path /var/log/containers/*.log
  pos_file /var/log/containers.log.pos
  time_format %Y-%m-%dT%H:%M:%S.%NZ
  tag kubernetes.*
  format json
  read_from_head false
</source>

# Example:
# Dec 21 23:17:22 gke-foo-1-1-4b5cbd14-node-4eoj startupscript: Finished running startup script /var/run/google.startup.script
<source>
  @type tail
  format syslog
  path /var/log/startupscript.log
  pos_file /var/log/startupscript.log.pos
  tag startupscript
</source>

# Examples:
# time="2016-02-04T06:51:03.053580605Z" level=info msg="GET /containers/json"
# time="2016-02-04T07:53:57.505612354Z" level=error msg="HTTP Error" err="No such image: -f" statusCode=404
<source>
  @type tail
  format /^time="(?<time>[^)]*)" level=(?<severity>[^ ]*) msg="(?<message>[^"]*)"( err="(?<error>[^"]*)")?( statusCode=($<status_code>\d+))?/
  time_format %Y-%m-%dT%H:%M:%S.%NZ
  path /var/log/docker.log
  pos_file /var/log/docker.log.pos
  tag docker
</source>

# Example:
# 2016/02/04 06:52:38 filePurge: successfully removed file /var/etcd/data/member/wal/00000000000006d0-00000000010a23d1.wal
<source>
  @type tail
  # Not parsing this, because it doesn't have anything particularly useful to
  # parse out of it (like severities).
  format none
  path /var/log/etcd.log
  pos_file /var/log/etcd.log.pos
  tag etcd
</source>

# Multi-line parsing is required for all the kube logs because very large log
# statements, such as those that include entire object bodies, get split into
# multiple lines by glog.

# Example:
# I0204 07:32:30.020537    3368 server.go:1048] POST /stats/container/: (13.972191ms) 200 [[Go-http-client/1.1] 10.244.1.3:40537]
<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/kubelet.log.pos
  tag kubelet
</source>

# Example:
# I0204 07:00:19.604280       5 handlers.go:131] GET /api/v1/nodes: (1.624207ms) 200 [[kube-controller-manager/v1.1.3 (linux/amd64) kubernetes/6a81b50] 127.0.0.1:38266]
<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/kube-apiserver.log.pos
  tag kube-apiserver
</source>

# Example:
# I0204 06:55:31.872680       5 servicecontroller.go:277] LB already exists and doesn't need update for service kube-system/kube-ui
<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-controller-manager.log
  pos_file /var/log/kube-controller-manager.log.pos
  tag kube-controller-manager
</source>

# Example:
# W0204 06:49:18.239674       7 reflector.go:245] pkg/scheduler/factory/factory.go:193: watch of *api.Service ended with: 401: The event in requested index is outdated and cleared (the requested history has been cleared [2578313/2577886]) [2579312]
<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/kube-scheduler.log.pos
  tag kube-scheduler
</source>
  <filter kubernetes.**>
    @type kubernetes_metadata
    kubernetes_url https://10.167.240.1:443
    bearer_token_file /var/run/secrets/kubernetes.io/serviceaccount/token
    verify_ssl false
  </filter>
<match **>
  @type copy
<store>
  @type deis
</store>
</match>

This happens everytime i rebuild the image and redeploy. There is a fix I need in 0.14.6 so I dont think I would downgrade.

tagomoris · 2016-09-13T04:45:58Z

You have 8 sections for tail plugin. Can you specify which section is this problem about?
And could you paste the entire log if this problem happens just after Fluentd launched? Or, could you tell me when it occurs?

jchauncey · 2016-09-13T13:02:03Z

I don't know what section the error occurs in. And I gave you the relevant
stack trace.

On Sep 13, 2016 12:46 AM, "tagomoris" [email protected] wrote:

You have 8 sections for tail plugin. Can you specify which section is
this problem about?
And could you paste the entire log if this problem happens just after
Fluentd launched? Or, could you tell me when it occurs?

—
You are receiving this because you authored the thread.
Reply to this email directly, view it on GitHub
#1229 (comment),
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAaRGO6TtmYQreFhRKWdGFnEZ8WnWrHNks5qpiqRgaJpZM4J6swu
.

jchauncey · 2016-09-13T14:52:03Z

2016-09-13 14:46:56 +0000 [info]: reading config file path="/opt/fluentd/conf/fluentd.conf"
2016-09-13 14:46:56 +0000 [info]: starting fluentd-0.14.6
2016-09-13 14:46:56 +0000 [info]: spawn command to main: /usr/bin/ruby2.3 -Eascii-8bit:ascii-8bit /usr/local/bin/fluentd -c /opt/fluentd/conf/fluentd.conf --under-supervisor
2016-09-13 14:46:56 +0000 [info]: reading config file path="/opt/fluentd/conf/fluentd.conf"
2016-09-13 14:46:56 +0000 [info]: starting fluentd-0.14.6 without supervision
2016-09-13 14:46:56 +0000 [info]: gem 'fluent-mixin-config-placeholders' version '0.4.0'
2016-09-13 14:46:56 +0000 [info]: gem 'fluent-mixin-plaintextformatter' version '0.2.6'
2016-09-13 14:46:56 +0000 [info]: gem 'fluent-mixin-rewrite-tag-name' version '0.1.0'
2016-09-13 14:46:56 +0000 [info]: gem 'fluent-plugin-deis_output' version '0.1.0'
2016-09-13 14:46:56 +0000 [info]: gem 'fluent-plugin-elasticsearch' version '1.6.0'
2016-09-13 14:46:56 +0000 [info]: gem 'fluent-plugin-kubernetes_metadata_filter' version '0.25.3'
2016-09-13 14:46:56 +0000 [info]: gem 'fluent-plugin-remote_syslog' version '0.3.2'
2016-09-13 14:46:56 +0000 [info]: gem 'fluent-plugin-sumologic-mattk42' version '0.0.4'
2016-09-13 14:46:56 +0000 [info]: gem 'fluentd' version '0.14.6'
2016-09-13 14:46:56 +0000 [info]: gem 'fluentd' version '0.14.0'
2016-09-13 14:46:56 +0000 [info]: adding filter pattern="kubernetes.**" type="kubernetes_metadata"
2016-09-13 14:46:56 +0000 [info]: adding match pattern="**" type="copy"
2016-09-13 14:46:57 +0000 [info]: adding source type="tail"
2016-09-13 14:46:57 +0000 [info]: adding source type="tail"
2016-09-13 14:46:57 +0000 [info]: adding source type="tail"
2016-09-13 14:46:57 +0000 [info]: adding source type="tail"
2016-09-13 14:46:57 +0000 [info]: adding source type="tail"
2016-09-13 14:46:57 +0000 [info]: adding source type="tail"
2016-09-13 14:46:57 +0000 [info]: adding source type="tail"
2016-09-13 14:46:57 +0000 [info]: adding source type="tail"
2016-09-13 14:46:57 +0000 [info]: using configuration file: <ROOT>
  <source>
    @type tail
    path "/var/log/containers/*.log"
    pos_file "/var/log/containers.log.pos"
    time_format %Y-%m-%dT%H:%M:%S.%NZ
    tag "kubernetes.*"
    format json
    read_from_head false
    <parse>
      @type json
      time_format %Y-%m-%dT%H:%M:%S.%NZ
    </parse>
  </source>
  <source>
    @type tail
    format syslog
    path "/var/log/startupscript.log"
    pos_file "/var/log/startupscript.log.pos"
    tag "startupscript"
    <parse>
      @type syslog
    </parse>
  </source>
  <source>
    @type tail
    format /^time="(?<time>[^)]*)" level=(?<severity>[^ ]*) msg="(?<message>[^"]*)"( err="(?<error>[^"]*)")?( statusCode=($<status_code>\d+))?/
    time_format %Y-%m-%dT%H:%M:%S.%NZ
    path "/var/log/docker.log"
    pos_file "/var/log/docker.log.pos"
    tag "docker"
    <parse>
      @type /^time="(?<time>[^)]*)" level=(?<severity>[^ ]*) msg="(?<message>[^"]*)"( err="(?<error>[^"]*)")?( statusCode=($<status_code>\d+))?/
      time_format %Y-%m-%dT%H:%M:%S.%NZ
    </parse>
  </source>
  <source>
    @type tail
    format none
    path "/var/log/etcd.log"
    pos_file "/var/log/etcd.log.pos"
    tag "etcd"
    <parse>
      @type none
    </parse>
  </source>
  <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/kubelet.log.pos"
    tag "kubelet"
    <parse>
      @type multiline
      time_format %m%d %H:%M:%S.%N
      format_firstline /^\w\d{4}/
      format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/
    </parse>
  </source>
  <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/kube-apiserver.log.pos"
    tag "kube-apiserver"
    <parse>
      @type multiline
      time_format %m%d %H:%M:%S.%N
      format_firstline /^\w\d{4}/
      format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/
    </parse>
  </source>
  <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-controller-manager.log"
    pos_file "/var/log/kube-controller-manager.log.pos"
    tag "kube-controller-manager"
    <parse>
      @type multiline
      time_format %m%d %H:%M:%S.%N
      format_firstline /^\w\d{4}/
      format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/
    </parse>
  </source>
  <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/kube-scheduler.log.pos"
    tag "kube-scheduler"
    <parse>
      @type multiline
      time_format %m%d %H:%M:%S.%N
      format_firstline /^\w\d{4}/
      format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/
    </parse>
  </source>
  <filter kubernetes.**>
    @type kubernetes_metadata
    kubernetes_url "https://10.167.240.1:443"
    bearer_token_file "/var/run/secrets/kubernetes.io/serviceaccount/token"
    verify_ssl false
  </filter>
  <match **>
    @type copy
    <store>
      @type "deis"
    </store>
  </match>
</ROOT>
2016-09-13 14:46:57 +0000 [warn]: parameter 'time_format' in <parse>
  @type multiline
  time_format %m%d %H:%M:%S.%N
  format_firstline /^\w\d{4}/
  format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/
</parse> is not used.
2016-09-13 14:46:57 +0000 [warn]: parameter 'time_format' in <parse>
  @type multiline
  time_format %m%d %H:%M:%S.%N
  format_firstline /^\w\d{4}/
  format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/
</parse> is not used.
2016-09-13 14:46:57 +0000 [warn]: parameter 'time_format' in <parse>
  @type multiline
  time_format %m%d %H:%M:%S.%N
  format_firstline /^\w\d{4}/
  format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/
</parse> is not used.
2016-09-13 14:46:57 +0000 [warn]: parameter 'time_format' in <parse>
  @type multiline
  time_format %m%d %H:%M:%S.%N
  format_firstline /^\w\d{4}/
  format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/
</parse> is not used.
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/kubelet.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/docker.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/startupscript.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/deis-registry-proxy-nzoby_deis_POD-d6d87fdfd43dba3a0ce6006566614f3bd19970ab13bfa64f93e27b3e08096a1b.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/deis-logger-fluentd-hjmxx_deis_deis-logger-fluentd-b7a9ad0d69599653c9a89ed133291f08ee44656a1630de7120bbb13d7d59ea70.log
2016-09-13 14:46:57 +0000 [info]: Filtering works with worse performance, because [Fluent::KubernetesMetadataFilter] uses `#filter_stream` method.
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/fluentd-cloud-logging-gke-jchauncey-default-pool-625a6421-d11j_kube-system_fluentd-cloud-logging-6bca2e1aa495d57524cd4166f1639c63ec0808d8dcf56c790765b7aff5901a5c.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/deis-database-o2hqi_deis_POD-7e90eb0837967e3218e99818ead933675c8feff9a5567c33b2ad2679cdb87a57.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/kube-dns-v17.1-jwuw9_kube-system_POD-12f6f8e729213e2aa9cb7f5223352364ccf1e3a045fefa3cacb4dba651afa607.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/kube-dns-v17.1-jwuw9_kube-system_dnsmasq-41e31d50c29841335512720b290f3402fac9552d1e0bb706a2407ed7e109a575.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/deis-monitor-influxdb-gjgyb_deis_deis-monitor-influxdb-9339c7b37429a3527c9fe9c890cdae497fc36f192b0b006ad310c9f0f222470c.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/kube-proxy-gke-jchauncey-default-pool-625a6421-d11j_kube-system_POD-67898ff422cc0a297af3a1666889cf5abd47efe3c4006f17fd0a365bb7c6d222.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/deis-minio-7witf_deis_POD-e8adadff78650177db428ac25c2e497a14f75313c4c506723c6d8c70bb2dde3f.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/kube-dns-v17.1-jwuw9_kube-system_healthz-923bd9879265e66a9ba484da09eaf3601da5e937087c622ed01188f6e565a613.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/deis-registry-proxy-nzoby_deis_deis-registry-proxy-d4816a263a648227b4fdc76ac8a65f3b9119c73e2a8d7d7166aba538614f0067.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/kube-proxy-gke-jchauncey-default-pool-625a6421-d11j_kube-system_POD-acd61bdfd7562a4dd15a4aa0bdead6198a765f97604cdd3574a9a9593bb7d75d.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/fluentd-cloud-logging-gke-jchauncey-default-pool-625a6421-d11j_kube-system_fluentd-cloud-logging-2ea7fd7a2767cd62b5ca58c155de4876ee6a1ea68b0986464472c4456961c57d.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/kube-dns-v17.1-jwuw9_kube-system_dnsmasq-ba792ed3309bb326c6dd01dc61944724824158e478dd6a57365e8d08addd8758.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/fluentd-cloud-logging-gke-jchauncey-default-pool-625a6421-d11j_kube-system_POD-a9e4365ec493a860ee9d13303fd6813e14d529358d0bca15e27c041acc4b6d7e.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/deis-logger-fluentd-hjmxx_deis_POD-c1d60448fafa4b2fe260e19106ccd94c76e387fc980c752463c27a27de0d1777.log
2016-09-13 14:46:57 +0000 [info]: Filtering works with worse performance, because [Fluent::KubernetesMetadataFilter] uses `#filter_stream` method.
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/kube-dns-v17.1-jwuw9_kube-system_POD-8d829b1a2a3f4c30989a526ef65527428f62035a16e4125addc531afdd7f0128.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/deis-monitor-telegraf-zfdde_deis_deis-monitor-telegraf-aaf542a00114f9200f936e5425423c3d4b73e96ae5eaad5461f9a73723d6d923.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/deis-minio-7witf_deis_deis-minio-1d1bb1bc197eb54759e651832d27225d803792df40b9eb7462444b5ed1b46027.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/kube-dns-v17.1-jwuw9_kube-system_kubedns-dff644ea24c7684cc9f98f1a2d0d2a4831e8d3bf4eb1c70cb50d95adeecddb70.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/deis-logger-fluentd-wzhle_deis_deis-logger-fluentd-3dc205fb1601276170d9f22739ebfe26cdea79cf6dc52b0293e258f5d3bee741.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/fluentd-cloud-logging-gke-jchauncey-default-pool-625a6421-d11j_kube-system_POD-3f3c9b906c2f48654be5768758cc0f6cf26a469eb57ec168d8ff10c2d54d0d29.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/deis-logger-fluentd-wzhle_deis_POD-8e110b294b874e255ad83ba40c658d45ad9e938b8dc46707944e8d194a854737.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/kube-proxy-gke-jchauncey-default-pool-625a6421-d11j_kube-system_kube-proxy-5995f8404f2f7a0905d427399e89b473407b5b30c520812f23454064bb65ec32.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/kube-dns-v17.1-jwuw9_kube-system_healthz-7b7ffbad0f8d77754950094d434cfc65a9e1a436cfc865479661a3f462e90f29.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/deis-monitor-telegraf-zfdde_deis_POD-59d74ef8b95c765e11826d975dae1b7bd353e3adde9de86eb3ef74b18f9ed234.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/kube-dns-v17.1-jwuw9_kube-system_kubedns-7bb688f1915a2f76e5f3becbad0c507ba02c23b31b532d58dbc38c888b2d0a44.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/kube-proxy-gke-jchauncey-default-pool-625a6421-d11j_kube-system_kube-proxy-758605527f02c47034aa5fd1b923c5573d0c5883eb015c217db64017480c0a1b.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/deis-monitor-influxdb-gjgyb_deis_POD-7df553d175f070519d3c5b989e784d72b24d326d8475777298efbdc4da192707.log
2016-09-13 14:46:57 +0000 [info]: following tail of /var/log/containers/deis-database-o2hqi_deis_deis-database-59827ad49f32d432768b2b3fc6100e5329f4f452b946804b3bd5d5ab22797148.log
2016-09-13 14:46:58 +0000 [info]: Filtering works with worse performance, because [Fluent::KubernetesMetadataFilter] uses `#filter_stream` method.
2016-09-13 14:47:16 +0000 [info]: Filtering works with worse performance, because [Fluent::KubernetesMetadataFilter] uses `#filter_stream` method.
2016-09-13 14:47:43 +0000 [info]: detected rotation of /var/log/containers/deis-logger-fluentd-hjmxx_deis_deis-logger-fluentd-b7a9ad0d69599653c9a89ed133291f08ee44656a1630de7120bbb13d7d59ea70.log; waiting 5 seconds
2016-09-13 14:47:43 +0000 [info]: detected rotation of /var/log/containers/deis-logger-fluentd-hjmxx_deis_POD-c1d60448fafa4b2fe260e19106ccd94c76e387fc980c752463c27a27de0d1777.log; waiting 5 seconds
2016-09-13 14:47:49 +0000 [error]: closed stream
  2016-09-13 14:47:49 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:561:in `readpartial'
  2016-09-13 14:47:49 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:561:in `on_notify'
  2016-09-13 14:47:49 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:444:in `on_notify'
  2016-09-13 14:47:49 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin_helper/timer.rb:76:in `on_timer'
  2016-09-13 14:47:49 +0000 [error]: /var/lib/gems/2.3.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run_once'
  2016-09-13 14:47:49 +0000 [error]: /var/lib/gems/2.3.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run'
  2016-09-13 14:47:49 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin_helper/event_loop.rb:71:in `block in start'
  2016-09-13 14:47:49 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin_helper/thread.rb:66:in `block in thread_create'
2016-09-13 14:47:49 +0000 [error]: closed stream
  2016-09-13 14:47:49 +0000 [error]: suppressed same stacktrace
2016-09-13 14:47:50 +0000 [error]: closed stream
  2016-09-13 14:47:50 +0000 [error]: suppressed same stacktrace
2016-09-13 14:47:50 +0000 [error]: closed stream
  2016-09-13 14:47:50 +0000 [error]: suppressed same stacktrace
2016-09-13 14:47:51 +0000 [error]: closed stream
  2016-09-13 14:47:51 +0000 [error]: suppressed same stacktrace
2016-09-13 14:47:51 +0000 [error]: closed stream
  2016-09-13 14:47:51 +0000 [error]: suppressed same stacktrace
2016-09-13 14:47:52 +0000 [error]: closed stream
  2016-09-13 14:47:52 +0000 [error]: suppressed same stacktrace
2016-09-13 14:47:52 +0000 [error]: closed stream
  2016-09-13 14:47:52 +0000 [error]: suppressed same stacktrace
2016-09-13 14:47:53 +0000 [error]: closed stream

jchauncey · 2016-09-13T15:04:31Z

If you go back to 0.14.5 you get this error -

2016-09-13 15:01:39 +0000 [error]: unexpected error error="uninitialized constant Fluent::Plugin::MultilineParser\nDid you mean?  Fluent::MultiEventStream"
  2016-09-13 15:01:39 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.5/lib/fluent/plugin/in_tail.rb:88:in `configure'
  2016-09-13 15:01:39 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.5/lib/fluent/root_agent.rb:237:in `add_source'
  2016-09-13 15:01:39 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.5/lib/fluent/root_agent.rb:95:in `block in configure'
  2016-09-13 15:01:39 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.5/lib/fluent/root_agent.rb:92:in `each'
  2016-09-13 15:01:39 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.5/lib/fluent/root_agent.rb:92:in `configure'
  2016-09-13 15:01:39 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.5/lib/fluent/engine.rb:119:in `configure'
  2016-09-13 15:01:39 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.5/lib/fluent/engine.rb:93:in `run_configure'
  2016-09-13 15:01:39 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.5/lib/fluent/supervisor.rb:673:in `run_configure'
  2016-09-13 15:01:39 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.5/lib/fluent/supervisor.rb:435:in `block in run_worker'
  2016-09-13 15:01:39 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.5/lib/fluent/supervisor.rb:606:in `main_process'
  2016-09-13 15:01:39 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.5/lib/fluent/supervisor.rb:431:in `run_worker'
  2016-09-13 15:01:39 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.5/lib/fluent/command/fluentd.rb:271:in `<top (required)>'
  2016-09-13 15:01:39 +0000 [error]: /usr/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb:68:in `require'
  2016-09-13 15:01:39 +0000 [error]: /usr/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb:68:in `require'
  2016-09-13 15:01:39 +0000 [error]: /var/lib/gems/2.3.0/gems/fluentd-0.14.5/bin/fluentd:5:in `<top (required)>'
  2016-09-13 15:01:39 +0000 [error]: /usr/local/bin/fluentd:23:in `load'
  2016-09-13 15:01:39 +0000 [error]: /usr/local/bin/fluentd:23:in `<main>'

tagomoris · 2016-09-14T04:07:49Z

How about with v0.14.4? It's a bug introduced at v0.14.5.

jchauncey · 2016-09-14T13:10:02Z

Ah k yeah moving back to 0.14.4 seems to have fixed the problem

tagomoris · 2016-09-15T02:05:18Z

Thank you for reporting it! I'll investigate that problem further more.

gcs-github · 2016-09-21T00:55:48Z

if it helps, I've also encountered can't modify string; temporarily locked in one of my installations.

The only obvious differences between an in_tail config without this problem and an in_tail config with this problem for me are read_from_head being true and the format being multiline on the problematic config. There's also a different match & filter chain routing after the in_tail input.

I can post more details if needed.

repeatedly · 2016-09-21T01:27:58Z

@gcs-github Do you use fluentd v0.14.6?

gcs-github · 2016-09-21T08:29:45Z

yes

repeatedly · 2016-09-21T08:37:02Z

@gcs-github I want to know using v0.14.4 resolve your problem or not? Since v0.14.5, we migrate in_tail plugin with v0.14 API. If the problem is gone with v0.14.4, we need to check this migration change.

cjdmax · 2016-09-21T08:55:53Z

same error here with 0.14.6, moving back to 0.14.4 seems to have mitigated the problem.

repeatedly · 2016-09-21T09:05:05Z

This error doesn't happen on fluentd test. So I want more information to investigate the problem.

@cjdmax @gcs-github Could you give me a entire fluentd logs? I want to check the configuration and error patterns.

gcs-github · 2016-09-21T09:36:38Z

I shared the logs privately with you @repeatedly in the fluentd Slack, and I'm now testing with 0.14.4

gcs-github · 2016-09-21T11:00:35Z

The problem seems to be gone with 0.14.4 for me as well.

gcs-github · 2016-09-21T22:01:31Z

If it helps: I switched back to 0.14.6 and discovered I had mistakes in the configuration of some of my <match> sections which apply to the data coming from my in_tail source. These mistakes were causing problems of their own, raising exceptions. I fixed the issues I had in my <match> sections and haven't encountered the original can't modify string; temporarily locked problem since.

Could ruby exceptions downstream of the in_tail source maybe cause problems with the in_tail source itself?

I'll update this issue again if I stumble upon the problem again.

cmachler · 2016-09-23T05:13:12Z

@repeatedly I had the same issue, I rolled back from 0.14.6 to 0.14.4. Let me know if you need any information from my environment.

fluent/fluentd#1229

repeatedly · 2016-09-27T08:08:49Z

@cmachler We are now investigating this issue. The flow late is not related with this error, right?

We are now trying to reproduce this problem on our side and write a patch. Please wait...

cmachler · 2016-09-27T15:06:47Z

@repeatedly if you're referring to my slack message, no. I'm good with running 0.14.4.

okkez · 2016-09-28T02:27:07Z

Reproduce sequence(on master HEAD):

fluent.conf:

<source>
  @type tail
  path tmp/logs/*.log
  pos_file tmp/logs/tail.pos
  read_from_head true
  tag test.log
  format json
#  <parse>
#    @type json
#  </parse>
</source>

<match **>
  @type null
</match>

append.rb:

require "time"
require "json"
require "fileutils"

5.times do |n|
  FileUtils.touch("tmp/logs/log#{n}.log")
end

LOG_FILES = Dir.glob("tmp/logs/*.log")

MESSAGE = "This is dummy log message!" * 10

def append_log(file)
  time = Time.now.strftime("%Y-%m-%dT%H:%M:%S.%NZ")
  log = {
    "time" => time,
    "message" => MESSAGE
  }
  file.puts(log.to_json)
end

def rotate_file_if_needed(file)
  return false if file.size < 1024 * 1024 * 500 # 500MiB

  path = file.path
  FileUtils.mv(path, "#{path}.#{Time.now.to_f}")
  #sleep(30)
  FileUtils.touch(path)
  file.close
  puts "#{Time.now}: rotated file: #{path}"
  true
end

Signal.trap(:INT) do
  exit(true)
end

def run
  loop do
    files = LOG_FILES.map do |path|
      File.open(path, "ab+")
    end
    rotated = false
    loop do
      files.each do |file|
        append_log(file)
        rotated = rotate_file_if_needed(file)
        break if rotated
      end
      break if rotated
    end
  end
end

run

Create large log files:

$ cp tmp/600M.log tmp/logs/log0.log
$ cp tmp/600M.log tmp/logs/log1.log
$ cp tmp/600M.log tmp/logs/log2.log
$ cp tmp/600M.log tmp/logs/log3.log
$ cp tmp/600M.log tmp/logs/log4.log
($ rm -f tmp/logs/tail.pos)
($ rm -f tmp/logs/log*.log.*)

Run fluend:

$ bundle exec fluentd -c fluent.conf

Run append.rb on another terminal:

$ ruby append.rb

Check fluentd logs.

repeatedly · 2016-09-28T08:28:16Z

Thanks for finding reproducible step.
I will check the behaviour changes between v0.12 and v0.14.

repeatedly · 2016-10-05T01:45:57Z

We found one possible reason to cause this issue.
Try to fix soon.

This change fixes fluent#1229

repeatedly · 2016-10-07T07:23:18Z

Released v0.14.7 including this fix.
Could you test it again with v0.14.7?

cmachler · 2016-10-14T15:29:43Z

working well for me now. Thanks!

repeatedly · 2016-10-14T16:15:24Z

thanks for the test 👍

There are important changes in 0.14.7, namely options to rotate fluentd's own logs, compression and a fix for fluent/fluentd#1229

There are important changes in 0.14.7, namely options to rotate fluentd's own logs, compression and a fix for fluent/fluentd#1229 Using 0.14.8 because it is the latest, with another minor fix.

tagomoris added the moreinfo Missing version, need reproducible steps, need to investigate more label Sep 13, 2016

tagomoris added bug Something isn't working v0.14 and removed moreinfo Missing version, need reproducible steps, need to investigate more labels Sep 15, 2016

tagomoris self-assigned this Sep 15, 2016

cmachler pushed a commit to cmachler/fluentd-kubernetes-coreos-secure that referenced this issue Sep 23, 2016

Falling back fluentd version to 0.14.4 hitting known bug

e93eadc

fluent/fluentd#1229

tagomoris assigned repeatedly and unassigned tagomoris Sep 28, 2016

okkez added a commit to okkez/fluentd that referenced this issue Oct 5, 2016

in_tail: Detach timer trigger when detach TailWatcher

611445d

This change fixes fluent#1229

okkez mentioned this issue Oct 5, 2016

in_tail: Detach timer trigger when detach TailWatcher #1259

Merged

repeatedly closed this as completed in #1259 Oct 5, 2016

akihiro17 mentioned this issue Oct 5, 2016

Run TailWatcher#on_notify before attaching triggers #1261

Merged

therc added a commit to therc/docker-fluentd that referenced this issue Oct 20, 2016

Update fluentd to 0.14.8

819dadb

There are important changes in 0.14.7, namely options to rotate fluentd's own logs, compression and a fix for fluent/fluentd#1229

therc mentioned this issue Oct 20, 2016

Update fluentd to 0.14.8 fabric8io/docker-fluentd#1

Merged

therc mentioned this issue Oct 20, 2016

Update fluentd to 0.14.8 fabric8io/docker-fluentd-kubernetes#17

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Errors with in_tail plugin in 0.14.6 #1229

Errors with in_tail plugin in 0.14.6 #1229

jchauncey commented Sep 12, 2016

tagomoris commented Sep 13, 2016

jchauncey commented Sep 13, 2016

tagomoris commented Sep 13, 2016

jchauncey commented Sep 13, 2016

jchauncey commented Sep 13, 2016

jchauncey commented Sep 13, 2016

tagomoris commented Sep 14, 2016

jchauncey commented Sep 14, 2016

tagomoris commented Sep 15, 2016

gcs-github commented Sep 21, 2016

repeatedly commented Sep 21, 2016

gcs-github commented Sep 21, 2016

repeatedly commented Sep 21, 2016

cjdmax commented Sep 21, 2016

repeatedly commented Sep 21, 2016

gcs-github commented Sep 21, 2016

gcs-github commented Sep 21, 2016

gcs-github commented Sep 21, 2016 •

edited

Loading

cmachler commented Sep 23, 2016

repeatedly commented Sep 27, 2016

cmachler commented Sep 27, 2016

okkez commented Sep 28, 2016

repeatedly commented Sep 28, 2016 •

edited

Loading

repeatedly commented Oct 5, 2016

repeatedly commented Oct 7, 2016 •

edited

Loading

cmachler commented Oct 14, 2016

repeatedly commented Oct 14, 2016

Errors with in_tail plugin in 0.14.6 #1229

Errors with in_tail plugin in 0.14.6 #1229

Comments

jchauncey commented Sep 12, 2016

tagomoris commented Sep 13, 2016

jchauncey commented Sep 13, 2016

tagomoris commented Sep 13, 2016

jchauncey commented Sep 13, 2016

jchauncey commented Sep 13, 2016

jchauncey commented Sep 13, 2016

tagomoris commented Sep 14, 2016

jchauncey commented Sep 14, 2016

tagomoris commented Sep 15, 2016

gcs-github commented Sep 21, 2016

repeatedly commented Sep 21, 2016

gcs-github commented Sep 21, 2016

repeatedly commented Sep 21, 2016

cjdmax commented Sep 21, 2016

repeatedly commented Sep 21, 2016

gcs-github commented Sep 21, 2016

gcs-github commented Sep 21, 2016

gcs-github commented Sep 21, 2016 • edited Loading

cmachler commented Sep 23, 2016

repeatedly commented Sep 27, 2016

cmachler commented Sep 27, 2016

okkez commented Sep 28, 2016

repeatedly commented Sep 28, 2016 • edited Loading

repeatedly commented Oct 5, 2016

repeatedly commented Oct 7, 2016 • edited Loading

cmachler commented Oct 14, 2016

repeatedly commented Oct 14, 2016

gcs-github commented Sep 21, 2016 •

edited

Loading

repeatedly commented Sep 28, 2016 •

edited

Loading

repeatedly commented Oct 7, 2016 •

edited

Loading