Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

in_tail plugin crashes on multiple gracefulReloads of fluentd #3333

Closed
alex-vmw opened this issue Apr 16, 2021 · 4 comments
Closed

in_tail plugin crashes on multiple gracefulReloads of fluentd #3333

alex-vmw opened this issue Apr 16, 2021 · 4 comments
Assignees
@ashie
Labels
bug

Comments

@alex-vmw
Copy link

Describe the bug
We were performing tests that were issuing multiple /api/config.gracefulReload calls to fluentd. After issuing 2+ gracefulReloads one right after another (without letting fluentd fully go through the reload) we can see the below error in the logs:

2021-04-16 01:34:19 +0000 [error]: #0 [in_tail_container_logs] closed stream
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail/position_file.rb:212:in `pos='
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail/position_file.rb:212:in `block in update_pos'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail/position_file.rb:211:in `synchronize'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail/position_file.rb:211:in `update_pos'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:933:in `block in handle_notify'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:964:in `with_io'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:912:in `handle_notify'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:895:in `block in on_notify'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:895:in `synchronize'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:895:in `on_notify'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:724:in `on_notify'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:376:in `setup_watcher'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:410:in `block in start_watchers'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:396:in `each_value'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:396:in `start_watchers'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:359:in `refresh_watchers'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:234:in `start'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:200:in `block in start'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:189:in `block (2 levels) in lifecycle'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:188:in `each'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:188:in `block in lifecycle'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:175:in `each'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:175:in `lifecycle'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:199:in `start'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/engine.rb:244:in `start_phase'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/engine.rb:201:in `reload_config'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/supervisor.rb:915:in `block (2 levels) in reload_config'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/variable_store.rb:32:in `try_to_reset'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/supervisor.rb:914:in `block in reload_config'
2021-04-16 01:34:19 +0000 [error]: #0 fluent/log.rb:371:error: failed to reload config: undefined method `synchronize' for nil:NilClass

To Reproduce
Reload fluentd config 2+ times via /api/config.gracefulReload call one right after another (without letting fluentd fully go through the reload).

Expected behavior
in_tail plugin shouldn't crash on multiple fluentd reloads.

Your Environment

  • Fluentd or td-agent version: fluentd 1.12.2 we also tested with 1.9.1 and 1.11.2 and saw same issue in those as well.
  • Operating system: Ubuntu 20.04.1 LTS
  • Kernel version: 5.4.0-42-generic

Your Configuration

<ROOT>
  <system>
    log_level info
    rpc_endpoint "127.0.0.1:24444"
  </system>
  <source>
    @type systemd
    @id in_systemd_docker
    path "/var/log/journal"
    tag "systemd.unit"
    read_from_head false
    <storage>
      @type "local"
      persistent true
      path "/var/log/-kube-fluentd-operator--fluentd-journald-cursor.json"
    </storage>
    <entry>
      field_map {"_SYSTEMD_UNIT":"unit","MESSAGE":"log","_PID":["pid"],"_PRIORITY":"priority","_COMM":"cmd","_HOSTNAME":"hostname"}
      field_map_strict true
      fields_lowercase true
    </entry>
  </source>
  <match systemd.unit>
    @type rewrite_tag_filter
    <rule>
      key "unit"
      pattern ^(.+)$
      tag "systemd.$1"
    </rule>
  </match>
  <filter systemd.kubelet.service>
    @type parser
    reserve_data true
    key_name "log"
    emit_invalid_record_to_error false
    <parse>
      @type "kubernetes"
      time_format "%m%d %H:%M:%S.%N"
      expression /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/m
    </parse>
  </filter>
  <source>
    @type tail
    @id in_tail_container_logs
    path "/var/log/containers/*.log"
    pos_file "/var/log/-kube-fluentd-operator--fluentd-containers.log.pos"
    tag "kubernetes.*"
    read_from_head true
    <parse>
      @type "multiline"
      format1 /^(?<partials>([^\n]+ (stdout|stderr) P [^\n]+\n)*)/
      format2 /(?<time>[^\n]+) (?<stream>stdout|stderr) F (?<log>[^\n]*)/
      format3 /|(?<json>{.*})/
      time_format "%Y-%m-%dT%H:%M:%S.%N%:z"
      unmatched_lines
    </parse>
  </source>
  <filter kubernetes.**>
    @type record_transformer
    @id filter_crio_container_logs
    enable_ruby true
    remove_keys partials
    <record>
      log ${record["partials"]&.gsub(/.+ (stdout|stderr) P (.+)\n/, '\\2')}${record["log"]}
    </record>
  </filter>
  <filter kubernetes.**>
    @type parser
    @id filter_docker_container_logs
    key_name "json"
    remove_key_name_field true
    reserve_data true
    emit_invalid_record_to_error false
    <parse>
      @type "json"
      time_format "%Y-%m-%dT%H:%M:%S.%NZ"
      time_type string
    </parse>
  </filter>
  <source>
    @type tail
    @id in_tail_startupscript
    path "/var/log/startupscript.log"
    pos_file "/var/log/-kube-fluentd-operator--fluentd-startupscript.log.pos"
    tag "startupscript"
    <parse>
      @type "syslog"
      unmatched_lines
    </parse>
  </source>
  <source>
    @type tail
    @id in_tail_docker
    path "/var/log/docker.log"
    pos_file "/var/log/-kube-fluentd-operator--fluentd-docker.log.pos"
    tag "docker"
    <parse>
      @type "regexp"
      expression /^time="(?<time>[^)]*)" level=(?<severity>[^ ]*) msg="(?<message>[^"]*)"( err="(?<error>[^"]*)")?( statusCode=($<status_code>\d+))?/
      unmatched_lines
    </parse>
  </source>
  <source>
    @type tail
    @id in_tail_etcd
    path "/var/log/etcd.log"
    pos_file "/var/log/-kube-fluentd-operator--fluentd-etcd.log.pos"
    tag "k8s.etcd"
    <parse>
      @type "none"
      unmatched_lines
    </parse>
  </source>
  <source>
    @type tail
    @id in_tail_kubelet
    multiline_flush_interval 5s
    path "/var/log/kubelet.log"
    pos_file "/var/log/-kube-fluentd-operator--fluentd-kubelet.log.pos"
    tag "k8s.kubelet"
    <parse>
      @type "kubernetes"
      unmatched_lines
      expression /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/m
      time_format "%m%d %H:%M:%S.%N"
    </parse>
  </source>
  <source>
    @type tail
    @id in_tail_kube_proxy
    multiline_flush_interval 5s
    path "/var/log/kube-proxy.log"
    pos_file "/var/log/-kube-fluentd-operator--fluentd-kube-proxy.log.pos"
    tag "k8s.kube-proxy"
    <parse>
      @type "kubernetes"
      unmatched_lines
      expression /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/m
      time_format "%m%d %H:%M:%S.%N"
    </parse>
  </source>
  <source>
    @type tail
    @id in_tail_kube_apiserver
    multiline_flush_interval 5s
    path "/var/log/kube-apiserver.log"
    pos_file "/var/log/-kube-fluentd-operator--fluentd-kube-apiserver.log.pos"
    tag "k8s.kube-apiserver"
    <parse>
      @type "kubernetes"
      unmatched_lines
      expression /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/m
      time_format "%m%d %H:%M:%S.%N"
    </parse>
  </source>
  <source>
    @type tail
    @id in_tail_kube_controller_manager
    multiline_flush_interval 5s
    path "/var/log/kube-controller-manager.log"
    pos_file "/var/log/-kube-fluentd-operator--fluentd-kube-controller-manager.log.pos"
    tag "k8s.kube-controller-manager"
    <parse>
      @type "kubernetes"
      unmatched_lines
      expression /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/m
      time_format "%m%d %H:%M:%S.%N"
    </parse>
  </source>
  <source>
    @type tail
    @id in_tail_kube_scheduler
    multiline_flush_interval 5s
    path "/var/log/kube-scheduler.log"
    pos_file "/var/log/-kube-fluentd-operator--fluentd-kube-scheduler.log.pos"
    tag "k8s.kube-scheduler"
    <parse>
      @type "kubernetes"
      unmatched_lines
      expression /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/m
      time_format "%m%d %H:%M:%S.%N"
    </parse>
  </source>
  <source>
    @type tail
    @id in_tail_rescheduler
    multiline_flush_interval 5s
    path "/var/log/rescheduler.log"
    pos_file "/var/log/-kube-fluentd-operator--fluentd-rescheduler.log.pos"
    tag "k8s.rescheduler"
    <parse>
      @type "kubernetes"
      unmatched_lines
      expression /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/m
      time_format "%m%d %H:%M:%S.%N"
    </parse>
  </source>
  <source>
    @type tail
    @id in_tail_glbc
    multiline_flush_interval 5s
    path "/var/log/glbc.log"
    pos_file "/var/log/-kube-fluentd-operator--fluentd-glbc.log.pos"
    tag "k8s.glbc"
    <parse>
      @type "kubernetes"
      unmatched_lines
      expression /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/m
      time_format "%m%d %H:%M:%S.%N"
    </parse>
  </source>
  <source>
    @type tail
    @id in_tail_cluster_autoscaler
    multiline_flush_interval 5s
    path "/var/log/cluster-autoscaler.log"
    pos_file "/var/log/-kube-fluentd-operator--fluentd-cluster-autoscaler.log.pos"
    tag "k8s.cluster-autoscaler"
    <parse>
      @type "kubernetes"
      unmatched_lines
      expression /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/m
      time_format "%m%d %H:%M:%S.%N"
    </parse>
  </source>
  <source>
    @type tail
    @id in_tail_kube_apiserver_audit
    multiline_flush_interval 5s
    path "/var/log/kubernetes/kube-apiserver-audit.log"
    pos_file "/var/log/-kube-fluentd-operator--kube-apiserver-audit.log.pos"
    tag "k8s.kube-apiserver-audit"
    <parse>
      @type "multiline"
      format_firstline "/^\\S+\\s+AUDIT:/"
      format1 /^(?<time>\S+) AUDIT:(?: (?:id="(?<id>(?:[^"\\]|\\.)*)"|ip="(?<ip>(?:[^"\\]|\\.)*)"|method="(?<method>(?:[^"\\]|\\.)*)"|user="(?<user>(?:[^"\\]|\\.)*)"|groups="(?<groups>(?:[^"\\]|\\.)*)"|as="(?<as>(?:[^"\\]|\\.)*)"|asgroups="(?<asgroups>(?:[^"\\]|\\.)*)"|namespace="(?<namespace>(?:[^"\\]|\\.)*)"|uri="(?<uri>(?:[^"\\]|\\.)*)"|response="(?<response>(?:[^"\\]|\\.)*)"|\w+="(?:[^"\\]|\\.)*"))*/
      time_format "%Y-%m-%dT%T.%L%Z"
      unmatched_lines
    </parse>
  </source>
  <filter kubernetes.**>
    @type kubernetes_metadata
    @id filter_kube_metadata
  </filter>
  <filter kubernetes.**>
    @type kubernetes_metadata
  </filter>
  <filter kubernetes.**>
    @type record_transformer
    enable_ruby true
    <record>
      kubernetes_namespace_container_name ${record["kubernetes"]["namespace_name"]}.${record["kubernetes"]["pod_name"]}.${record["kubernetes"]["container_name"]}
      container_info ${record["docker"]["container_id"]}-${record["stream"]}
    </record>
  </filter>
  <match kubernetes.**>
    @type rewrite_tag_filter
    <rule>
      key "kubernetes_namespace_container_name"
      pattern ^(.+)$
      tag "kube.$1"
    </rule>
  </match>
  <filter kube.*.*.*>
    @type record_modifier
    remove_keys "dummy_"
    <record>
      dummy_ ${record["kubernetes"]&.delete("master_url"); record["kubernetes"]&.delete("namespace_id"); if record["kubernetes"]&.has_key?("labels"); record["kubernetes"]["labels"].delete("pod-template-generation"); record["kubernetes"]["labels"].delete("controller-revision-hash");  record["kubernetes"]["labels"].delete("pod-template-hash"); end; nil}
    </record>
  </filter>
  <filter kube.*.*.*>
    @type record_transformer
    remove_keys kubernetes_namespace_container_name
  </filter>
  <filter kube.kube-system.**>
    @type parser
    reserve_data true
    key_name "log"
    emit_invalid_record_to_error false
    <parse>
      @type "kubernetes"
      time_format "%m%d %H:%M:%S.%N"
      expression /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/m
    </parse>
  </filter>
  <source>
    @type prometheus
  </source>
  <source>
    @type prometheus_monitor
  </source>
  <source>
    @type prometheus_output_monitor
  </source>
  <match systemd.** kube.kube-system.**>
    @type copy
    <store>
      @id X
      @type "vmware_loginsight"
      host "X.X.X.X"
      include_tag_key true
      log_text_keys ["log","msg","message"]
      port 9000
      scheme "http"
      serializer "json"
      ssl_verify false
      tag_key "tag"
    </store>
  </match>
  <match **>
    @type null
  </match>
</ROOT>

Your Error Log

2021-04-16 01:34:19 +0000 [error]: #0 [in_tail_container_logs] closed stream
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail/position_file.rb:212:in `pos='
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail/position_file.rb:212:in `block in update_pos'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail/position_file.rb:211:in `synchronize'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail/position_file.rb:211:in `update_pos'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:933:in `block in handle_notify'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:964:in `with_io'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:912:in `handle_notify'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:895:in `block in on_notify'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:895:in `synchronize'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:895:in `on_notify'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:724:in `on_notify'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:376:in `setup_watcher'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:410:in `block in start_watchers'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:396:in `each_value'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:396:in `start_watchers'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:359:in `refresh_watchers'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:234:in `start'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:200:in `block in start'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:189:in `block (2 levels) in lifecycle'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:188:in `each'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:188:in `block in lifecycle'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:175:in `each'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:175:in `lifecycle'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:199:in `start'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/engine.rb:244:in `start_phase'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/engine.rb:201:in `reload_config'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/supervisor.rb:915:in `block (2 levels) in reload_config'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/variable_store.rb:32:in `try_to_reset'
  2021-04-16 01:34:19 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/supervisor.rb:914:in `block in reload_config'
2021-04-16 01:34:19 +0000 [error]: #0 fluent/log.rb:371:error: failed to reload config: undefined method `synchronize' for nil:NilClass

Additional context
@alex-vmw
Copy link
Author

We are also seeing similar, but still different stack trace under the same conditions:

2021-04-16 03:54:12 +0000 [error]: #0 [in_tail_container_logs] closed stream
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail/position_file.rb:212:in `pos='
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail/position_file.rb:212:in `block in update_pos'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail/position_file.rb:211:in `synchronize'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail/position_file.rb:211:in `update_pos'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:933:in `block in handle_notify'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:964:in `with_io'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:912:in `handle_notify'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:895:in `block in on_notify'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:895:in `synchronize'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:895:in `on_notify'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:724:in `on_notify'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:376:in `setup_watcher'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:410:in `block in start_watchers'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:396:in `each_value'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:396:in `start_watchers'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:359:in `refresh_watchers'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:234:in `start'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:200:in `block in start'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:189:in `block (2 levels) in lifecycle'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:188:in `each'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:188:in `block in lifecycle'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:175:in `each'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:175:in `lifecycle'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:199:in `start'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/engine.rb:248:in `start'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/engine.rb:147:in `run'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/supervisor.rb:700:in `block in run_worker'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/supervisor.rb:951:in `main_process'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/supervisor.rb:691:in `run_worker'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/command/fluentd.rb:365:in `<top (required)>'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/2.7.0/rubygems/core_ext/kernel_require.rb:83:in `require'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/2.7.0/rubygems/core_ext/kernel_require.rb:83:in `require'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/bin/fluentd:8:in `<top (required)>'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/bin/fluentd:23:in `load'
  2021-04-16 03:54:12 +0000 [error]: #0 /usr/local/bin/fluentd:23:in `<main>'
2021-04-16 03:54:12 +0000 [error]: #0 fluent/log.rb:371:error: unexpected error error_class=NoMethodError error="undefined method `synchronize' for nil:NilClass"
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin_helper/event_loop.rb:50:in `event_loop_detach'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:386:in `block in setup_watcher'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:385:in `each'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:385:in `rescue in setup_watcher'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:362:in `setup_watcher'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:410:in `block in start_watchers'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:396:in `each_value'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:396:in `start_watchers'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:359:in `refresh_watchers'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/plugin/in_tail.rb:234:in `start'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:200:in `block in start'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:189:in `block (2 levels) in lifecycle'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:188:in `each'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:188:in `block in lifecycle'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:175:in `each'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:175:in `lifecycle'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/root_agent.rb:199:in `start'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/engine.rb:248:in `start'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/engine.rb:147:in `run'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/supervisor.rb:700:in `block in run_worker'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/supervisor.rb:951:in `main_process'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/supervisor.rb:691:in `run_worker'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/lib/fluent/command/fluentd.rb:365:in `<top (required)>'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/2.7.0/rubygems/core_ext/kernel_require.rb:83:in `require'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/2.7.0/rubygems/core_ext/kernel_require.rb:83:in `require'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/lib/ruby/gems/2.7.0/gems/fluentd-1.12.2/bin/fluentd:8:in `<top (required)>'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/bin/fluentd:23:in `load'
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:951:main_process: /usr/local/bin/fluentd:23:in `<main>'
2021-04-16 03:54:12 +0000 [error]: #0 fluent/log.rb:371:error: unexpected error error_class=NoMethodError error="undefined method `synchronize' for nil:NilClass"
  2021-04-16 03:54:12 +0000 [error]: #0 fluent/supervisor.rb:950:main_process: suppressed same stacktrace
2021-04-16 03:54:13 +0000 [info]: fluent/log.rb:329:info: Worker 0 finished unexpectedly with status 1

@ashie ashie added the bug label Apr 16, 2021
@Cryptophobia Cryptophobia mentioned this issue Apr 17, 2021
Closed
@ashie
Copy link
Member

ashie commented Apr 28, 2021 •
edited

The current code doesn't seem have guards to prevent multiple gracefulReload so that it will spawn multiple uncooperative reload threads, it might be the cause.

@ashie ashie self-assigned this Apr 28, 2021
@ashie
Copy link
Member

ashie commented May 20, 2021

I saw a similar error at #3323 (comment) and it's fixed by #3380.
Now I think this issue should be addressed by #3380 too.

@ashie ashie mentioned this issue May 20, 2021
Merged
@ashie
Copy link
Member

ashie commented May 25, 2021

#3380 has been merged.
v1.13.0 will ship it (will be released at the end of this month).

@ashie ashie closed this as completed May 25, 2021
@Cryptophobia Cryptophobia mentioned this issue May 25, 2021
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@ashie ashie

Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@ashie @alex-vmw