Fluentd: Errors with in_tail plugin in 0.14.6

[jchauncey]

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>'

[tagomoris]

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]

<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]

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]

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
https://github.com/fluent/fluentd/issues/1229#issuecomment-246572450,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAaRGO6TtmYQreFhRKWdGFnEZ8WnWrHNks5qpiqRgaJpZM4J6swu
.

[jchauncey]

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]

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]

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

[jchauncey]

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

[tagomoris]

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

[gcs-github]

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]

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

[gcs-github]

yes

[repeatedly]

@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]

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

[repeatedly]

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]

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

[gcs-github]

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

[gcs-github]

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]

@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.

[repeatedly]

@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]

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

[okkez]

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]

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

[repeatedly]

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

[repeatedly]

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

[cmachler]

working well for me now. Thanks!

[repeatedly]

thanks for the test 👍