New Kubernetes container logs are not tailed by fluentd #3423

alex-vmw · 2021-06-15T02:45:02Z

We have noticed an issue where new Kubernetes container logs are not tailed by fluentd.
For example:

At 2021-06-14 22:04:52 UTC we had deployed a Kubernetes pod frontend-f6f48b59d-fq697.
We expected fluentd to tail the log for this new container based on our configuration, but when we look at fluentd logs we only see a few kube_metadata_filter errors for that pod and NO fluentd logs from in_tail plugin about this pod.

Describe the bug
For example:

At 2021-06-14 22:04:52 UTC we had deployed a Kubernetes pod frontend-f6f48b59d-fq697.
We expected fluentd to tail the log for this new container based on our configuration, but when we look at fluentd logs we only see a few kube_metadata_filter errors for that pod and NO fluentd logs from in_tail plugin about this pod (see full log file attached):

2021-06-14 22:04:52 +0000 [debug]: #0 [filter_kube_metadata] parsing container meta information failed for: ara-lumberjack/frontend-f6f48b59d-fq697
2021-06-14 22:04:52 +0000 [debug]: [filter_kube_metadata] parsing container meta information failed for: ara-lumberjack/frontend-f6f48b59d-fq697
2021-06-14 22:04:52 +0000 [debug]: parsing container meta information failed for: ara-lumberjack/frontend-f6f48b59d-fq697
2021-06-14 22:04:52 +0000 [debug]: #0 parsing container meta information failed for: ara-lumberjack/frontend-f6f48b59d-fq697

To Reproduce
Setup fluentd to tail logs of Kubernetes pods and create/delete Kubernetes pods.

Expected behavior
fluentd should successfully tail logs for new Kubernetes pods.

Your Environment
Fluentd or td-agent version: fluentd 1.13.0.
Operating system: Ubuntu 20.04.1 LTS
Kernel version: 5.4.0-62-generic

If you hit the problem with older fluentd version, try latest version first.

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
kube-fluentd-operator-jcss8-fluentd.log.gz

Additional context
With Kubernetes and Docker there are 2 levels of links before we get to a log file. Just mentioning, in case fluentd has some issues reading logs via symlinks.

fluentd looks at /var/log/containers/*.log
/var/log/containers/something.log is a symlink to /var/log/pods/something/something.log.
/var/log/pods/something/something.log is also a symlink to /var/lib/docker/containers/container_id/something.log.

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

alex-vmw · 2021-06-17T15:51:07Z

@cosmo0920 and @ashie, I see you have handled a number of in_tail issues lately. Could you please help look into this one? This issue is completely blocking us. :( Thank you very much in advance.

ashie · 2021-06-17T18:57:00Z

With Kubernetes and Docker there are 2 levels of links before we get to a log file. Just mentioning, in case fluentd has some issues reading logs via symlinks.

I checked with such symlinks, but I get work correctly with them.

We expected fluentd to tail the log for this new container based on our configuration, but when we look at fluentd logs we only see a few kube_metadata_filter errors for that pod and NO fluentd logs from in_tail plugin about this pod (see full log file attached):

2021-06-14 22:04:52 +0000 [debug]: #0 [filter_kube_metadata] parsing container meta information failed for: ara-lumberjack/frontend-f6f48b59d-fq697

Although I'm not sure for now that it's the plugin's issue or fluentd's issue, it seems that they might be filtered out by fluent-plugin-kubernetes_metadata_filter.

ref: fabric8io/fluent-plugin-kubernetes_metadata_filter#294

alex-vmw · 2021-06-17T19:12:45Z

Although I'm not sure for now that it's the plugin's issue or fluentd's issue, it seems that they might be filtered out by fluent-plugin-kubernetes_metadata_filter.

ref: fabric8io/fluent-plugin-kubernetes_metadata_filter#294

@ashie A few questions for you:

Are plugins/filters in the fluentd config executed in order they are specified?
If the answer to question 1 is Yes, then can you please explain why in_tail plugin doesn't pick up the log file while it is listed before kube_metadata_filter in the config?
How can kube_metadata_filter "filter out" the logs before they are even tailed? If the log files are not tailed, which is the case, filter has nothing to work on.
Based on fluentd architecture, would the error from kube_metadata_filter prevent in_tail plugin from tailing the logs?

ashie · 2021-06-18T07:25:01Z

AFAIK filter plugins cannot affect to input plugin's behavior.
So that if a log following tail of /path/to/file like the following

2021-06-11 18:39:08 +0000 [info]: #0 [in_tail_container_logs] following tail of /var/log/containers/selenium-node-chrome-test-6b7c8674df-wfg5x_ara-pssb-e2e-test_selenium-node-chrome-test-4db7577e75211dd16ad1527bed00540a76b1f0344a28eac089047ad71196e44f.log

isn't output for the file you want, it's considered as in_tail's issue.

Because I didn't check your report & log exactly yet,I missed some important point like NO fluentd logs from in_tail plugin about this pod .
Sorry for that.

Gallardot · 2021-06-19T16:03:22Z

I met the same issue on fluentd-1.12.1
My configuration

........
<source>
  @id source_tail
  @type tail
  path /var/log/containers/*.log
  # exclude Fluentd logs
  exclude_path /var/log/containers/*fluentd*.log
  pos_file /opt/bitnami/fluentd/logs/buffers/fluentd-docker.pos
  tag kubernetes.*
  read_from_head true
  follow_inodes true
  <parse>
    @type json
    keep_time_key
  </parse>
</source>
# enrich with kubernetes metadata
<filter kubernetes.**>
  @id filter_k8s_meta
  @type kubernetes_metadata
</filter>
.............

I also checked my fluentd-docker.pos file, which did not contain the contents of the newly created POD log file path.
@alex-vmw Have you checked the .pos file?

So that if a log following tail of /path/to/file like the following
2021-06-11 18:39:08 +0000 [info]: #0 [in_tail_container_logs] following tail of /var/log/containers/selenium-node-chrome-test-6b7c8674df-wfg5x_ara-pssb-e2e-test_selenium-node-chrome-test-4db7577e75211dd16ad1527bed00540a76b1f0344a28eac089047ad71196e44f.log
isn't output for the file you want, it's considered as in_tail's issue.

@ashie Yes. I didn't see the file log content I want .

If you restart fluentd, everything will be fine. But with frequent creation and deletion of PODs, problems will continue to arise.
I install fluentd by

helm repo add bitnami https://charts.bitnami.com/bitnami
helm install my-release bitnami/fluentd

alex-vmw · 2021-06-21T20:20:35Z

@Gallardot I have tested again and I do NOT see any entries in the pos file and do NOT see any in_tail log lines in the fluentd logs.

fluentd logs for my test pod:

$ kara -n cluster-services logs kube-fluentd-operator-hsmff fluentd | grep alex-busybox
2021-06-21 20:06:16 +0000 [debug]: fluent/log.rb:308:debug: parsing container meta information failed for: default/alex-busybox
2021-06-21 20:06:16 +0000 [debug]: #0 parsing container meta information failed for: default/alex-busybox
2021-06-21 20:06:16 +0000 [debug]: [filter_kube_metadata] parsing container meta information failed for: default/alex-busybox
2021-06-21 20:06:16 +0000 [debug]: fluent/log.rb:308:debug: parsing container meta information failed for: default/alex-busybox
2021-06-21 20:06:16 +0000 [debug]: #0 [filter_kube_metadata] parsing container meta information failed for: default/alex-busybox
2021-06-21 20:06:16 +0000 [debug]: #0 [filter_kube_metadata] parsing container meta information failed for: default/alex-busybox
2021-06-21 20:06:16 +0000 [debug]: [filter_kube_metadata] parsing container meta information failed for: default/alex-busybox
2021-06-21 20:06:16 +0000 [debug]: #0 parsing container meta information failed for: default/alex-busybox
2021-06-21 20:06:16 +0000 [debug]: [filter_kube_metadata] parsing container meta information failed for: default/alex-busybox
2021-06-21 20:06:16 +0000 [debug]: [filter_kube_metadata] parsing container meta information failed for: default/alex-busybox
2021-06-21 20:06:16 +0000 [debug]: [filter_kube_metadata] parsing container meta information failed for: default/alex-busybox
2021-06-21 20:06:16 +0000 [debug]: [filter_kube_metadata] parsing container meta information failed for: default/alex-busybox
2021-06-21 20:06:16 +0000 [debug]: fluent/log.rb:308:debug: parsing container meta information failed for: default/alex-busybox
2021-06-21 20:06:16 +0000 [debug]: fluent/log.rb:308:debug: parsing container meta information failed for: default/alex-busybox
2021-06-21 20:06:16 +0000 [debug]: [filter_kube_metadata] parsing container meta information failed for: default/alex-busybox
2021-06-21 20:06:16 +0000 [debug]: parsing container meta information failed for: default/alex-busybox
2021-06-21 20:06:16 +0000 [debug]: fluent/log.rb:308:debug: parsing container meta information failed for: default/alex-busybox
2021-06-21 20:06:16 +0000 [debug]: fluent/log.rb:308:debug: parsing container meta information failed for: default/alex-busybox
2021-06-21 20:06:16 +0000 [debug]: [filter_kube_metadata] parsing container meta information failed for: default/alex-busybox
2021-06-21 20:06:16 +0000 [debug]: fluent/log.rb:308:debug: parsing container meta information failed for: default/alex-busybox

pos file doesn't have the entry for this pod's log as well:

# grep alex /var/log/kube-fluentd-operator-fluentd-containers.log.pos
#

@ashie @cosmo0920 Any help on this would be highly appreciated as this issue is preventing us from getting any new pod logs. Thank you very much in advance!

cosmo0920 · 2021-06-22T08:35:10Z

@ashie @cosmo0920 Any help on this would be highly appreciated as this issue is preventing us from getting any new pod logs. Thank you very much in advance!

I'm not sure the root cause of this issue but new k8s gets changed log directories due to removals of dockershim.
Fluentd in_tail needs to follow symlinked files on /var/log/containers/*.log.

Older k8s, they should be pointed on /var/lib/docker/containers/*.log.
But with CRI-O runtime, the symlinked places should be changed and be pointed on /var/log/pods/*.log.

/var/log/pods/*.log or /var/lib/docker/containers/*.log should be mounted on Fluentd daemonset or pods (or operator?) to tail log contents.

So, I think that this line should adopt to new CRI-O k8s environment:
https://github.com/vmware/kube-fluentd-operator/blob/7a5347adaba86ff33fa70c17f03eb770b324704c/charts/log-router/templates/daemonset.yaml#L73

And also I added a guide for tailing logs on CRI-O k8s environment in official Fluentd daemonset:
fluent/fluentd-kubernetes-daemonset@79c33be

Hope this helps.

ashie · 2021-06-22T09:43:26Z

BTW @Gallardot v1.12.1 isn't recommended for in_tail, it has some serious bugs in it.
Please use 1.12.4 or later (or 1.11.x).

alex-vmw · 2021-06-22T16:41:15Z

@ashie @cosmo0920 Any help on this would be highly appreciated as this issue is preventing us from getting any new pod logs. Thank you very much in advance!

I'm not sure the root cause of this issue but new k8s gets changed log directories due to removals of dockershim.
Fluentd in_tail needs to follow symlinked files on /var/log/containers/*.log.

Older k8s, they should be pointed on /var/lib/docker/containers/*.log.
But with CRI-O runtime, the symlinked places should be changed and be pointed on /var/log/pods/*.log.

/var/log/pods/*.log or /var/lib/docker/containers/*.log should be mounted on Fluentd daemonset or pods (or operator?) to tail log contents.

So, I think that this line should adopt to new CRI-O k8s environment:
https://github.com/vmware/kube-fluentd-operator/blob/7a5347adaba86ff33fa70c17f03eb770b324704c/charts/log-router/templates/daemonset.yaml#L73

And also I added a guide for tailing logs on CRI-O k8s environment in official Fluentd daemonset:
fluent/fluentd-kubernetes-daemonset@79c33be

Hope this helps.

@ashie and @cosmo0920 We are aware of the k8s changes, but do NOT have the issue with the log file locations. On startup or reload, fluentd doesn't have any issues tailing the log files. The issue only happens for newly created k8s pods!

alex-vmw · 2021-06-22T21:40:19Z

@ashie @cosmo0920 For the latest pod example, I just noticed that in_tail actually did pickup the log file, but over 3 hours after the k8s pod was deployed (deployed at ~2021-06-21 20:06:16 and in_tail picked up at ~2021-06-21 23:34:25)!

2021-06-21 20:06:16 +0000 [debug]: fluent/log.rb:308:debug: parsing container meta information failed for: default/alex-busybox
2021-06-21 23:34:25 +0000 [info]: #0 [in_tail_container_logs] following tail of /var/log/containers/alex-busybox_default_alex-busybox-0584af93443bad99c0b64bf291190609f5d22557c7be937f36c9af2dde9ce54b.log

When I check our external log receiver (VMware LogInsight) it only received the logs from fluentd for ~10mins (between 2021-06-21 23:26:22 and 2021-06-21 23:36:14) and then again all logs stopped coming completely!

ashie · 2021-06-23T00:56:59Z

Do you have huge log files?
If so, it's same issue with #2478.
v1.13.0 has log throttling feature which will be effective against this issue.
Please try read_bytes_limit_per_second.
Note that trailing logs in such huge files might be dropped after file rotation if you enable this feature.
#3390 will resolve it but not yet merged.

BTW I think this issue can be considered as same issue with #3239, so I want to close this issue and continue discussion at #3239.

alex-vmw · 2021-06-23T02:30:14Z

Do you have huge log files?

Are you asking about any large log files on the node? Or are you asking if my test k8s pod has a large log file?
On the node itself, the largest log file I see is 95MB, but my k8s pod has only a log of 1.1M.

If so, it's same issue with #2478.
v1.13.0 has log throttling feature which will be effective against this issue.
Please try read_bytes_limit_per_second.
Note that trailing logs in such huge files might be dropped after file rotation if you enable this feature.
#3390 will resolve it but not yet merged.

We don't seem to have any issues with the network saturation, so I am confused on how read_bytes_limit_per_second will help in our situation. Can you please explain a bit more on this? If we decide to try it out, what would be the way to choose the right value for it?

BTW I think this issue can be considered as same issue with #3239, so I want to close this issue and continue discussion at #3239.

Personally, I would rather keep this issue separate as it only deals with a specific re-creatable problem instead of dealing with 2 years old ticket and a ton of unrelated comments in it.

ashie · 2021-06-23T03:40:43Z

Are you asking about any large log files on the node? Or are you asking if my test k8s pod has a large log file?

On the node.
I want to know not only largest size of a file but also total approximate size of all files.

When read_from_head true is specified, in_tail runs busy loop until reaching EOF.
While executing this loop, all other event handlers (e.g. watching new files) are prevented to run.
In other words, tailing multiple files and finding new files aren't parallel.

On the node itself, the largest log file I see is 95MB

95MB isn't so big but it might take several tens of minutes to reach EOF (depends on parser's performance).
If you have ten files of the size at the same level, it might takes over 1 hours.
While this operation, in_tail can't find new files.

We don't seem to have any issues with the network saturation, so I am confused on how read_bytes_limit_per_second will help in our situation. Can you please explain a bit more on this? If we decide to try it out, what would be the way to choose the right value for it?

read_bytes_limit_per_second is the limit size of the busy loop.
When read size is reached this limit while reading a file, in_tail aborts the busy loop and gives other event handlers (reading other files or finding new files or something) a chance to work. After 1 sec is elapsed, in_tail tries to continue reading the file.

what would be the way to choose the right value for it?

A smaller value makes easy to work other event handlers, but reading pace of a file is slow.
A bigger value is fast to read a file but tend to block other event handlers.

I suggest you to start with 8192, and increase it progressively to tune the pace if it's too slow for you.

alex-vmw · 2021-06-23T04:02:39Z

On the node.
I want to know not only largest size of a file but also total approximate size of all files.

See attached file:
sizes_of_log_files_on_node.txt

When read_from_head true is specified, in_tail runs busy loop until reaching EOF.
While executing this loop, all other event handlers (e.g. watching new files) are prevented to run.
In other words, tailing multiple files and finding new files aren't parallel.
95MB isn't so big but it might take several tens of minutes to reach EOF (depends on parser's performance).
If you have ten files of the size at the same level, it might takes over 1 hours.
While this operation, in_tail can't find new files.

Right before you replied, I was doing testing with read_from_head false being set. I waited for over 40 minutes and in_tail still did NOT follow all container log files on the node, so there must be some other blocking loop.

read_bytes_limit_per_second is the limit size of the busy loop.
When read size is reached to this limit while reading a file, in_tail abort the loop and gives other event handlers (reading other files or finding new files or something) a chance to work. After 1 sec elapsed, in_tail tries to continue reading the file.
A smaller value makes easy to work other event handlers, but reading pace of a file is slow.
A bigger value is fast to read a file but tend to block other event handlers.
I suggest you to start with 8192, and increase it progressively to tune the pace if it's too slow for you.

OK, I will test now with read_bytes_limit_per_second 8192 to see what would happen. Thanks.

ashie · 2021-06-23T04:07:05Z

I waited for over 40 minutes and in_tail still did NOT follow all container log files on the node, so there must be some other blocking loop.

I'm also thinking about other possibilities because of your following comment:

When I check our external log receiver (VMware LogInsight) it only received the logs from fluentd for ~10mins (between 2021-06-21 23:26:22 and 2021-06-21 23:36:14) and then again all logs stopped coming completely!

If in_tail is running busy loop, events should be emitted continuously. But your case isn't.

alex-vmw · 2021-06-23T04:55:16Z

@ashie the read_bytes_limit_per_second 8192 looks promising so far.

On the same exact node:

With read_from_head false, but without read_bytes_limit_per_second 8192 the in_tail was able to follow 109 unique logs in about ~53 minutes.
With read_from_head false and read_bytes_limit_per_second 8192 the in_tail was able to follow 268 unique logs in 15 seconds!
With read_from_head true and read_bytes_limit_per_second 8192 the in_tail was able to follow 273 unique logs in 18 seconds!

alex-vmw · 2021-06-23T06:44:03Z

@ashie also just tested with read_from_head true and read_bytes_limit_per_second 32768 and immediately see issues:

the in_tail was able to follow 272 unique logs in about 6 minutes and 35 seconds.
for the new pod log to get tailed it took about 2 minutes and 40 seconds.
for the new pod log I saw the first 2 mins and 40 seconds worth of logs show up on our external logging server, then logging stopped for like 5-10 mins and then again started and got caught up for all of those minutes that it wasn't sending any logs. Very weird behavior, which I have NOT seen with read_bytes_limit_per_second 8192.

I will also test with read_bytes_limit_per_second 16384 just to see what happens. :)

alex-vmw · 2021-06-23T07:08:27Z

With read_from_head true and read_bytes_limit_per_second 16384 the in_tail was able to follow 275 unique logs in 55 seconds! Logs for the new pod were also tailed very quickly upon pod creation. So, looks like read_bytes_limit_per_second 8192 might be a safe bet right now, unless it starts causing some other issues, which I am currently not seeing.

ashie · 2021-06-23T07:51:08Z

Thanks for your test.
It's very helpful also for us because we don't yet have enough data for it.

ashie · 2021-06-23T08:45:00Z

unless it starts causing some other issues, which I am currently not seeing.

A known issue is that you'll lost logs when rotation is occurred before reaching EOF as I mentioned above.

alex-vmw · 2021-06-25T02:23:14Z

So, for the past 2 days the read_bytes_limit_per_second 8192 seems to be working very well for us. Will be waiting for the release of #3390 soon. I am still not fully clear about why in_tail on our nodes is so slow without this option (even with read_from_head false set). As I said before, I am guessing there are other loops that this option is helping to break in our environment where nodes have a lot of kubernetes pods with a lot of log files.

ashie · 2021-06-25T02:36:51Z

I am still not fully clear about why in_tail on our nodes is so slow without this option (even with read_from_head false set).

One of possibilities is JSON library.
Do you install oj gem?
For JSON parsing, oj is faster than other JSON libraries, but it's not installed by default if you install fluentd by gem.

https://docs.fluentd.org/parser/json#json_parser

alex-vmw · 2021-06-25T02:41:08Z

I am still not fully clear about why in_tail on our nodes is so slow without this option (even with read_from_head false set).

One of possibilities is JSON library.
Do you install oj gem?
For JSON parsing, oj is faster than other JSON libraries, but it's not installed by default if you install fluentd by gem.

https://docs.fluentd.org/parser/json#json_parser

We use kube-fluentd-operator and it does install oj into its image:
https://github.com/vmware/kube-fluentd-operator/blob/0ce50a0a7dd6d35e22b00b207ac69dc37d8a8b67/base-image/basegems/Gemfile#L16

Gallardot · 2021-06-25T03:36:09Z

A known issue is that you'll lost logs when rotation is occurred before reaching EOF as I mentioned above.

@ashie If follow_inodes true set，will we still lost logs when rotation is occurred before reaching EOF ？

shenmuxiaosen · 2021-06-28T22:18:11Z

A known issue is that you'll lost logs when rotation is occurred before reaching EOF as I mentioned above.

@ashie If follow_inodes true set，will we still lost logs when rotation is occurred before reaching EOF ？

@ashie Any updates on this question?

ashie · 2021-06-29T00:15:48Z

A known issue is that you'll lost logs when rotation is occurred before reaching EOF as I mentioned above.

@ashie If follow_inodes true set，will we still lost logs when rotation is occurred before reaching EOF ？

Yes, it will lost even if follow_inodes true.

ashie · 2021-07-12T08:50:32Z

Will be waiting for the release of #3390 soon.

Landed onto v1.13.2, so I close this issue.
If you still have problem around this, please reopen this or file a new issue.

ashie mentioned this issue Jun 28, 2021

Kubernetes container logs - in_tail lose some of rotated logs when rotation is quite fast #3434

Closed

ashie mentioned this issue Jul 12, 2021

Fluentd not picking new log files #3239

Closed

ashie closed this as completed Jul 12, 2021

ashie mentioned this issue Sep 6, 2021

Fluentd misses log file when >1 app log rotation happens back to back fluent/fluentd-kubernetes-daemonset#465

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

New Kubernetes container logs are not tailed by fluentd #3423

New Kubernetes container logs are not tailed by fluentd #3423

alex-vmw commented Jun 15, 2021 •

edited

Loading

alex-vmw commented Jun 17, 2021

ashie commented Jun 17, 2021

alex-vmw commented Jun 17, 2021 •

edited

Loading

ashie commented Jun 18, 2021 •

edited

Loading

Gallardot commented Jun 19, 2021 •

edited

Loading

alex-vmw commented Jun 21, 2021

cosmo0920 commented Jun 22, 2021 •

edited

Loading

ashie commented Jun 22, 2021

alex-vmw commented Jun 22, 2021

alex-vmw commented Jun 22, 2021

ashie commented Jun 23, 2021 •

edited

Loading

alex-vmw commented Jun 23, 2021

ashie commented Jun 23, 2021 •

edited

Loading

alex-vmw commented Jun 23, 2021

ashie commented Jun 23, 2021 •

edited

Loading

alex-vmw commented Jun 23, 2021 •

edited

Loading

alex-vmw commented Jun 23, 2021

alex-vmw commented Jun 23, 2021

ashie commented Jun 23, 2021

ashie commented Jun 23, 2021

alex-vmw commented Jun 25, 2021

ashie commented Jun 25, 2021

alex-vmw commented Jun 25, 2021

Gallardot commented Jun 25, 2021 •

edited

Loading

shenmuxiaosen commented Jun 28, 2021

ashie commented Jun 29, 2021

ashie commented Jul 12, 2021

New Kubernetes container logs are not tailed by fluentd #3423

New Kubernetes container logs are not tailed by fluentd #3423

Comments

alex-vmw commented Jun 15, 2021 • edited Loading

alex-vmw commented Jun 17, 2021

ashie commented Jun 17, 2021

alex-vmw commented Jun 17, 2021 • edited Loading

ashie commented Jun 18, 2021 • edited Loading

Gallardot commented Jun 19, 2021 • edited Loading

alex-vmw commented Jun 21, 2021

cosmo0920 commented Jun 22, 2021 • edited Loading

ashie commented Jun 22, 2021

alex-vmw commented Jun 22, 2021

alex-vmw commented Jun 22, 2021

ashie commented Jun 23, 2021 • edited Loading

alex-vmw commented Jun 23, 2021

ashie commented Jun 23, 2021 • edited Loading

alex-vmw commented Jun 23, 2021

ashie commented Jun 23, 2021 • edited Loading

alex-vmw commented Jun 23, 2021 • edited Loading

alex-vmw commented Jun 23, 2021

alex-vmw commented Jun 23, 2021

ashie commented Jun 23, 2021

ashie commented Jun 23, 2021

alex-vmw commented Jun 25, 2021

ashie commented Jun 25, 2021

alex-vmw commented Jun 25, 2021

Gallardot commented Jun 25, 2021 • edited Loading

shenmuxiaosen commented Jun 28, 2021

ashie commented Jun 29, 2021

ashie commented Jul 12, 2021

alex-vmw commented Jun 15, 2021 •

edited

Loading

alex-vmw commented Jun 17, 2021 •

edited

Loading

ashie commented Jun 18, 2021 •

edited

Loading

Gallardot commented Jun 19, 2021 •

edited

Loading

cosmo0920 commented Jun 22, 2021 •

edited

Loading

ashie commented Jun 23, 2021 •

edited

Loading

ashie commented Jun 23, 2021 •

edited

Loading

ashie commented Jun 23, 2021 •

edited

Loading

alex-vmw commented Jun 23, 2021 •

edited

Loading

Gallardot commented Jun 25, 2021 •

edited

Loading