Splunk-connect-for-kubernetes: Failed parsing container metadata

Created on 5 May 2020  路  23Comments  路  Source: splunk/splunk-connect-for-kubernetes

What happened:
After upgrade on 1.4.1 we've faced with some problems.
Parsing container metadata information is failing , I show much notices in Fluentd pod logs, like:
What you expected to happen:

Correct parsing containers metadata

How to reproduce it (as minimally and precisely as possible):
Upgrade to 1.4.1

Environment:

  • Kubernetes version (use kubectl version): 1.11
  • OS (e.g: cat /etc/os-release): RHEL7
  • OpenShift 3.11.98
bug question support
Source
picture iyurev

All 23 comments

Environment:

  • Kubernetes version: 1.16.6
  • OS: Ubuntu 16.04

We are also seeing the same issue, since upgrading the logging pod to docker.io/splunk/fluentd-hec:1.2.2

The pod logs when failing:

2020-05-05 09:27:53 +0000 [info]: parsing config file is succeeded path="/fluentd/etc/fluent.conf"
2020-05-05 09:27:53 +0000 [info]: gem 'fluentd' version '1.9.1'
2020-05-05 09:27:53 +0000 [info]: gem 'fluent-plugin-concat' version '2.4.0'
2020-05-05 09:27:53 +0000 [info]: gem 'fluent-plugin-jq' version '0.5.1'
2020-05-05 09:27:53 +0000 [info]: gem 'fluent-plugin-kubernetes_metadata_filter' version '2.4.5'
2020-05-05 09:27:53 +0000 [info]: gem 'fluent-plugin-prometheus' version '1.7.0'
2020-05-05 09:27:53 +0000 [info]: gem 'fluent-plugin-splunk-hec' version '1.2.2'
2020-05-05 09:27:53 +0000 [info]: gem 'fluent-plugin-systemd' version '1.0.2'
#<Thread:0x000055b25eb8f018@/usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/filter_kubernetes_metadata.rb:277 run> terminated with exception (report_on_exception is true):
/usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/kubernetes_metadata_watch_namespaces.rb:43:in `rescue in set_up_namespace_thread': undefined method `<' for nil:NilClass (NoMethodError)
    from /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/kubernetes_metadata_watch_namespaces.rb:38:in `set_up_namespace_thread'
    from /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/filter_kubernetes_metadata.rb:277:in `block in configure'
bundler: failed to load command: fluentd (/usr/bin/fluentd)
NoMethodError: undefined method `<' for nil:NilClass
  /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/kubernetes_metadata_watch_namespaces.rb:43:in `rescue in set_up_namespace_thread'
  /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/kubernetes_metadata_watch_namespaces.rb:38:in `set_up_namespace_thread'
  /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/filter_kubernetes_metadata.rb:277:in `block in configure'

It has been my experience that the pod will, after a number of restarts, complete startup and run.

When successfully running the log messages begin:
2020-05-05 09:28:07 +0000 [info]: parsing config file is succeeded path="/fluentd/etc/fluent.conf" 2020-05-05 09:28:07 +0000 [info]: gem 'fluentd' version '1.9.1' 2020-05-05 09:28:07 +0000 [info]: gem 'fluent-plugin-concat' version '2.4.0' 2020-05-05 09:28:07 +0000 [info]: gem 'fluent-plugin-jq' version '0.5.1' 2020-05-05 09:28:07 +0000 [info]: gem 'fluent-plugin-kubernetes_metadata_filter' version '2.4.5' 2020-05-05 09:28:07 +0000 [info]: gem 'fluent-plugin-prometheus' version '1.7.0' 2020-05-05 09:28:07 +0000 [info]: gem 'fluent-plugin-splunk-hec' version '1.2.2' 2020-05-05 09:28:07 +0000 [info]: gem 'fluent-plugin-systemd' version '1.0.2' 2020-05-05 09:28:07 +0000 [info]: using configuration file: <ROOT> <system> log_level info root_dir "/tmp/fluentd" </system> <source> @id containers.log @type tail @label @SPLUNK . . .

mgherman picture mgherman on 5 May 2020
  • I have noticed periodic restarts pods with fluentd agent , but I couldn鈥檛 catch error messages from fluentd log.
iyurev picture iyurev on 5 May 2020

It looks like it may be related to https://github.com/fabric8io/fluent-plugin-kubernetes_metadata_filter/issues/222

mgherman picture mgherman on 5 May 2020

I don鈥檛 complete understand what is watch_retry_count parameter?! It鈥檒l be added in new metadata_filter plugin release?

iyurev picture iyurev on 5 May 2020

hmm...will keep on the lookout in my lab, anything interesting about your namespaces or the requests being made to the k8s api from the logging pods?? (audit should show)

matthewmodestino picture matthewmodestino on 7 May 2020

i read the issue..looks like certain conditions would trigger this? when it happens do you lose data, or does the pod just keep crashing till theres an event in the namespace?

matthewmodestino picture matthewmodestino on 7 May 2020

There鈥檚 no warning events in namespace while logging pod is crashing. I look something like: kill pod -> start pod.
I don鈥檛 notice data loss, and couldn鈥檛 catch condition that is cause crashing fluentd container.

iyurev picture iyurev on 7 May 2020

I do see the same issue in Ibm Kubernetes Cluster running Splunk-connect 1.4.0
Kubernetes version: 1.15.10

where the splunk logging pod restarts multiple times with the error:

``` 2020-05-28 18:09:56 +0000 [info]: parsing config file is succeeded path="/fluentd/etc/fluent.conf"
2020-05-28 18:09:56 +0000 [info]: gem 'fluentd' version '1.9.1'
2020-05-28 18:09:56 +0000 [info]: gem 'fluent-plugin-concat' version '2.4.0'
2020-05-28 18:09:56 +0000 [info]: gem 'fluent-plugin-jq' version '0.5.1'
2020-05-28 18:09:56 +0000 [info]: gem 'fluent-plugin-kubernetes_metadata_filter' version '2.4.5'
2020-05-28 18:09:56 +0000 [info]: gem 'fluent-plugin-prometheus' version '1.7.0'
2020-05-28 18:09:56 +0000 [info]: gem 'fluent-plugin-splunk-hec' version '1.2.2'
2020-05-28 18:09:56 +0000 [info]: gem 'fluent-plugin-systemd' version '1.0.2'

terminated with exception (report_on_exception is true):/usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/kubernetes_metadata_watch_namespaces.rb:43:in rescue in set_up_namespace_thread': undefined method<' for nil:NilClass (NoMethodError)

from /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/kubernetes_metadata_watch_namespaces.rb:38:in `set_up_namespace_thread'  from /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/filter_kubernetes_metadata.rb:277:in `block in configure'2020-05-28 18:09:57 +0000 [error]: config error file="/fluentd/etc/fluent.conf" error_class=Fluent::ConfigError error="Could not parse jq filter: .record.source = \"/run/log/journal/\" + .record.source | .record.sourcetype = (.tag | ltrimstr(\"journald.\")) | .record.cluster_name = \"iksprodclusterussouth\" | .record.index = \"devops_kubernetes_prod\" |.record, error: undefined method `<' for nil:NilClass"```
kish3007 picture kish3007 on 28 May 2020
👎1

Hi,

Have upgraded from 1.4.0 to 1.4.1 a couples hours back and see pods getting restarted.

Error:

terminated with exception (report_on_exception is true):

/usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/kubernetes_metadata_watch_namespaces.rb:43:in rescue in set_up_namespace_thread': undefined method<' for nil:NilClass (NoMethodError)
from /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/kubernetes_metadata_watch_namespaces.rb:38:in set_up_namespace_thread' from /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/filter_kubernetes_metadata.rb:277:inblock in configure'
2020-06-04 12:32:43 +0000 [error]: #0 unexpected error error_class=NoMethodError error="undefined method <' for nil:NilClass" 2020-06-04 12:32:43 +0000 [error]: #0 /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/kubernetes_metadata_watch_namespaces.rb:43:inrescue in set_up_namespace_thread'
2020-06-04 12:32:43 +0000 [error]: #0 /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/kubernetes_metadata_watch_namespaces.rb:38:in set_up_namespace_thread' 2020-06-04 12:32:43 +0000 [error]: #0 /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/filter_kubernetes_metadata.rb:277:inblock in configure'
2020-06-04 12:32:43 +0000 [error]: #0 unexpected error error_class=NoMethodError error="undefined method `<' for nil:NilClass"
2020-06-04 12:32:43 +0000 [error]: #0 suppressed same stacktrace

2020-06-04 12:32:43 +0000 [info]: Worker 0 finished unexpectedly with status 1

restarts happening on oly few pods and errors also on few pods as of now

and error also on few pods but even the pods which havent restarted see this error

Are pods getting restarted because of this error?

shanmukha511 picture shanmukha511 on 4 Jun 2020

@matthewmodestino any updates on this request ?

kish3007 picture kish3007 on 6 Oct 2020

I turned off watch parameter in k8s metadata filter on Oracle cloud to stop restarts caused by watch connection being terminated..not sure if thats your issue as this thread seems to have a few different error messages...

Whats the latest error you are seeing? and are you on the latest version of the logging pod?

https://github.com/fabric8io/fluent-plugin-kubernetes_metadata_filter#configuration

we were seeing issues with the watch timing out so we set watch false and lowered the cache invalidate to 10 mins as a workaround to issues with watch being interrupted.

Again, not sure if this is similar to your scenario or not

matthewmodestino picture matthewmodestino on 6 Oct 2020

My scenario was splunk-connect-splunk-kubernetes-logging pods keep crashing

/usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/kubernetes_metadata_watch_namespaces.rb:43:inrescue in set_up_namespace_thread': undefined method <' for nil:NilClass 鈹傗攤 from /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/kubernetes_metadata_watch_namespaces.rb:38:inset_up_namespace_thread' 鈹傗攤 from /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/filter_kubernetes_metadata.rb:277:in block in configure' 鈹傗攤 Unexpected error undefined method<' for nil:NilClass 鈹傗攤 /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/kubernetes_metadata_watch_namespaces.rb:43:in rescue in set_up_namespace_thread' 鈹傗攤 /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/kubernetes_metadata_watch_namespaces.rb:38:inset_up_namespace_thread' 鈹傗攤 /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/filter_kubernetes_metadata.rb:277:in block in configure' 鈹傗攤 stream closed

I am using Splunk connect -1.4.0 helm chart, IKS- 1.17 Kubernetes version.
Any settings/config updates in the chart values.yaml help?

kish3007 picture kish3007 on 6 Oct 2020

yeah i think yours was a known condition. please get off 1.4.0 asap. There was cluster utilization bugs there. Please try latest chart

matthewmodestino picture matthewmodestino on 6 Oct 2020

Sounds good, Thanks for the suggestion. I will update the chart and see whether it fixes this issue.

kish3007 picture kish3007 on 6 Oct 2020

no prob! let us know!

matthewmodestino picture matthewmodestino on 6 Oct 2020

@matthewmodestino tried the 1.4.3 SKC- helm chart , seemed like it reduced the number of retries, its more like couple of hours once and the pod restarts now with the error below :

2020-10-07 00:50:16 +0000 [info]: #0 stats - namespace_cache_size: 49, pod_cache_size: 7, namespace_cache_api_updates: 49, pod_cache_api_updates: 49, id_cache_miss: 49, pod_cache_watch_updates: 164, namespace_cache_host_updates: 784, namespace_watch_failures: 10, namespace_watch_gone_errors: 5, namespace_watch_gone_notices: 5 聽 | 2020-10-07 00:50:51 +0000 [error]: Exception encountered parsing namespace watch event. The connection might have been closed. Retried 10 times yet still failing. Restarting.error reading from socket: Could not parse data 聽 | #<Thread:0x000056299bef72a0@/usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.5.2/lib/fluent/plugin/filter_kubernetes_metadata.rb:279 run> terminated with exception (report_on_exception is true): 聽 | /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.5.2/lib/fluent/plugin/kubernetes_metadata_watch_namespaces.rb:70:inrescue in set_up_namespace_thread': Exception encountered parsing namespace watch event. The connection might have been closed. Retried 10 times yet still failing. Restarting. (Fluent::UnrecoverableError)
聽 | from /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.5.2/lib/fluent/plugin/kubernetes_metadata_watch_namespaces.rb:39:in set_up_namespace_thread' 聽 | from /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.5.2/lib/fluent/plugin/filter_kubernetes_metadata.rb:279:inblock in configure'
聽 | Unexpected error Exception encountered parsing namespace watch event. The connection might have been closed. Retried 10 times yet still failing. Restarting.
聽 | /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.5.2/lib/fluent/plugin/kubernetes_metadata_watch_namespaces.rb:70:in rescue in set_up_namespace_thread' 聽 | /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.5.2/lib/fluent/plugin/kubernetes_metadata_watch_namespaces.rb:39:inset_up_namespace_thread'
聽 | /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.5.2/lib/fluent/plugin/filter_kubernetes_metadata.rb:279:in block in configure'

kish3007 picture kish3007 on 7 Oct 2020

ok now u have the same watch connection being torn down, causing pod restart..

You can work around this by customizing the configmap and updating the kubernetes metadata filter here:

https://github.com/splunk/splunk-connect-for-kubernetes/blob/0672ce4a2992c4bc15a11429b7dc1e56d276ad56/manifests/splunk-kubernetes-logging/configMap.yaml#L257

with the following options:

https://github.com/fabric8io/fluent-plugin-kubernetes_metadata_filter#configuration

watch false
cache_ttl 600

This is a temporary workaround which turns off the watch we set up and instead will simply update the cache every 10 mins.

You should probably open a new issue for tracking, as it was likely unrelated to this original thread...

matthewmodestino picture matthewmodestino on 7 Oct 2020

@matthewmodestino i see, is it the right config map update?

<label @SPLUNK>
  # Enrich log with k8s metadata
  <filter tail.containers.**>
    @type kubernetes_metadata
    annotation_match [ "^splunk\.com" ]
    watch false                                                    ---> new line added
    cache_ttl 600                                                 ---> new line added
    de_dot false
  </filter>
kish3007 picture kish3007 on 7 Oct 2020
👍1

Seems like there is no restart after this workaround, Hope that wont have any effect in the log- events to splunk . Thanks @matthewmodestino

kish3007 picture kish3007 on 8 Oct 2020

@rockb1017 for fyi ^

Shouldnt impact anything, may just take longer for annotation changes etc to show up....

matthewmodestino picture matthewmodestino on 9 Oct 2020
👍1

Pods keep restarting even after adding
watch false and cache_ttl 600 to the logging config map

rsrivastava-cs picture rsrivastava-cs on 30 Nov 2020

I'm seeing this error as well. I think I'm still on 1.4.1 of the chart though.

2020-12-06 17:37:12 +0000 [info]: parsing config file is succeeded path="/fluentd/etc/fluent.conf"
2020-12-06 17:37:12 +0000 [info]: gem 'fluentd' version '1.9.1'
2020-12-06 17:37:12 +0000 [info]: gem 'fluent-plugin-concat' version '2.4.0'
2020-12-06 17:37:12 +0000 [info]: gem 'fluent-plugin-jq' version '0.5.1'
2020-12-06 17:37:12 +0000 [info]: gem 'fluent-plugin-kubernetes_metadata_filter' version '2.4.5'
2020-12-06 17:37:12 +0000 [info]: gem 'fluent-plugin-prometheus' version '1.7.0'
2020-12-06 17:37:12 +0000 [info]: gem 'fluent-plugin-splunk-hec' version '1.2.2'
2020-12-06 17:37:12 +0000 [info]: gem 'fluent-plugin-systemd' version '1.0.2'
#<Thread:0x000055f8ff4c15a0@/usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/filter_kubernetes_metadata.rb:277 run> terminated with exception (report_on_exception is true):
/usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/kubernetes_metadata_watch_namespaces.rb:43:in `rescue in set_up_namespace_thread': undefined method `<' for nil:NilClass (NoMethodError)
    from /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/kubernetes_metadata_watch_namespaces.rb:38:in `set_up_namespace_thread'
    from /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/filter_kubernetes_metadata.rb:277:in `block in configure'
2020-12-06 17:37:12 +0000 [error]: config error file="/fluentd/etc/fluent.conf" error_class=Fluent::ConfigError error="Could not parse jq filter: .record.sourcetype = (.tag | ltrimstr(\"tail.file.\")) | .record.cluster_name = \"my-cluster\" | .record.index = \"nws-prd\" | .record, error: undefined method `<' for nil:NilClass"
ekristen picture ekristen on 6 Dec 2020

Hello , I am running 1.4.0 and I saw same error ...
2021-01-18 15:59:07 +0000 [info]: parsing config file is succeeded path="/fluentd/etc/fluent.conf"
2021-01-18 15:59:07 +0000 [info]: gem 'fluentd' version '1.9.1'
2021-01-18 15:59:07 +0000 [info]: gem 'fluent-plugin-concat' version '2.4.0'
2021-01-18 15:59:07 +0000 [info]: gem 'fluent-plugin-jq' version '0.5.1'
2021-01-18 15:59:07 +0000 [info]: gem 'fluent-plugin-kubernetes_metadata_filter' version '2.4.5'
2021-01-18 15:59:07 +0000 [info]: gem 'fluent-plugin-prometheus' version '1.7.0'
2021-01-18 15:59:07 +0000 [info]: gem 'fluent-plugin-splunk-hec' version '1.2.2'
2021-01-18 15:59:07 +0000 [info]: gem 'fluent-plugin-systemd' version '1.0.2'

I see same error

terminated with exception (report_on_exception is true):

/usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/kubernetes_metadata_watch_namespaces.rb:43:in rescue in set_up_namespace_thread': undefined method<' for nil:NilClass (NoMethodError)
from /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/kubernetes_metadata_watch_namespaces.rb:38:in set_up_namespace_thread' from /usr/share/gems/gems/fluent-plugin-kubernetes_metadata_filter-2.4.5/lib/fluent/plugin/filter_kubernetes_metadata.rb:277:inblock in configure'
2021-01-18 16:06:50 +0000 [error]: #0 config error file="/fluentd/etc/fluent.conf" error_class=Fluent::ConfigError error="Could not parse jq filter: .record.source = \"/run/log/journal/\" + .record.source | .record.sourcetype = (.tag | ltrimstr(\"journald.\")) | .record.cluster_name = \"cluster_name\" | .record.index = \"kubernetes-nonprod\" |.record, error: undefined method `<' for nil:NilClass"

I added the workaround ... as described above

watch false
cache_ttl 600

.. and the error disappeared, but I still see another error ..

config error file="/fluentd/etc/fluent.conf" error_class=Fluent::ConfigError error="Plugin 'tail' does not support multi workers configuration (Fluent::Plugin::TailInput)"

Any idea how to fix that.
Thank you.

bdaoudtdc picture bdaoudtdc on 18 Jan 2021
Was this page helpful?
0 / 5 - 0 ratings

Related issues

aakashbhalla1 picture aakashbhalla1  路  6Comments
ajsaclayan picture ajsaclayan  路  5Comments
matthewmodestino picture matthewmodestino  路  4Comments
johnr84 picture johnr84  路  9Comments
stiller-leser picture stiller-leser  路  8Comments