This blog post was originally published on the GitLab Unfiltered blog. It was reviewed and republished on 2019-12-03.
What began as failure in a GitLab static analysis check led to a
dizzying investigation that uncovered a subtle bug in the Docker client
library code used by
the GitLab Runner. We ultimately worked around the problem by upgrading
the Go compiler, but in the process we uncovered an unexpected change in
the Go TCP keepalive defaults that fixed an issue with Docker and GitLab
CI.
This investigation started on October 23, when backend engineer Luke
Duncalfe mentioned, "I'm seeing
static-analysis failures with no output.
Is there something wrong with this job?" He opened a GitLab
issue to discuss.
When Luke ran the static analysis check locally on his laptop, he saw
useful debugging output when the test failed. For example, an extraneous
newline would accurately be reported by Rubocop. However, when the same
test ran in GitLab's automated test infrastructure, the test failed
quietly:
Notice how the job log did not include any clues after the bin/rake lint:all step. This made it difficult to determine whether a real
problem existed, or whether this was just a flaky test.
In the ensuing days, numerous team members reported the same problem.
Nothing kills productivity like silent test failures.
Was something wrong with the test itself?
In the past, we had seen that if that specific test generated enough
errors, the output buffer would fill up, and the continuous integration
(CI) job would lock
indefinitely. We
thought we had fixed that issue months
ago. Upon
further review, that fix seemed to eliminate any chance of a thread
deadlock.
Did we have to flush the buffer? No, because the Linux kernel will do
that for an exiting process already.
Was there a change in how CI logs were handled?
When a test runs in GitLab CI, the GitLab
Runner launches a Docker
container that runs commands specified by a .gitlab-ci.yml inside the
project repository. As the job runs, the runner streams the output to
the GitLab API via PATCH requests. The GitLab backend saves this data
into a file. The following sequence diagram shows how this works:
== Get a job! ==
Runner -> GitLab: POST /api/v4/jobs/request
GitLab -> Runner: 201 Job was scheduled
== Job sends logs (1 of 2) ==
Runner -> GitLab: PATCH /api/v4/job/:id/trace
GitLab -> File: Save to disk
GitLab -> Runner: 202 Accepted
== Job sends logs (2 of 2) ==
Runner -> GitLab: PATCH /api/v4/job/:id/trace
GitLab -> File: Save to disk
GitLab -> Runner: 202 Accepted
Henrich Lee Yu mentioned
that we had recently disabled a feature flag that changed how GitLab
handled CI job
logs. The
timing seemed to line
up.
This feature, called live CI traces, eliminates the need for a shared
POSIX filesystem (e.g., NFS) when saving job logs to disk by:
- Streaming data into memory via Redis
- Persisting the data in the database (PostgreSQL)
- Archiving the final data into object storage
When this flag is enabled, the flow of CI job logs looks something like
the following:
== Get a job! ==
Runner -> GitLab: POST /api/v4/jobs/request
GitLab -> Runner: 201 Job was scheduled
== Job sends logs ==
Runner -> GitLab: PATCH /api/v4/job/:id/trace
GitLab -> Redis: Save chunk
GitLab -> Runner: 202 Accepted
...
== Copy 128 KB chunks from Redis to database ==
GitLab -> Redis: GET gitlab:ci:trace:id:chunks:0
GitLab -> PostgreSQL: INSERT INTO ci_build_trace_chunks
...
== Job finishes ==
Runner -> GitLab: PUT /api/v4/job/:id
GitLab -> Runner: 200 Job was updated
== Archive trace to object storage ==
Looking at the flow diagram above, we see that this approach has more
steps. After receiving data from the runner, something could have gone
wrong with handling a chunk of data. However, we still had many
questions:
- Did the runners send the right data in the first place?
- Did GitLab drop a chunk of data somewhere?
- Did this new feature actually have anything to do with the problem?
- Are they really making another Gremlins movie?
Reproducing the bug: Simplify the .gitlab-ci.yml
To help answer those questions, we simplified the .gitlab-ci.yml to
run only the static-analysis step. We inserted a known Rubocop error,
replacing a eq with eql. We first ran this test on a separate GitLab
instance with a private runner. No luck there – the job showed the right
output:
Offenses:
ee/spec/models/project_spec.rb:55:42: C: RSpec/BeEql: Prefer be over eql.
expect(described_class.count).to eql(2)
^^^
12669 files inspected, 1 offense detected
However, we repeated the test on our staging server and found that we
reproduced the original problem. In addition, the live CI trace feature
flag had been activated on staging. Since the problem occurred with and
without the feature, we could eliminate that feature as a possible
cause.
Perhaps something with the GitLab server environment caused a
problem. For example, could the load balancers be rate-limiting the
runners? As an experiment, we pointed a private runner at the staging
server and re-ran the test. This time, it succeeded: the output was
shown. That seemed to suggest that the problem had more to do with the
runner than with the server.
Docker Machine vs. Docker
One key difference between the two tests: One runner used a shared,
autoscaled runner using a Docker
Machine executor, and the
private runner used a Docker
executor.
What does Docker Machine do exactly? The following diagram may help
illustrate:
The top-left shows a local Docker instance. When you run Docker from the
command-line interface (e.g., docker attach my-container), the program
just makes REST calls to the Docker Engine
API.
The rest of the diagram shows how Docker Machine fits into the
picture. Docker Machine is an entirely separate program. The GitLab
Runner shells out to docker-machine to create and destroy virtual
machines using cloud-specific (e.g. Amazon, Google, etc.) drivers. Once
a machine is running, the runner then uses the Docker Engine API to run,
watch, and stop containers.
Note that this API is used securely over an HTTPS connection. This is an
important difference between the Docker Machine executor and Docker
executor: The former needs to communicate across the network, while the
latter can either use a local TCP socket or UNIX domain socket.
Google Cloud Platform timeouts
We've known for a while that Google Cloud has a 10-minute idle
timeout,
which has caused issues in the past:
Note that idle connections are tracked for a maximum of 10 minutes,
after which their traffic is subject to firewall rules, including the
implied deny ingress rule. If your instance initiates or accepts
long-lived connections with an external host, you should adjust TCP
keep-alive settings on your Compute Engine instances to less than 600
seconds to ensure that connections are refreshed before the timeout
occurs.
Was the problem caused by this timeout? With the Docker Machine
executor, we found that we could reproduce the problem with a simple
.gitlab-ci.yml:
image: "busybox:latest"
test:
script:
- date
- sleep 601
- echo "Hello world!"
- date
- exit 1
This would reproduce the failure, where we would never see the Hello world! output. Changing the sleep 601 to sleep 599 would make the
problem go away. Hurrah! All we have to do is tweak the system TCP
keepalives, right? Google provided these sensible settings:
sudo /sbin/sysctl -w net.ipv4.tcp_keepalive_time=60 net.ipv4.tcp_keepalive_intvl=60 net.ipv4.tcp_keepalive_probes=5
However, enabling these kernel-level settings didn't solve the
problem. Were keepalives even being sent? Or was there some other issue?
We turned our attention to network traces.
Eavesdropping on Docker traffic
In order to understand what was happening, we needed to be able to
monitor the network communication between the runner and the Docker
container. But how exactly does the GitLab Runner stream data from a
Docker container to the GitLab server? The following diagram
illustrates the flow:
Runner -> Docker: POST /containers/name/attach
Docker -> Runner: <container output>
Docker -> Runner: <container output>
Runner -> GitLab: PATCH /api/v4/job/:id/trace
GitLab -> File: Save to disk
GitLab -> Runner: 202 Accepted
First, the runner makes a POST request to attach to the container
output.
As soon as a process running in the container outputs some data, Docker
will transmit the data over this HTTPS stream. The runner then copies
this data to GitLab via the PATCH request.
However, as mentioned earlier, traffic between a GitLab Runner and the
remote Docker machine is encrypted over HTTPS on port 2376. Was there an
easy way to disable HTTPS? Searching through the code of Docker Machine,
we found that it did not appear to be supported out of the box.
Since we couldn't disable HTTPS, we had two ways to eavesdrop:
- Use a man-in-the-middle proxy (e.g. mitmproxy)
- Record the traffic and decrypt the traffic later using the private keys
Ok, let's be the man-in-the-middle!
The first seemed more straightforward, since we already had experience
doing this with the Docker
client.
However, after defining the proxy variables for GitLab
Runner,
we found we were only able to intercept the GitLab API calls with
mitmproxy. The Docker API calls still went directly to the remote
host. Something wasn't obeying the proxy configuration, but we didn't
investigate further. We tried the second approach.
Decrypting TLS data
To decrypt TLS data, we would need to obtain the encryption keys. Where
were these located for a newly-created system with docker-machine? It
turns out docker-machine worked in the following way:
- Call the Google Cloud API to create a new machine
- Create a
/root/.docker/machine/machines/:machine_namedirectory - Generate a new SSH keypair
- Install the SSH key on the server
- Generate a new TLS certificate and key
- Install and configure Docker on the newly-created machine with TLS certificates
As long as the machine runs, the directory will contain the information
needed to decode this traffic. We ran tcpdump and saved the private keys.
Our first attempt at decoding the traffic failed. Wireshark could not
decode the encrypted traffic, although general TCP traffic could still
be seen. Researching more, we found out why: If the encrypted traffic
used a Diffie-Hellman key
exchange,
having the private keys would not suffice! This is by design, a property
called perfect forward
secrecy.
To get around that limitation, we modified the GitLab Runner to disable
cipher suites that used the Diffie-Hellman key exchange:
diff --git a/vendor/github.com/docker/go-connections/tlsconfig/config_client_ciphers.go b/vendor/github.com/docker/go-connections/tlsconfig/config_client_ciphers.go
index 6b4c6a7c0..a3f86d756 100644
