IT IS DNS AGAIN !!! KONG API WAS STOPPED IN ITS TRACKS

We have a two node Kubernetes cluster with one master and one worker node. Kong api is installed as containers on this cluster. Log files in our Kong API server were located in root directory of the host machine. As the number of logs were getting increased, there was a danger of filling up root directory. So, we decided to move it to separate mount keeping directory path same. Our plan was as below:

1. Cordon and drain the node.
2. Stop kubelet and docker.
3. Move logs to separate mount.
4. Start docker and kubelet.
5. Uncordon the node.

We followed the plan but Kong pod was stuck in Init state. We have verified Kong access, error logs, Init (wait-for-db container) container logs and kubelet logs (/var/log/messages in our case). There was nothing suspicious written. We also checked status of all kube-system pods and all were running fine. We verified Control Plane logs as well. We tried restarting docker, kubelet and Cassandra pods (Kong’s persistent store). But nothing worked. Sooner it dawned on me that it was going to be long battle.

As Init container is running, we thought of starting Kong manually from the init container. I got into shell of the container and started kong in debug mode as below:

kubectl exec -it <kong pod name> -c waiting-for-db bash
kong start --vv

Kong was hanging here too after writing below verbose output:

2021/06/10 17:30:17 [debug] trusted_ips = {}
2021/06/10 17:30:17 [debug] upstream_keepalive = 60
2021/06/10 17:30:17 [debug] vitals = true
2021/06/10 17:30:17 [debug] vitals_delete_interval_pg = 30
2021/06/10 17:30:17 [debug] vitals_flush_interval = 10
2021/06/10 17:30:17 [debug] vitals_prometheus_scrape_interval = 5
2021/06/10 17:30:17 [debug] vitals_statsd_prefix = "kong"
2021/06/10 17:30:17 [debug] vitals_statsd_udp_packet_size = 1024
2021/06/10 17:30:17 [debug] vitals_strategy = "database"
2021/06/10 17:30:17 [debug] vitals_ttl_minutes = 90000
2021/06/10 17:30:17 [debug] vitals_ttl_seconds = 3600
2021/06/10 17:30:17 [warn] RBAC authorization is enabled but Admin API calls will not be encrypted via SSL
2021/06/10 17:30:17 [verbose] prefix in use: /usr/local/kong

After this, we came to a conclusion that Kong process was hung and waiting for something. But we were not sure for what it was waiting. We usually use strace, lsof and other tools to investigate hang and slowness issues. Unfortunately, strace cannot be used with containers and other network tools were not part of the Kong image. So, we decided to check proc file system for a clue.

Found the process id using following commands:

$ ps -ef
UID PID PPID C STIME TTY TIME CMD
kong 1 0 0 03:38 ? 00:00:00 /bin/sh -c until kong start; do echo 'waiting for db'; sleep 1; done; kong stop
kong 6 1 0 03:38 ? 00:00:00 perl /usr/local/openresty/bin/resty /usr/local/bin/kong start
kong 8 6 0 03:38 ? 00:00:00 /usr/local/openresty/nginx/sbin/nginx -p /tmp/resty_uBRRyunnCu/ -c conf/nginx.co

From above ps output, the process id of the kong was 8. We changed directory to /proc/8/ and listed it contents:

Checked at what syscall the kong process was executing by looking at syscall file. It had below content and was not changing . That means this syscall was waiting for file descriptor 7 which can be a file or network connection.

7 0x7ffe9daf9750 0x1 0x1e847f 0x60c2f245 0x0 0x1 0x7ffe9daf9748 0x7f2d3e5781f0

Next logical step was to find out what this file descriptor belonged to. Below is listing from /proc/8/fd directory. From this, we concluded that process is waiting on a network connection.

lrwx------ 1 kong kong 64 Jun 11 05:29 7 -> socket:[436899094]
lrwx------ 1 kong kong 64 Jun 11 05:29 6 -> socket:[436899093]
lrwx------ 1 kong kong 64 Jun 11 05:29 5 -> anon_inode:[signalfd]
lrwx------ 1 kong kong 64 Jun 11 05:29 4 -> anon_inode:[eventfd]
lrwx------ 1 kong kong 64 Jun 11 05:29 3 -> anon_inode:[eventpoll]
l-wx------ 1 kong kong 64 Jun 11 05:29 2 -> pipe:[436890129]
l-wx------ 1 kong kong 64 Jun 11 05:29 1 -> pipe:[436890128]
lrwx------ 1 kong kong 64 Jun 11 05:29 0 -> /dev/null

Next step was to find out where this network connection was going. This information can be obtained from /proc/<proc id>/net directory. There were 4 files for each protocol (tcp, tcp6, udp and udp). All files were empty except udp. It had following content:

9577: 7E01F40A:E2B4 0A00600A:0035 01 00000000:00000000 00:00000000 00000000 1000 0 437443032 2 0000000000000000 0
12520: 7E01F40A:AE33 0A00600A:0035 01 00000000:00000000 00:00000000 00000000 1000 0 436899093 2 0000000000000000 0

Second column in above output was about source machine ip and port. Similarly, 3rd column was about target machine ip and port. Both were in hexadecimal. 0035 is hexadecimal representation of 53 which is usually DNS listen port. So, Kong process was waiting for DNS response. To confirm it, we tested connectivity to DNS server using below curl command:
curl <DNS Server ip>:53

Even curl command was hanging. So we concluded that the issue was due to DNS. We restarted DNS pods and Kong pods automatically came into running state. Still missing piece in the puzzle is why DNS pod was not responding.