Falco: Falco would occasionally restart due to connection error to kubernetes api service

[oownus]

What happened:
Falco agents would occasionally restart due to a connection error to kubernetes service at kubernetes.default.svc.cluster.local (10.195.238.1)
It seems to happen more frequently especially on the busy clusters.

...
Sun Nov 17 03:12:13 2019: Runtime error: Error during connection attempt to https://10.195.238.1 (socket=122, error=111): Connection refused. Exiting.

...
Sun Nov 17 03:08:02 2019: Runtime error: Socket handler (k8s_namespace_handler_event) an error occurred while connecting to https://10.195.238.1: Connection refused. Exiting.



md5-bdbbeca1d811a0abadbcf0ee53f7e7b4



20:56:23.256627 IP falco-daemonset-nxb72.38144 > kube-dns.kube-system.svc.cluster.local.53: 54927+ A? mine.moneropool.com.falco.svc.cluster.local. (61)
20:56:23.258072 IP kube-dns.kube-system.svc.cluster.local.53 > falco-daemonset-nxb72.38144: 54927 NXDomain 0/1/0 (154)
20:56:23.258194 IP falco-daemonset-nxb72.38144 > kube-dns.kube-system.svc.cluster.local.53: 18838+ AAAA? mine.moneropool.com.falco.svc.cluster.local. (61)
20:56:23.259073 IP kube-dns.kube-system.svc.cluster.local.53 > falco-daemonset-nxb72.38144: 18838 NXDomain 0/1/0 (154)
20:56:23.260583 IP falco-daemonset-nxb72.35302 > kube-dns.kube-system.svc.cluster.local.53: 7232+ A? mine.moneropool.com.svc.cluster.local. (55)
20:56:23.261660 IP kube-dns.kube-system.svc.cluster.local.53 > falco-daemonset-nxb72.35302: 7232 NXDomain 0/1/0 (148)



md5-c951fa661bdba4b7a3c645f208dc8ed6



00:34:51.359118 IP kubernetes.default.svc.cluster.local.443 > falco-daemonset-6xq4c.60896: Flags [P.], seq 2129670:2133795, ack 1, win 285, options [nop,nop,TS val 3858423463 ecr 1533327183], length 4125
00:34:51.359131 IP falco-daemonset-6xq4c.60896 > kubernetes.default.svc.cluster.local.443: Flags [.], ack 2133795, win 1945, options [nop,nop,TS val 1533328911 ecr 3858423463], length 0
00:34:51.359135 IP kubernetes.default.svc.cluster.local.443 > falco-daemonset-6xq4c.60896: Flags [P.], seq 2133795:2139997, ack 1, win 285, options [nop,nop,TS val 3858423463 ecr 1533327183], length 6202
00:34:51.359139 IP falco-daemonset-6xq4c.60896 > kubernetes.default.svc.cluster.local.443: Flags [.], ack 2139997, win 1911, options [nop,nop,TS val 1533328911 ecr 3858423463], length 0
00:34:51.359259 IP kubernetes.default.svc.cluster.local.443 > falco-daemonset-6xq4c.60896: Flags [P.], seq 2139997:2140028, ack 1, win 285, options [nop,nop,TS val 3858423463 ecr 1533328911], length 31
00:34:51.359262 IP falco-daemonset-6xq4c.60896 > kubernetes.default.svc.cluster.local.443: Flags [.], ack 2140028, win 1911, options [nop,nop,TS val 1533328911 ecr 3858423463], length 0
00:34:51.637833 IP kubernetes.default.svc.cluster.local.443 > falco-daemonset-6xq4c.60896: Flags [P.], seq 2140028:2144153, ack 1, win 285, options [nop,nop,TS val 3858423742 ecr 1533328911], length 4125
00:34:51.637863 IP falco-daemonset-6xq4c.60896 > kubernetes.default.svc.cluster.local.443: Flags [.], ack 2144153, win 1879, options [nop,nop,TS val 1533329189 ecr 3858423742], length 0
00:34:51.637868 IP kubernetes.default.svc.cluster.local.443 > falco-daemonset-6xq4c.60896: Flags [P.], seq 2144153:2149731, ack 1, win 285, options [nop,nop,TS val 3858423742 ecr 1533328911], length 5578
00:34:51.637871 IP falco-daemonset-6xq4c.60896 > kubernetes.default.svc.cluster.local.443: Flags [.], ack 2149731, win 1841, options [nop,nop,TS val 1533329190 ecr 3858423742], length 0
00:34:51.638019 IP kubernetes.default.svc.cluster.local.443 > falco-daemonset-6xq4c.60896: Flags [P.], seq 2149731:2149762, ack 1, win 285, options [nop,nop,TS val 3858423742 ecr 1533329189], length 31
00:34:51.638024 IP falco-daemonset-6xq4c.60896 > kubernetes.default.svc.cluster.local.443: Flags [.], ack 2149762, win 1841, options [nop,nop,TS val 1533329190 ecr 3858423742], length 0



md5-7f4e38129b256bb4f197a6221bc7847b



# falco --support | jq .system_info
Fri Nov 22 19:21:42 2019: Falco initialized with configuration file /etc/falco/falco.yaml
Fri Nov 22 19:21:42 2019: Loading rules from file /etc/falco/falco_rules.yaml:
Fri Nov 22 19:21:42 2019: Loading rules from file /etc/falco/falco_rules.local.yaml:
{
  "machine": "x86_64",
  "nodename": "falco-daemonset-nr758",
  "release": "4.14.137+",
  "sysname": "Linux",
  "version": "#1 SMP Thu Aug 8 02:47:02 PDT 2019"
}



md5-a590ee9e047a80907840d5b09d28e9df



PRETTY_NAME="Debian GNU/Linux bullseye/sid"
NAME="Debian GNU/Linux"
ID=debian
HOME_URL="https://www.debian.org/"
SUPPORT_URL="https://www.debian.org/support"
BUG_REPORT_URL="https://bugs.debian.org/"



md5-2dd661ea99e8a3747c9858b58126ed25



Linux falco-daemonset-nr758 4.14.137+ #1 SMP Thu Aug 8 02:47:02 PDT 2019 x86_64 GNU/Linux



md5-053526be28af6c60204952cc16c2c1c5



Kubernetes master node 1.13.11-gke.14
Kubernetes node 1.13.10-gke.0

• Others:

[axot]

I think this is related to #680, we are using the latest Falco version: 0.18.0.

Mon Dec 16 08:28:56 2019: Runtime error: Socket handler (k8s_daemonset_handler_event) an error occurred while connecting to https://10.110.128.1: Connection timed out. Exiting.

https://github.com/falcosecurity/falco/blob/28fa4a72e85bce322a7a6d63fae47ee6b49f1721/userspace/falco/falco.cpp#L1251
Should we generate a stack backtrace here?

[fntlnz]

yes please @axot - it would be useful!

[axot]

Hi I got some progress, this backtrace was generated from 0.18.1.

Catchpoint 1 (exception thrown), 0x00007ffff7e5e2ae in __cxa_throw () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#0  0x00007ffff7e5e2ae in __cxa_throw () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#1  0x0000555555704c74 in socket_data_handler<k8s_handler>::try_connect (this=this@entry=0x55555615b400) at /usr/include/c++/9/ext/new_allocator.h:89
#2  0x0000555555706036 in socket_data_handler<k8s_handler>::connect_socket (this=0x55555615b400) at /usr/include/c++/9/bits/basic_string.h:2300
#3  0x00005555557063bc in socket_data_handler<k8s_handler>::get_socket (timeout_ms=<optimized out>, this=0x55555615b400) at /usr/src/dev/sysdig/userspace/libsinsp/socket_handler.h:92
#4  socket_collector<socket_data_handler<k8s_handler> >::add (this=0x5555561046b0, handler=std::shared_ptr<socket_data_handler<k8s_handler>> (use count 2, weak count 0) = {...}) at /usr/src/dev/sysdig/userspace/libsinsp/socket_collector.h:34
#5  0x00005555556ec323 in k8s_handler::connect (this=0x555556099740) at /usr/include/c++/9/ext/atomicity.h:96
#6  0x00005555556ef1f2 in k8s_handler::k8s_handler (this=0x555556099740, id=..., is_captured=<optimized out>, url=..., path=..., state_filter=..., event_filter=".", null_filter="", collector=std::shared_ptr<socket_collector<socket_data_handler<k8s_handler> >> (use count 4, weak count 0) = {...}, http_version="1.1", timeout_ms=1000, ssl=std::shared_ptr<sinsp_ssl> (use count 5, weak count 0) = {...}, bt=std::shared_ptr<sinsp_bearer_token> (use count 5, weak count 0) = {...}, watch=false, connect=true, dependency_handler=std::shared_ptr<k8s_handler> (use count 2, weak count 0) = {...}, blocking_socket=true, max_messages=4294967295, state=0x0) at /usr/src/dev/sysdig/userspace/libsinsp/k8s_handler.cpp:101
#7  0x000055555578c790 in k8s_api_handler::k8s_api_handler (this=0x555556099740, collector=..., url=..., path="/api", filter=".versions", http_version="1.1", ssl=std::shared_ptr<sinsp_ssl> (use count 5, weak count 0) = {...}, bt=std::shared_ptr<sinsp_bearer_token> (use count 5, weak count 0) = {...}, blocking_socket=true) at /usr/include/c++/9/bits/char_traits.h:300
#8  0x0000555555766f77 in sinsp::update_k8s_state (this=0x555555c3cd50) at /usr/include/c++/9/ext/atomicity.h:96
#9  0x0000555555767879 in sinsp::next (this=0x555555c3cd50, puevt=0x7fffffffc0c8) at /usr/src/dev/sysdig/userspace/libsinsp/sinsp.cpp:1139
#10 0x000055555567545b in do_inspect (engine=0x555555c66ac0, outputs=0x555555c67880, inspector=0x555555c3cd50, duration_to_tot_ns=0, stats_filename=...) at /usr/src/dev/falco/userspace/falco/falco.cpp:169
#11 0x0000555555678f82 in falco_init (argc=<optimized out>, argv=<optimized out>) at /usr/src/dev/falco/userspace/falco/falco.cpp:723
#12 0x00007ffff7abebbb in __libc_start_main (main=0x555555664900 <main(int, char**)>, argc=6, argv=0x7fffffffcce8, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fffffffccd8) at ../csu/libc-start.c:308
#13 0x00005555556679ea in _start () at /usr/include/c++/9/ext/new_allocator.h:89
Thu Dec 19 07:51:48 2019: Runtime error: Error during connection attempt to https://10.135.0.1 (socket=5, error=110): Connection timed out. Exiting.

[axot]

@fntlnz So it should use exponential backoff retry to improve this?

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[Thyrst]

Hi, we have probably the same issue. Falco 0.18.0 on GKE.

Runtime error: Socket handler (k8s_deployment_handler_event) an error occurred while connecting to https://10.0.16.1: Connection timed out. Exiting.

[Thyrst]

Setting dnsConfig.ndots to 1 didn't help and I did not find any relevance between restarts and CPU, memory or network usage neither.

[ahmed1smael]

@fntlnz Wondering if you have an update on this, we are getting this in 0.20.0 in GKE too:
Runtime error: Socket handler (k8s_daemonset_handler_event) an error occurred while connecting to https://x.x.x.x: Connection timed out. Exiting.

[a0145]

I am also hitting this, with falco <= 0.22
Mon Apr 13 17:59:07 2020: Runtime error: Socket handler (k8s_namespace_handler_event), error 5 (Success) while connecting to apiserver:443. Exiting.

[loetn]

Same here, using latest Falco:
Runtime error: Error during connection attempt to https://10.96.0.1 (socket=8, error=110): Connection timed out. Exiting.

[itaimirin]

Same here. Also using the latest:

Runtime error: Socket handler (k8s_replicaset_handler_event) an error occurred while connecting to https://10.15.240.1: Connection timed out.

[webbdog28]

Same error as well. Are there plans to address?

[robsonke]

In what way can we help to solve this issue. Our Falco instances restart roughly once an hour due to this issue, which isn't an operational problem but does pollute our monitoring. With over 80 instances running, we get quite some restarts.

Silly thought, but can't we just catch such a connection issue, retry a few times and then just ignore instead of crash?

Info: Kubernetes 1.13 and 1.14 both gave these issues, Falco 0.21, 0.22 and 0.23, all the same.

[fntlnz]

Investigated this a bit more and after talking with @leodido we agreed that the problem here is that the library we use to enrich events with kubernetes metadata (libsinsp) does not have an extensive exception hierarchy to allow us to understand when an exception is thrown because of a connection error or something else.

Connection errors to kubernetes can happen (network can fail) but we should log the error instead of stopping Falco. At the moment we have no way to understand what are the types of errors that can stop Falco vs the types of errors that should not.

The interesting exception is here:
https://github.com/draios/sysdig/blob/master/userspace/libsinsp/socket_handler.h#L1211

To solve this, we need to connect with the community behind libsinsp and make a plan with them to make the exceptions more blatant. This needs at least a discussion on the community call too because it can be very impacting on how Falco works.

In the meanwhile, what we suggest is to let Kubernetes restart Falco when the errors occur.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions. Issues labeled "cncf", "roadmap" and "help wanted" will not be automatically closed. Please refer to a maintainer to get such label added if you think this should be kept open.

[mvandewouw]

same issue on aks: Fri Aug 21 09:39:43 2020: Runtime error: Socket handler (k8s_api_handler_state), error 5 (Success) while connecting to **.azmk8s.io:443. Exiting.

[leogr]

/help

[poiana]

@leogr:
This request has been marked as needing help from a contributor.

Please ensure the request meets the requirements listed here.

If this request no longer meets these requirements, the label can be removed
by commenting with the /remove-help command.

In response to this:

/help

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

[djsly]

on AKS

Wed Oct 14 19:48:49 2020: Runtime error: Socket handler (k8s_namespace_handler_event), error 5 (Success) while connecting to 192.168.0.1:443. Exiting.

[poiana]

Issues go stale after 90d of inactivity.

Mark the issue as fresh with /remove-lifecycle stale.

Stale issues rot after an additional 30d of inactivity and eventually close.

If this issue is safe to close now please do so with /close.

Provide feedback via https://github.com/falcosecurity/community.

/lifecycle stale

[bygui86]

I'm have the same issue on GKE

2021-01-18T09:58:31+0000: Runtime error: Socket handler (k8s_replicationcontroller_handler_event) an error occurred while connecting to https://10.4.0.1: Connection timed out. Exiting.

falco version: 0.26.2
k8s version: 1.17.14-gke400

@fntlnz is there a way to increase the timeout?

/remove-lifecycle stale

[kkujawa-sumo]

I also see this issue using falco version 0.26.2 on OpenShift 4.6.4 on AWS.

Tue Jan 19 13:31:34 2021: Runtime error: Socket handler (k8s_service_handler_event) an error occurred while connecting to https://172.30.0.1: Connection refused. Exiting.

Mon Jan 18 22:33:58 2021: Runtime error: Socket handler (k8s_namespace_handler_event) an error occurred while connecting to https://172.30.0.1: Connection refused. Exiting.

[bygui86]

The main issue is not only that Falco restarts due to this error (timeout or connection refused), but also because it happens tons of times... In less than 2 days, I've seen Falco pods restarting between 40 and 500 times!!
This means in the worst case scenario even 10 times/hour!!!
And the restart does not take 2 seconds, but till 2 minutes... so every hour I have 20 minutes in which Falco does not audit...

[bygui86]

Thanks to @leogr I found what was causing my issues: the ClusterRole configuration!
Running on GKE, this is the ClusterRole I'm using currently:

kind: ClusterRole
apiVersion: rbac.authorization.k8s.io/v1
metadata:
  name: falco
rules:
  - nonResourceURLs:
      - /healthz
      - /healthz/*
    verbs:
      - get
  - apiGroups:
      - extensions
      - ""
    resources:
      - nodes
      - namespaces
      - pods
      - replicationcontrollers
      - replicasets
      - services
      - daemonsets
      - deployments
      - events
      - configmaps
    verbs:
      - get
      - list
      - watch
  - apiGroups:
      - apps
    resources:
      - daemonsets
      - deployments
      - replicasets
      - statefulsets
    verbs:
      - get
      - list
      - watch

Result: no restarts in the last 3 days :)

Unfortunately Falco put out a log of a "connection timeout" but actually it ends up having no rights to get info about either deployment, job, statefulset or else.
I think on Falco side can be improved the specific log, in order to better identify if it's a bad communication with the k8s-api-server or else (like in my case missing of rights)