How we reduced 502 errors by caring about PID 1 in Kubernetes

This blog post and linked pages contain information related to upcoming products, features, and functionality. It is important to note that the information presented is for informational purposes only. Please do not rely on this information for purchasing or planning purposes. As with all projects, the items mentioned in this blog post and linked pages are subject to change or delay. The development, release, and timing of any products, features, or functionality remain at the sole discretion of GitLab Inc.

Our SRE on call was getting paged daily that one of our SLIs was burning through our SLOs for the GitLab Pages service. It was intermittent and short-lived, but enough to cause user-facing impact which we weren't comfortable with. This turned into alert fatigue because there wasn't enough time for the SRE on call to investigate the issue and it wasn't actionable since it recovered on its own.

We decided to open up an investigation issue for these alerts. We had to find out what the issue was since we were showing 502 errors to our users and we needed a DRI that wasn't on call to investigate.

What is even going on?

As an SRE at GitLab, you get to touch a lot of services that you didn't build yourself and interact with system dependencies that you might have not touched before. There's always detective work to do!

When we looked at the GitLab Pages logs we found that it's always returning ErrDomainDoesNotExist errors which result in a 502 error to our users. GitLab Pages sends a request to GitLab Workhorse, specifically the /api/v4/internal/pages route.

GitLab Workhorse is a Go service in front of our Ruby on Rails monolith and it's deployed as a sidecar inside of the webservice pod, which runs Ruby on Rails using the Puma web server.

We used the internal IP to correlate the GitLab Pages requests with GitLab Workhorse containers. We looked at multiple requests and found that all the 502 requests had the following error attached to them: 502 Bad Gateway with dial tcp 127.0.0.1:8080: connect: connection refused. This means that GitLab Workhorse couldn't connect to the Puma web server. So we needed to go another layer deeper.

The Puma web server is what runs the Ruby on Rails monolith which has an internal API endpoint but Puma was never getting these requests since it wasn't running. What this tells us is that Kubernetes kept our pod in the service even when Puma wasn't responding, despite having readiness probes configured.

Below is the request flow between GitLab Pages, GitLab Workhorse, and Puma/Webservice to try and make it more clear:

Attempt 1: Red herring

We shifted our focus on GitLab Workhorse and Puma to try and understand how GitLab Workhorse was returning 502 errors in the first place. We found some 502 Bad Gateway with dial tcp 127.0.0.1:8080: connect: connection refused errors during container startup time. How could this be? With the readiness probe, the pod shouldn't be added to the Endpoint until all readiness probes pass. We later found out that it's because of a polling mechanisim that we have for Geo which runs in the background, using a Goroutine in GitLab Workhorse, and pings Puma for Geo information. We don't have Geo enabled on GitLab.com so we simply disabled it to reduce the noise.

We removed the 502 errors, but not the ones we want, just a red herring.

Attempt 2: Close but not quite

At this time, we were still burning through our SLO from time to time, so this was still an urgent thing that we needed to fix. Now that we had cleaner logs for 502 errors it started to become a bit clearer that this is happening on pod termination:

2022-04-05 06:03:49.000 UTC: Readiness probe failed
2022-04-05 06:03:51.000 UTC: Puma (127.0.0.1:8080) started shutdown.
2022-04-05 06:04:04.526 UTC: Puma shutdown finished.
2022-04-05 06:04:04.000 UTC - 2022-04-05 06:04:46.000 UTC: workhorse started serving 502 constantly.  42 seconds of serving 502 requests for any request that comes in apart from /api/v4/jobs/request

In the timeline shown above, we see that we've kept serving requests well after our Puma/webservice container exited, and the first readiness probe failed. If we look at the readiness probes we had on that pod we see the following:

$ kubectl -n gitlab get po gitlab-webservice-api-785cb54bbd-xpln2 -o jsonpath='{range .spec.containers[*]} {@.name}{":\n\tliveness:"} {@.livenessProbe} {"\n\treadiness:"} {@.readinessProbe} {"\n"} {end}'
 webservice:
        liveness: {"failureThreshold":3,"httpGet":{"path":"/-/liveness","port":8080,"scheme":"HTTP"},"initialDelaySeconds":20,"periodSeconds":60,"successThreshold":1,"timeoutSeconds":30}
        readiness: {"failureThreshold":3,"httpGet":{"path":"/-/readiness","port":8080,"scheme":"HTTP"},"initialDelaySeconds":60,"periodSeconds":10,"successThreshold":1,"timeoutSeconds":2}
  gitlab-workhorse:
        liveness: {"exec":{"command":["/scripts/healthcheck"]},"failureThreshold":3,"initialDelaySeconds":20,"periodSeconds":60,"successThreshold":1,"timeoutSeconds":30}
        readiness: {"exec":{"command":["/scripts/healthcheck"]},"failureThreshold":3,"periodSeconds":10,"successThreshold":1,"timeoutSeconds":2}

This meant that for the webservice pod to be marked unhealthy and removed from the endpoints, Kubernetes had to get 3 consecutive failures with an interval of 10 seconds, so in total that's 30 seconds. That seems a bit slow.

Our next logical step was to reduce the periodSeconds for the readiness probe for the webservice pod so we don't wait 30 seconds before removing the pod from the service when it becomes unhealthy.

Before doing so we had to understand if sending more requests to /-/readiness endpoint would have any knock-on effect with using more memory or anything else. We had to understand what the /-/readiness endpoint was doing and if it was safe to increase the frequency at which we send requests. We decided it was safe, and after enabling it on staging, and canary we didn't see any increase in CPU/Memory usage, as expected, and saw an improvement in the removal of 502 errors, which made us more confident that this was the issue. We rolled this out to production with high hopes.

As usual, Production is a different story than Staging or Canary, and it showed that it didn't remove all the 502 errors, just enough to stop triggering the SLO every day, but at least we removed the alert fatigue on the SRE on call. We were close, but not quite.

Attempt 3: All gone!

At this point, we were a bit lost and weren't sure what to look at next. We had a bit of tunnel vision and kept focusing/blaming that we aren't removing the Pod from the Endpoint quickly enough. We even looked at Google Cloud Platform NEGs to see if we could have faster readiness probes and remove the pod quicker. However, this wasn't ideal because we wouldn't have solved this for our self-hosting customers which seem to be facing the same problem.

While researching we also came across a known problem with running Puma in Kubernetes, and thought that might be the solution. However, we already implemented a blackout window just for this specific reason, so it couldn't be that either...in other words, it was another dead end.

We took a step back and looked at the timelines one more time and then it hit us. The Puma/webservice container is terminating within a few seconds, but the GitLab Workhorse one is always taking 30 seconds. Is it because of the long polling from GitLab Runner? 30 seconds is a "special" number for Kubernetes pod termination. When Kubernetes deletes a pod it firsts sends the TERM signal to the container and waits 30 seconds, if the container hasn't exited yet, it will send a KILL signal. This indicated that maybe GitLab Workhorse was never shutting down and Kubernetes had to kill it.

Once more we looked at GitLab Workhorse source code and searched for the SIGTERM usage and it did seem to support graceful termination and it also had explicit logic about long polling requests, so is this just another dead end? Luckily when the TERM signal is sent, Workhorse logs a message that it's shutting down. We looked at our logs for this specific message and didn't see anything. Is this it? We aren't gracefully shutting down? But how? Why does it result in 502 errors? Why do the GitLab Pages keep using the same pod that is terminating?

We know that the TERM signal is being sent to PID 1 inside of the container, and that process should handle the TERM signal for graceful shutdown. We looked at the GitLab Workhorse process tree and this is what we found:

git@gitlab-webservice-default-5d85b6854c-sbx2z:/$ ps faux
USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root        1015  0.0  0.0 805036  4588 ?        Rsl  13:12   0:00 runc init
git         1005  0.3  0.0   5992  3784 pts/0    Ss   13:12   0:00 bash
git         1014  0.0  0.0   8592  3364 pts/0    R+   13:12   0:00  \_ ps faux
git            1  0.0  0.0   2420   532 ?        Ss   12:52   0:00 /bin/sh -c /scripts/start-workhorse
git           16  0.0  0.0   5728  3408 ?        S    12:52   0:00 /bin/bash /scripts/start-workhorse
git           19  0.0  0.3 1328480 33080 ?       Sl   12:52   0:00  \_ gitlab-workhorse -logFile stdout -logFormat json -listenAddr 0.0.0.0:8181 -documentRoot /srv/gitlab/public -secretPath /etc/gitlab/gitlab-workhorse/secret -config /srv/gitlab/config/workhorse-config.toml

Bingo! gitlab-workhorse is PID 19 in this case, and a child process of a script that we invoke. Taking a close look at the script we check if it listens to TERM and it doesn't! So far everything indicated that GitLab Workhorse was never getting the TERM signal which ended up in receiving KILL after 30 seconds. We updated our scripts/start-workhorse to use exec(1) so that gitlab-workhorse replaced the PID of our bash script, that should have worked, right? When we tested this locally we then saw the following process tree.

git@gitlab-webservice-default-84c68fc9c9-xcsnm:/$ ps faux
USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
git          167  0.0  0.0   5992  3856 pts/0    Ss   14:27   0:00 bash
git          181  0.0  0.0   8592  3220 pts/0    R+   14:27   0:00  \_ ps faux
git            1  0.0  0.0   2420   520 ?        Ss   14:24   0:00 /bin/sh -c /scripts/start-workhorse
git           17  0.0  0.3 1328228 32800 ?       Sl   14:24   0:00 gitlab-workhorse -logFile stdout -logFormat json -listenAddr 0.0.0.0:8181 -documentRoot /srv/gitlab/public -secretPath /etc/gitlab/gitlab-workhorse/secret -config /srv/gitlab/config/workhorse-config.toml

This changed a bit: this shows that gitlab-workhorse was no longer a child process of /scripts/start-workhorse however /bin/sh was still PID 1. What is even invoking /bin/sh that we didn't see anywhere in our Dockerfile? After some thumb-twiddling, we had an idea that the container runtime is invoking /bin/sh. We went back to basics and looked at the CMD documentation to see if we were missing something, and we were. We read the following:

If you use the shell form of the CMD, then the will execute in /bin/sh -c:

FROM ubuntu
CMD echo "This is a test." | wc -

If you want to run your without a shell then you must express the command as a JSON array and give the full path to the executable. This array form is the preferred format of CMD. Any additional parameters must be individually expressed as strings in the array:

FROM ubuntu
CMD ["/usr/bin/wc","--help"]

This was exactly what we were doing! we weren't using CMD in exec form, but in shell form. Changing this confirmed that gitlab-workhorse is now PID 1, and also receives the termination signal after testing it locally:

git@gitlab-webservice-default-84c68fc9c9-lzwmp:/$ ps faux
USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
git           65  1.0  0.0   5992  3704 pts/0    Ss   15:25   0:00 bash
git           73  0.0  0.0   8592  3256 pts/0    R+   15:25   0:00  \_ ps faux
git            1  0.2  0.3 1328228 32288 ?       Ssl  15:24   0:00 gitlab-workhorse -logFile stdout -logFormat json -listenAddr 0.0.0.0:8181 -documentRoot /srv/gitlab/public -secretPath /etc/gitlab/gitlab-workhorse/secret -config /srv/gitlab/config/workhorse-config.toml

{"level":"info","msg":"shutdown initiated","shutdown_timeout_s":61,"signal":"terminated","time":"2022-04-13T15:27:57Z"}
{"level":"info","msg":"keywatcher: shutting down","time":"2022-04-13T15:27:57Z"}
{"error":null,"level":"fatal","msg":"shutting down","time":"2022-04-13T15:27:57Z"}

Ok, then we just needed to update exec and CMD [] and we would have been done, right? Almost. GitLab Workhorse proxies all of the requests for the API, Web, and Git requests so we couldn't just do a big change and expect that everything is going to be OK. We had to progressively roll this out to make sure we didn't break any existing working behavior since this affects all the requests we get to GitLab.com. To do this, we hid it behind a feature flag so GitLab Workhorse is only PID 1 when the GITLAB_WORKHORSE_EXEC environment variable is set. This allowed us to deploy the change and only enable it on a small part of our fleet to see if we see any problems. We were a bit more careful here and rolled it out zone by zone in Production since we run on 3 zones. When we rolled it out in the first zone we saw all 502 errors disappear! After fully rolling this out we see that the problem is fixed and it had no negative side effects. Hurray!

We still had one question unanswered, why were GitLab Pages still trying to use the same connection even after the Pod was removed from the Service because it was scheduled for deletion? When we looked at Go internals we see that Go reuses TCP connections if we close the body of the request. So even though it's not part of the Service we can still keep the TCP connection open and send requests – this explains why we kept seeing 502 on pod being terminated and always from the same GitLab Pages pod.

Now it's all gone!

More things that we can explore

1. We've made graceful termination for GitLab Workhorse as default.
2. Audit all of our Dockerfiles that use CMD command and fix them. We've found 10, and fixed all of them.
3. Better readiness Probe defaults for webservice pod.
4. Add linting for Dockerfiles.
5. See if any of our child processes need zombie process reaping.

Takeaways

1. We should always care about what is PID 1 in a container.
2. Always try and use CMD ["executable","param1","param2"] in your Dockerfile.
3. Pods are removed from the Service/Endpoint in async.
4. If you are on GKE NEGs might be better for readinessProbes.
5. By default, there is a 30 second grace period between the TERM signal and the KILL signal when Pods terminate. You can update the time between the signals terminationGracePeriodSeconds.
6. The Go http.Client will reuse the TCP connection if the body is closed which in this case made the issue worse.

Thank you to @igorwwwwwwwwwwwwwwwwwwww, @gsgl, @jarv, and @cmcfarland for helping me debug this problem!