Falco restarted hundreds of times during a week of deployment

[ye]

Hi, I am testing falco daemonset on our GKE cluster in GCP, it works great except that after a week of running, all the the falco pods have been restarted hundreds of times and it’s probably clogging the kublet’s rate limit to cause new pods from properly running (they kept crashing, delete falco daemonset solves the issue).

Perhaps the default rulesets are probably too intensive and too noisy for a typical k8s environment. I’ve read through falco rules wiki page but nothing jumps out for me to solve them. Can anyone give me some additional pointers to fine tune those default rules? Where should I start? Thanks.

K8s info:

$ kubectl version
Client Version: version.Info{Major:"1", Minor:"13", GitVersion:"v1.13.0", GitCommit:"ddf47ac13c1a9483ea035a79cd7c10005ff21a6d", GitTreeState:"clean", BuildDate:"2018-12-03T21:04:45Z", GoVersion:"go1.11.2", Compiler:"gc", Platform:"darwin/amd64"}
Server Version: version.Info{Major:"1", Minor:"10+", GitVersion:"v1.10.11-gke.1", GitCommit:"5c4fddf874319c9825581cc9ab1d0f0cf51e1dc9", GitTreeState:"clean", BuildDate:"2018-11-30T16:18:58Z", GoVersion:"go1.9.3b4", Compiler:"gc", Platform:"linux/amd64"}

kubectl logs && kubectl describe pod Logs: https://gist.github.com/ye/0f4195faf3f80e7d4c8d618ae6b590b2

[mfdii]

@ye are you still seeing this?

[ye]

@mfdii yes, I am stilling seeing this behavior.

Here is a recent episode:

$ kubectl describe po falco-pqpdc
Name:           falco-pqpdc
Namespace:      default
Node:           gke-maven-stateless-pool-1512435801-f55a0382-7lxs/10.240.0.10
Start Time:     Thu, 07 Mar 2019 17:42:21 -0500
Labels:         app=maven-falco
                controller-revision-hash=764563707
                name=monitored-nodes
                pod-template-generation=1
                role=security
Annotations:    <none>
Status:         Running
IP:             10.240.0.10
Controlled By:  DaemonSet/falco
Containers:
  falco:
    Container ID:  docker://e6a22cdb403345411ee9af64c4de621caf4557959e4157502e8149f8aa8fe10d
    Image:         falcosecurity/falco:0.14.0
    Image ID:      docker-pullable://falcosecurity/falco@sha256:8176b851e5a6c2fb0662c32ab7ce18d59d0d8a896cd46844c810c6766b0c817c
    Port:          <none>
    Host Port:     <none>
    Args:
      /usr/bin/falco
      -K
      /var/run/secrets/kubernetes.io/serviceaccount/token
      -k
      https://kubernetes.default
      -o
      json_output=true
      -o
      program_output.enabled=true
      -o
      program_output.program=jq '{text: .output}'
    State:          Running
      Started:      Thu, 07 Mar 2019 18:17:24 -0500
    Last State:     Terminated
      Reason:       Error
      Exit Code:    139
      Started:      Thu, 07 Mar 2019 17:42:22 -0500
      Finished:     Thu, 07 Mar 2019 18:17:23 -0500
    Ready:          True
    Restart Count:  1
    Requests:
      cpu:     20m
      memory:  160M
    Environment:
      SYSDIG_BPF_PROBE:  
    Mounts:
      /host/boot from boot-fs (ro)
      /host/dev from dev-fs (rw)
      /host/etc from etc-fs (ro)
      /host/lib/modules from lib-modules (ro)
      /host/proc from proc-fs (ro)
      /host/usr from usr-fs (ro)
      /host/var/run/docker.sock from docker-socket (rw)
      /var/run/secrets/kubernetes.io/serviceaccount from falco-service-account-token-hfplx (ro)
Conditions:
  Type           Status
  Initialized    True 
  Ready          True 
  PodScheduled   True 
Volumes:
  docker-socket:
    Type:          HostPath (bare host directory volume)
    Path:          /var/run/docker.sock
    HostPathType:  
  dev-fs:
    Type:          HostPath (bare host directory volume)
    Path:          /dev
    HostPathType:  
  proc-fs:
    Type:          HostPath (bare host directory volume)
    Path:          /proc
    HostPathType:  
  boot-fs:
    Type:          HostPath (bare host directory volume)
    Path:          /boot
    HostPathType:  
  lib-modules:
    Type:          HostPath (bare host directory volume)
    Path:          /lib/modules
    HostPathType:  
  usr-fs:
    Type:          HostPath (bare host directory volume)
    Path:          /usr
    HostPathType:  
  etc-fs:
    Type:          HostPath (bare host directory volume)
    Path:          /etc
    HostPathType:  
  falco-service-account-token-hfplx:
    Type:        Secret (a volume populated by a Secret)
    SecretName:  falco-service-account-token-hfplx
    Optional:    false
QoS Class:       Burstable
Node-Selectors:  <none>
Tolerations:     node.kubernetes.io/disk-pressure:NoSchedule
                 node.kubernetes.io/memory-pressure:NoSchedule
                 node.kubernetes.io/not-ready:NoExecute
                 node.kubernetes.io/unreachable:NoExecute
Events:
  Type    Reason                 Age               From                                                        Message
  ----    ------                 ----              ----                                                        -------
  Normal  SuccessfulMountVolume  36m               kubelet, gke-maven-stateless-pool-1512435801-f55a0382-7lxs  MountVolume.SetUp succeeded for volume "proc-fs"
  Normal  SuccessfulMountVolume  36m               kubelet, gke-maven-stateless-pool-1512435801-f55a0382-7lxs  MountVolume.SetUp succeeded for volume "boot-fs"
  Normal  SuccessfulMountVolume  36m               kubelet, gke-maven-stateless-pool-1512435801-f55a0382-7lxs  MountVolume.SetUp succeeded for volume "docker-socket"
  Normal  SuccessfulMountVolume  36m               kubelet, gke-maven-stateless-pool-1512435801-f55a0382-7lxs  MountVolume.SetUp succeeded for volume "usr-fs"
  Normal  SuccessfulMountVolume  36m               kubelet, gke-maven-stateless-pool-1512435801-f55a0382-7lxs  MountVolume.SetUp succeeded for volume "dev-fs"
  Normal  SuccessfulMountVolume  36m               kubelet, gke-maven-stateless-pool-1512435801-f55a0382-7lxs  MountVolume.SetUp succeeded for volume "etc-fs"
  Normal  SuccessfulMountVolume  36m               kubelet, gke-maven-stateless-pool-1512435801-f55a0382-7lxs  MountVolume.SetUp succeeded for volume "lib-modules"
  Normal  SuccessfulMountVolume  36m               kubelet, gke-maven-stateless-pool-1512435801-f55a0382-7lxs  MountVolume.SetUp succeeded for volume "falco-service-account-token-hfplx"
  Normal  Pulled                 1m (x2 over 36m)  kubelet, gke-maven-stateless-pool-1512435801-f55a0382-7lxs  Container image "falcosecurity/falco:0.14.0" already present on machine
  Normal  Created                1m (x2 over 36m)  kubelet, gke-maven-stateless-pool-1512435801-f55a0382-7lxs  Created container
  Normal  Started                1m (x2 over 36m)  kubelet, gke-maven-stateless-pool-1512435801-f55a0382-7lxs  Started container

$ kubectl logs -f falco-pqpdc
* Setting up /usr/src links from host
ls: cannot access '/host/usr/src': No such file or directory
* Mounting debugfs
Found kernel config at /proc/config.gz
* COS detected (build 10452.101.0), downloading and setting up kernel headers
* Downloading https://storage.googleapis.com/cos-tools/10452.101.0/kernel-src.tar.gz
* Extracting kernel sources
* Configuring kernel
* Trying to compile BPF probe falco-probe-bpf (falco-probe-bpf-0.14.0-x86_64-4.14.22+-8953a03c1317cdc6d882d1f17b7fe001.o)
* BPF probe located, it's now possible to start sysdig
Thu Mar  7 23:20:17 2019: Falco initialized with configuration file /etc/falco/falco.yaml
Thu Mar  7 23:20:17 2019: Loading rules from file /etc/falco/falco_rules.yaml:
Thu Mar  7 23:20:17 2019: Loading rules from file /etc/falco/falco_rules.local.yaml:
Thu Mar  7 23:20:17 2019: Loading rules from file /etc/falco/k8s_audit_rules.yaml:
Thu Mar  7 23:20:18 2019: Starting internal webserver, listening on port 8765
{"output":"23:20:23.718171130: Notice Namespace change (setns) by unexpected program (user=<NA> command=<NA> parent=<NA> host (id=host))","priority":"Notice","rule":"Change thread namespace","time":"2019-03-07T23:20:23.718171130Z", "output_fields": {"container.id":"host","container.name":"host","evt.time":1552000823718171130,"proc.cmdline":"<NA>","proc.pname":null,"user.name":null}}
{
  "text": "23:20:23.718171130: Notice Namespace change (setns) by unexpected program (user=<NA> command=<NA> parent=<NA> host (id=host))"
}
{"output":"{\"container.id\":\"host\",\"container.name\":\"host\",\"evt.time\":1552000823718176168,\"proc.cmdline\":\"<NA>\",\"proc.pname\":null,\"user.name\":null}","priority":"Notice","rule":"Change thread namespace","time":"2019-03-07T23:20:23.718176168Z", "output_fields": {"container.id":"host","container.name":"host","evt.time":1552000823718176168,"proc.cmdline":"<NA>","proc.pname":null,"user.name":null}}
{
  "text": "{\"container.id\":\"host\",\"container.name\":\"host\",\"evt.time\":1552000823718176168,\"proc.cmdline\":\"<NA>\",\"proc.pname\":null,\"user.name\":null}"
}

[ye]

One question I have for the above log is that it's complaining /host/usr/src folder not existing (it's probably not in CoreOS image), but it seems that it's working (genreating log outputs in STDOUT). Is it okay to that falco pods restarted frequently? In this particular instance, I check the k8s events and pod logs, nothing really telling me why it restarted.

[ye]

17 hours later, some of the pods have almost hourly restarts. The last log line for all the falco pods that is non-json is free(): double free detected in tcache 2.

$ kuberctl get pods -l app=maven-falco
NAME          READY     STATUS    RESTARTS   AGE
falco-6vjq9   1/1       Running   17         17h
falco-hsdpt   1/1       Running   7          17h
falco-jxbrr   1/1       Running   1          17h
falco-k85kz   1/1       Running   5          17h
falco-pqpdc   1/1       Running   15         17h
falco-qzh8g   1/1       Running   9          17h
falco-tmw8k   1/1       Running   10         17h
falco-xctvk   1/1       Running   17         17h
falco-z9c7r   1/1       Running   18         17h
falco-zrtzp   1/1       Running   6          17h

$ for pod in `kubectl get pods --no-headers -l app=maven-falco -o custom-columns=":metadata.name"`; do echo -n "$pod exited with: "; kubectl logs $pod -c falco --previous | tail -n 1; done;
falco-6vjq9 exited with: free(): double free detected in tcache 2
falco-hsdpt exited with: free(): double free detected in tcache 2
falco-jxbrr exited with: free(): double free detected in tcache 2
falco-k85kz exited with: free(): double free detected in tcache 2
falco-pqpdc exited with: free(): double free detected in tcache 2
falco-qzh8g exited with: free(): double free detected in tcache 2
falco-tmw8k exited with: free(): double free detected in tcache 2
falco-xctvk exited with: free(): double free detected in tcache 2
falco-z9c7r exited with: free(): double free detected in tcache 2
falco-zrtzp exited with: free(): double free detected in tcache 2

Which Google brings me to these:

• https://bugzilla.redhat.com/show_bug.cgi?id=1652495
• https://bugzilla.redhat.com/show_bug.cgi?id=1666197

Are those related perhaps to the Falco crash?

[mfdii]

I'll let @mstemm or @gianlucaborello comment on the free messages. That's out of my depth.

Would you please let us know the following:

• COS version
• GKE version
• # of average container in this env
• rate at which containers churn in this environment

You can tune the number of events you're getting by changing the minimum priority for rules in the falco.yaml. If you're using the default falco.yaml it sets this to debug (which we should probably change). https://github.com/falcosecurity/falco/blob/dev/falco.yaml#L60

[ye]

@mfdii thanks for your response. Here are the answers from my end:

• COS version: cos-69-10895-138-0
• GKE version: v1.10.4-gke.2
• Number of average container in this env: ~40 pods, each pod has anywhere between 1 to 3 containers inside.
• rate at which containers churn in this environment: roughly 1 restart per hour, some falco pods churns faster than that some slower

Here is excerpt output from kubectl get nodes -o wide (anonymized node identifiers and IPs)

$ kubectl get nodes -o wide
AGE       VERSION         OS-IMAGE                             KERNEL-VERSION   CONTAINER-RUNTIME
212d      v1.10.4-gke.2   Container-Optimized OS from Google   4.14.22+         docker://17.3.2
212d      v1.10.4-gke.2   Container-Optimized OS from Google   4.14.22+         docker://17.3.2
212d      v1.10.4-gke.2   Container-Optimized OS from Google   4.14.22+         docker://17.3.2
212d      v1.10.4-gke.2   Container-Optimized OS from Google   4.14.22+         docker://17.3.2
173d      v1.10.4-gke.2   Container-Optimized OS from Google   4.14.22+         docker://17.3.2
212d      v1.10.4-gke.2   Container-Optimized OS from Google   4.14.22+         docker://17.3.2
212d      v1.10.4-gke.2   Container-Optimized OS from Google   4.14.22+         docker://17.3.2
212d      v1.10.4-gke.2   Container-Optimized OS from Google   4.14.22+         docker://17.3.2
212d      v1.10.4-gke.2   Container-Optimized OS from Google   4.14.22+         docker://17.3.2

[mfdii]

Sorry. What rate do your application containers churn at, not the falco containers.

[ye]

It's hard to estimate, our application pods aren't churn at a constant pace or have a regular pattern, we have deployments throughout the day, sometimes 3-5 times a day during work hours sometimes we don't deployment for a few days. I don't seem to find any pattern related to the application deployments to the best of my knowledge.

[mfdii]

fixed in draios/sysdig#1330

[ye]

@mstemm @mfdii any plans to release this fix in a new version soon? Still waiting anxiously here after seeing the restarts in recent audit.

free(): double free detected in tcache 2

Btw, I've seen significantly reduced crashes on the COS version 69-10895 with 4.14.91+ kernel and together with Kubernetes version v1.12.5-gke.10 but they are still crashing. FYI.

[mfdii]

We should have a release that fixes this out later this week. @mstemm is prepping some other changes that need to go out, and when he cuts a release, this will be picked up.

[mfdii]

Have you tested this build and are the restarts still happening @ye?