Jack Henschel's Blog

Collecting Kubernetes Events with Fluent Bit

Posted on
#logs #kubernetes #fluent-bit

Kubernetes Events are ephemeral objects that indicate why and when a particular state changed in the cluster. They describe events such as when a pod was stopped (or failed), why a node become unhealthy, when liveness and readiness probes failed and many more (see also: A complete guide to Kubernetes Events).

1
2
3
4
5

$ kubectl get events --sort-by=metadata.creationTimestamp
AGE   TYPE     REASON       OBJECT                                MESSAGE
59s   Normal   Created      pod/sls-availability-28322500-9c24g   Created container sls-availability
59s   Normal   Pulled       pod/sls-availability-28322500-9c24g   Container image "example.com/tools/availability:RELEASE.2022.08.03T13-39-24Z" already present on machine
56s   Normal   Completed    job/sls-availability-28322500         Job completed

These objects are stored in the Kubernetes control plane, more precisely in the etcd database. To avoid polluting the database with these objects, they are automatically pruned by the Kubernetes API server after a fixed period of time (default: 1 hour) that can be configured with the --event-ttl API server argument.

When operating Kubernetes clusters (especially when doing it for clients/users) we sometimes want to go back further (yesterday, last week, previous month …) for troubleshooting purposes. We could turn up the --event-ttl like crazy, but this would a) significantly increase the database size and b) likely introduce performance problems.

Instead, it is a much better approach to collect these logs from the Kubernetes API server when they are generated and ship them to an external log storage system (such as OpenSearch, Loki or Datadog). This approach enables cheap long-term storage as well as easy correlation between different log types (e.g. seeing Event and Pod logs in the same view).

This post will go over deploying such a component with the Fluent Bit Helm chart, analyzing its performance and making configuration adjustments. At the bottom of this post is a list of alternative tools that can be used in a similar fashion.

#  Fluent Bit

Fluent Bit is an open-source logging agent that can collect logs (and other types of data) from many different inputs, filter and modify them, and finally send the result to a variety of outputs - refer to the documentation for an overview of the data pipeline. It is written in C and extremely resource efficient (in terms of CPU and memory usage).

The basic Fluent Bit configuration to collect events from Kubernetes and print them on the console (stdout) looks as follows:

1
2
3
4
5
6
7

[INPUT]
name            kubernetes_events
tag             k8s_events

[OUTPUT]
name            stdout
match           k8s_events

Using the kubernetes_events input plugin locally is a bit tedious, because it does not support reading the Kubernetes configuration and credentials from a KUBECONFIG file. Instead the Kubernetes CA, token, API server URL etc. need to be specified separately.

By using the official Helm chart we can directly deploy Fluent Bit into our cluster and set the appropriate configuration variables - thereby sidestepping the issue described above.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17

kind: Deployment
nameOverride: fluent-bit-events-collector
testFramework:
  enabled: false
rbac:
  create: true
  eventsAccess: true
config:
    inputs: |
      [INPUT]
      name kubernetes_events
      tag k8s_events

    outputs: |
      [OUTPUT]
      name stdout
      match k8s_events

Reference: https://github.com/fluent/helm-charts/blob/main/charts/fluent-bit/values.yaml

With the above Helm values (fluent-bit.values.yaml), we can install the chart as follows in the newly created namespace “logging”:

1
2
3
4
5
6

helm repo add fluent https://fluent.github.io/helm-charts
helm install fluent-bit-events-collector \
    --namespace logging --create-namespace \
    --values fluent-bit.values.yaml \
    --version 0.39.1 \
    fluent/fluent-bit

The Helm chart takes care of creating the necessary Kubernetes Roles and RoleBindings (note the values rbac.create: true and rbac.eventsAccess: true), the credentials for the Kubernetes Service Account as well as injecting the Fluent Bit configuration file.

We should now see a running pod in the “logging” namespace - and hopefully some events in the logs!

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29

$ kubectl -n logging get pods
NAME                                           READY   STATUS    RESTARTS   AGE
fluent-bit-events-collector-664f69754d-wfbkp   1/1     Running   0          112s

$ kubectl -n logging logs fluent-bit-events-collector-664f69754d-wfbkp
Fluent Bit v2.1.10
* Copyright (C) 2015-2022 The Fluent Bit Authors
* Fluent Bit is a CNCF sub-project under the umbrella of Fluentd
* https://fluentbit.io

[2023/11/07 10:58:29] [ info] [fluent bit] version=2.1.10, commit=b19e9ce674, pid=1
[2023/11/07 10:58:29] [ info] [storage] ver=1.5.1, type=memory, sync=normal, checksum=off, max_chunks_up=128
[2023/11/07 10:58:29] [ info] [cmetrics] version=0.6.3
[2023/11/07 10:58:29] [ info] [ctraces ] version=0.3.1
[2023/11/07 10:58:29] [ info] [input:kubernetes_events:kubernetes_events.0] initializing
[2023/11/07 10:58:29] [ info] [input:kubernetes_events:kubernetes_events.0] storage_strategy='memory' (memory only)
[2023/11/07 10:58:29] [ info] [input:kubernetes_events:kubernetes_events.0] API server: https://kubernetes.default.svc:443
[2023/11/07 10:58:29] [ info] [input:kubernetes_events:kubernetes_events.0] thread instance initialized
[2023/11/07 10:58:29] [ info] [filter:kubernetes:kubernetes.0] https=1 host=kubernetes.default.svc port=443
[2023/11/07 10:58:29] [ info] [filter:kubernetes:kubernetes.0]  token updated
[2023/11/07 10:58:29] [ info] [filter:kubernetes:kubernetes.0] local POD info OK
[2023/11/07 10:58:29] [ info] [filter:kubernetes:kubernetes.0] testing connectivity with API server...
[2023/11/07 10:58:29] [ info] [filter:kubernetes:kubernetes.0] connectivity OK
[2023/11/07 10:58:29] [ info] [output:stdout:stdout.0] worker #0 started
[2023/11/07 10:58:29] [ info] [http_server] listen iface=0.0.0.0 tcp_port=2020
[2023/11/07 10:58:29] [ info] [sp] stream processor started
[0] k8s_events: [[1699354415.000000000, {}], {"metadata"=>{"name"=>"clu-jack-wspgeka3zvll-master-0.179551d6593eef9f", "namespace"=>"default", "uid"=>"5a78ff62-d6e1-43bc-a727-daa05da70688", "resourceVersion"=>"245", "creationTimestamp"=>"2023-11-07T10:53:35Z", "managedFields"=>[{"manager"=>"kube-controller-manager", "operation"=>"Update", "apiVersion"=>"v1", "time"=>"2023-11-07T10:53:35Z", "fieldsType"=>"FieldsV1", "fieldsV1"=>{"f:count"=>{}, "f:firstTimestamp"=>{}, "f:involvedObject"=>{}, "f:lastTimestamp"=>{}, "f:message"=>{}, "f:reason"=>{}, "f:source"=>{"f:component"=>{}}, "f:type"=>{}}}]}, "involvedObject"=>{"kind"=>"Node", "name"=>"clu-jack-wspgeka3zvll-master-0", "uid"=>"7a4677ba-e0b4-4267-baf0-4c3e2f8aca40", "apiVersion"=>"v1"}, "reason"=>"RegisteredNode", "message"=>"Node clu-jack-wspgeka3zvll-master-0 event: Registered Node clu-jack-wspgeka3zvll-master-0 in Controller", "source"=>{"component"=>"node-controller"}, "firstTimestamp"=>"2023-11-07T10:53:35Z", "lastTimestamp"=>"2023-11-07T10:53:35Z", "count"=>1, "type"=>"Normal", "eventTime"=>nil, "reportingComponent"=>"", "reportingInstance"=>""}]
[1] k8s_events: [[1699354463.000000000, {}], {"metadata"=>{"name"=>"clu-jack-wspgeka3zvll-master-0.179551e16cdb3ed4", "namespace"=>"default", "uid"=>"49ff11b9-7781-48a2-9886-43bf5af9c2f5", "resourceVersion"=>"986", "creationTimestamp"=>"2023-11-07T10:54:23Z", "managedFields"=>[{"manager"=>"kubelet", "operation"=>"Update", "apiVersion"=>"v1", "time"=>"2023-11-07T10:54:23Z", "fieldsType"=>"FieldsV1", "fieldsV1"=>{"f:count"=>{}, "f:firstTimestamp"=>{}, "f:involvedObject"=>{}, "f:lastTimestamp"=>{}, "f:message"=>{}, "f:reason"=>{}, "f:source"=>{"f:component"=>{}, "f:host"=>{}}, "f:type"=>{}}}]}, "involvedObject"=>{"kind"=>"Node", "name"=>"clu-jack-wspgeka3zvll-master-0", "uid"=>"clu-jack-wspgeka3zvll-master-0"}, "reason"=>"NodeReady", "message"=>"Node clu-jack-wspgeka3zvll-master-0 status is now: NodeReady", "source"=>{"component"=>"kubelet", "host"=>"clu-jack-wspgeka3zvll-master-0"}, "firstTimestamp"=>"2023-11-07T10:54:23Z", "lastTimestamp"=>"2023-11-07T10:54:23Z", "count"=>1, "type"=>"Normal", "eventTime"=>nil, "reportingComponent"=>"", "reportingInstance"=>""}]
[2] k8s_events: [[1699354481.000000000, {}], {"metadata"=>{"name"=>"clu-jack-wspgeka3zvll-master-0.179551e5c4f5c10c", "namespace"=>"default", "uid"=>"7f2fe1e1-7f2c-4e91-901e-432a6b086b30", "resourceVersion"=>"1101", "creationTimestamp"=>"2023-11-07T10:54:41Z", "managedFields"=>[{"manager"=>"openstack-cloud-controller-manager", "operation"=>"Update", "apiVersion"=>"v1", "time"=>"2023-11-07T10:54:41Z", "fieldsType"=>"FieldsV1", "fieldsV1"=>{"f:count"=>{}, "f:firstTimestamp"=>{}, "f:involvedObject"=>{}, "f:lastTimestamp"=>{}, "f:message"=>{}, "f:reason"=>{}, "f:source"=>{"f:component"=>{}}, "f:type"=>{}}}]}, "involvedObject"=>{"kind"=>"Node", "name"=>"clu-jack-wspgeka3zvll-master-0", "uid"=>"7a4677ba-e0b4-4267-baf0-4c3e2f8aca40", "apiVersion"=>"v1", "resourceVersion"=>"1031"}, "reason"=>"Synced", "message"=>"Node synced successfully", "source"=>{"component"=>"cloud-node-controller"}, "firstTimestamp"=>"2023-11-07T10:54:41Z", "lastTimestamp"=>"2023-11-07T10:54:41Z", "count"=>1, "type"=>"Normal", "eventTime"=>nil, "reportingComponent"=>"", "reportingInstance"=>""}]

The messages above show that Fluent Bit started successfully and was able to connect to the Kubernetes API server. We can also observe the first Events (tagged with k8s_events) formatted as Fluent Bit Records. A JSON-formatted and prettified version of event number 0 looks like this:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48

{
  "metadata": {
    "name": "clu-jack-wspgeka3zvll-master-0.179551d6593eef9f",
    "namespace": "default",
    "uid": "5a78ff62-d6e1-43bc-a727-daa05da70688",
    "resourceVersion": "245",
    "creationTimestamp": "2023-11-07T10:53:35Z",
    "managedFields": [
      {
        "manager": "kube-controller-manager",
        "operation": "Update",
        "apiVersion": "v1",
        "time": "2023-11-07T10:53:35Z",
        "fieldsType": "FieldsV1",
        "fieldsV1": {
          "f:count": {},
          "f:firstTimestamp": {},
          "f:involvedObject": {},
          "f:lastTimestamp": {},
          "f:message": {},
          "f:reason": {},
          "f:source": {
            "f:component": {}
          },
          "f:type": {}
        }
      }
    ]
  },
  "involvedObject": {
    "kind": "Node",
    "name": "clu-jack-wspgeka3zvll-master-0",
    "uid": "7a4677ba-e0b4-4267-baf0-4c3e2f8aca40",
    "apiVersion": "v1"
  },
  "reason": "RegisteredNode",
  "message": "Node clu-jack-wspgeka3zvll-master-0 event: Registered Node clu-jack-wspgeka3zvll-master-0 in Controller",
  "source": {
    "component": "node-controller"
  },
  "firstTimestamp": "2023-11-07T10:53:35Z",
  "lastTimestamp": "2023-11-07T10:53:35Z",
  "count": 1,
  "type": "Normal",
  "eventTime": null,
  "reportingComponent": "",
  "reportingInstance": ""
}

Fantastic! Now you can adjust the destination of these logs (the “output”) according to your infrastructure (refer to this list of supported outputs) and you’re good to go - almost.

#  Optimization

After deploying this setup in my Kubernetes cluster I checked the container metrics (Prometheus/Grafana) and noticed that the Fluent Bit Pod had a really high incoming traffic rate - on average 3 megabit per second. This did not correspond in any way to the amount of Kubernetes Events the cluster was generating, so I had to start investigating this behavior.

screenshot of pod incoming traffic

I read the documentation of Kubernetes Events plugin again and came across some interesting settings, but from their descriptions I could not figure out what they really meant. The following are direct quotes from the documentation:

  • interval_sec: Set the polling interval for each channel (default: 5).
  • kube_request_limit: Kubernetes limit parameter for events query, no limit applied when set to 0 (default: 0).
  • kube_retention_time: Kubernetes retention time for events (default: 1h).
  • db: Set a database file to keep track of recorded Kubernetes events.
  • db.sync: Set a database sync method. values: extra, full, normal and off (default: normal).

Thus I had to resort to the source code of the plugin to find out what’s really going on. Here’s my summary:

  • The plugin does not watch events (like what kubectl get events -w does), it instead uses polling.
  • At periodic intervals (interval_sec), the plugin fetches ALL Kubernetes Events from the API (kube_request_limit: 0).
  • These events are then stored in a local database (db).
  • This database is used to avoid processing the same event multiple times (checked based on the resourceVersion of the event).
  • Events are deleted from the local database if they are older than the Kubernetes Events TTL (kube_retention_time).

I was honestly quite perplexed when I found out that this is the case. Why is Fluent Bit not using a streaming approach by watching Events on the Kubernetes API server? We may never know. But this explains why I was seeing such large amounts of incoming traffic: by default, Fluent Bit dumps the full list of Events every 5 seconds. Let’s do a quick check:

1
2
3
4

$ kubectl get events -A | wc -l
10961 # number of events
$ kubectl get events -A -o json | wc -c
2646663 # number of characters

Yup, that is going to cause a lot of traffic if we run it every 5 seconds.

With this knowledge we can tame the behavior of Fluent Bit:

  • fetch events less often: since collecting events is not time-critical (the live events can always be viewed directly in the cluster), the period can be increased to higher value such as 30 or 60 seconds.
  • use pagination to avoid fetching all events: by setting kube_request_limits (e.g. 250) the plugin will only fetch an ordered subset of events from the API server; since they are ordered, if one of the events in the current batch has already been processed, the plugin won’t make additional API calls to fetch the rest of the events (since “the rest” is already stored in the local database).

The final configuration looks as follows. Of course, it should be adjusted according to the activity and size of your cluster(s).

1
2
3
4
5
6
7
8

[INPUT]
name kubernetes_events
# add the tag "k8s_events" to all events coming from this input
tag k8s_events
# ask k8s API for updates every 30 seconds
interval_sec 30
# fetch at most 250 items per requests (pagination)
kube_request_limit 250

With these changes the network traffic looks much more reasonable (and also CPU and memory consumption are lower).

network activity after

Happy logging!

#  See also