new pod logstream not getting created with mounted-file option

[vkadi]

I am seeing the issue with CW logstreams not getting created when using the "mounted-file" to ingest the logs from file in the container.
I picked the sample config from examples folder and able to reproduce it , below is the demo config what I have used.

apiVersion: apps/v1
kind: Deployment
metadata:
name: nginx-deployment
namespace: default
spec:
selector:
matchLabels:
app: nginx
replicas: 1
template:
metadata:
labels:
app: nginx
spec:
containers:
- image: ubuntu
name: test-container
command:
- bash
- -c
- while true; do echo date -R [INFO] "Random welcome number $((var++)) to file"; sleep 2; [[ $(($var % 100)) == 0 ]] && :> /var/log/welcome.log ;done > /var/log/welcome.log
volumeMounts:
- mountPath: /var/log
name: logs
- mountPath: /host-root
name: root
volumes:
- name: logs
emptyDir: {}
- name: root
hostPath:
path: /

Sometime when we refresh the fluent then we will see the logstreams but its not consistent either. Anyone using the "mounted-file" option heavily and saw this issue. Any guidance will be a great help around this area.
Note : Using the latest KFO version (1.16.1)

[vkadi]

@Cryptophobia Can you please help with the issue , seems like the new container information is not updated in "fluent.conf" until the fluent is refreshed manually.

[Cryptophobia]

@vkadi , can you share the configMap or CRD fluentdconfig that you are using for the above testing container?

Are you using type @mounted-file? Are you following the README here: https://github.com/vmware/kube-fluentd-operator#i-have-a-legacy-container-that-logs-to-varloghttpdaccesslog

Also it is possible, when your configuration changes the fluentd container needs to be restarted as gracefulReload may not be enough. Let me know if you can provide the detail above and I can test with a similar configmap or CRD.

[vkadi]

@Cryptophobia Yes, I am using the "mounted-file" and this is how my configmap looks for the testing pod -

<source>
   @type mounted-file
   path /var/log/welcome.log
   labels msg= nginx, _container=test-container
</source>
<match **>
   @type cloudwatch_logs
   auto_create_stream true
   log_stream_name_key stream_name
   remove_log_stream_name_key true
   retention_in_days 90
   region "#{ENV['AWS_REGION']}"
   <buffer>
     @type file
     path /var/log/fluentd
     flush_interval 5s
     flush_thread_count 8
     chunk_limit_size 2m
     queued_chunks_limit_size 32
     retry_forever true
   </buffer>
   log_group_name /aws/eks/<cluster_name>/cluster/namespace/default
</match>

[sabdalla80]

@Cryptophobia
I am having a similar problem with mounted-file as @vkadi. I believe the problem isn't in configMap changes, this part works as expected, reloader kicks in and invokes controller::RunOnce() loop and re-generates the proper ConfigMaps in addition to fluent.conf.
However, the problem seems to be when the pod in a deployment is replaced/restarted, the reloader seems to be unaware and thus it does not re-generate or update the proper fluent.conf and configmap files again and hence it never executes the mountedfile::Process() and also it won't create the cloudwatch logstream with the new pod name as a result.

Note that fluentd logs does show the new pod such as:
2021-11-17 16:51:15 +0000 [info]: #0 [in_tail_container_logs] following tail of /var/log/containers/nginx-deployment-f697bcfb-8b2jm_default_test-container-a13490af26e0e63a6eeafa884c66b6e7891835fc204fa2c259f5e3105a946496.log 2021-11-17 16:51:40 +0000 [info]: #0 detected rotation of /var/lib/kubelet/pods/601ac67a-0639-4f28-979b-cf21151257bd/volumes/kubernetes.io~empty-dir/logs/welcome.log; waiting 5 seconds 2021-11-17 16:51:41 +0000 [info]: #0 [in_tail_container_logs] detected rotation of /var/log/containers/nginx-deployment-f697bcfb-clqgw_default_test-container-664c91264cbc2b835b9a2ab1260b9c1c6d398f1ff419907cc5b243273b5efa97.log; waiting 5 seconds

[Cryptophobia]

Thank you @sabdalla80 , that description helps a lot! I think in this case maybe we are not doing it correctly. Since the config file has not change, we only force fluentd reload when config hashes change. We need to force gracefulReload on fluentd even when configmap does not change but the mountedFile pod is restarted/replaced.

This sounds like the issue here. This also explains why KFO sometimes does not work with job type pods.

[Cryptophobia]

I think this is related to the issues in #253

[sabdalla80]

Thank you @sabdalla80 , that description helps a lot! I think in this case maybe we are not doing it correctly. Since the config file has not change, we only force fluentd reload when config hashes change. We need to force gracefulReload on fluentd even when configmap does not change but the mountedFile pod is restarted/replaced.

This sounds like the issue here. This also explains why KFO sometimes does not work with job type pods.

@Cryptophobia Thank you for the response and feedback. It sounds like others having same issue, I know this issue is currently impacting me and I can use a quick fix. Do you know if you have an ETA for the fix? I would be glad to assist as I already went down this path of learning the insides of the code and got hung up on how to detect pod changes (I am not 100% sure, but it sounds like it's done in KubeInformer). Please let me know as I can help with testing the fix as well since I already have an environment with this issue ready for testing.

[Cryptophobia]

@sabdalla80 , yes I think we need to find some place in kubeInformer.go (config-reloader/datasource/kube_informer.go) where we can do this check via the sharedInformers for the pods. If pods are getting restarted in a namespaces, config-reloader needs to be smart enough to issue new reload to fluentd. This is where we can get a list of pods from namespace config struct that we build.

@sabdalla80 Before we start looking at code fix can you verify if this is not a regression for me? There are a couple lines of code were deleted that were thought to be useless. Can you run the v1.15.0 docker image and verify you are seeing the same problems?

The line deleted in question is this commit: https://github.com/vmware/kube-fluentd-operator/pull/227/files

[sabdalla80]

@sabdalla80 , yes I think we need to find some place in kubeInformer.go (config-reloader/datasource/kube_informer.go) where we can do this check via the sharedInformers for the pods. If pods are getting restarted in a namespaces, config-reloader needs to be smart enough to issue new reload to fluentd. This is where we can get a list of pods from namespace config struct that we build.

@sabdalla80 Before we start looking at code fix can you verify if this is not a regression for me? There are a couple lines of code were deleted that were thought to be useless. Can you run the v1.15.0 docker image and verify you are seeing the same problems?

The line deleted in question is this commit: https://github.com/vmware/kube-fluentd-operator/pull/227/files

@Cryptophobia I tried it against 1.15.0 and 1.13.0, it has the same issue.

[Cryptophobia]

I just looked at the code and I have an idea. We can use an hasher to get a unique has for the nsConfig struct each time RunOnce() loop runs. This will avoid us having to reload each time new pods restart or using kubeInformer at all. We just build namespace representation using our current way.

If the podlist slice representation in nsConfig.MiniContainers changes then the hash value of the whole nsConfig struct will change and we can issue reload.

We can use this for our hasher:
https://github.com/mitchellh/hashstructure

EDIT: The true problem stems from the fact that mount-file names change based on the container names, but forcing more reloads will make KFO more resilient and this is the best way to solve the problem I think.

[Cryptophobia]

@sabdalla80, thank you for testing. After I do some local testing, I will build a new test image today.