One with a Shrinking Black Box

- 5 mins read time
Tags: debugging Ruby docker

I joined a task force debugging mysterious test failures, and the problem looked like a black box to me. Instead of a familiar test failure, the only thing we knew was that we had some issues with CI infrastructure. Infrastructure… it sounded vague, magical, and impenetrable.

Image by Markus Distelrath from Pixabay

I was a bit lost, but had to start somewhere, so I checked the build logs:

16:48:07  Pushing schemas...
16:48:07  Failed to open TCP connection to graphql-gateway:5000 (getaddrinfo: Name or service not known) (Faraday::ConnectionFailed)
16:48:07  /usr/share/ruby/net/http.rb:949:in `rescue in block in connect'
16:48:07  /usr/share/ruby/net/http.rb:946:in `block in connect'
16:48:07  /usr/share/ruby/timeout.rb:93:in `block in timeout'
16:48:07  /usr/share/ruby/timeout.rb:103:in `timeout'
16:48:07  /usr/share/ruby/net/http.rb:945:in `connect'
16:48:07  /usr/share/ruby/net/http.rb:930:in `do_start'
16:48:07  /usr/share/ruby/net/http.rb:919:in `start'

16:48:07  /home/containeruser/.bundle/ruby/2.6.0/gems/headless-2.3.1/lib/headless.rb:251:in `exit': exit (SystemExit)

I learnt that we have a Ruby script setting up the infrastructure! I checked the part of the script that was failing:

def upload_and_activate_schemas(schema)
  post(Settings.graphql_gateway.url, body: schema) # <<<< error is raised here
	# ... activate
end

I was still in the dark, but at least I noticed that the issue happened when we were pushing GraphQL schemas to the gateway and that the failure occurred while opening a TCP connection.

That was something!

I thought that maybe the payload of the HTTP POST was so large that I was getting a timeout while trying to send it. (Oh, how wrong I was, but who hasn’t been wrong when poking a black box?) So I decided to stick a wrench into the mechanism and log a bit more:

def upload_and_activate_schemas
  puts "====checking: #{ping(Settings.graphql_gateway.url)}"
  post(Settings.graphql_gateway.url, body: schema) # <<<< error is raised here
end

def ping(url)
  response = Faraday.head(url)
  response.status
end

Of course I didn’t fix anything, but at least I got… a new error:

====checking: 404
Net::ReadTimeout (Net::ReadTimeout)

First there was a 404, but on a retry it raised a ReadTimeout. Weird. Two different errors, both different from the previous one (Failed to open TCP connection). The black box was still mysterious but at least I started understanding its shape.

I buried myself in a library to brush up on TCP failure modes, trying to remember long-forgotten knowledge from university courses. I relearnt that a Read Timeout is different from an Open Timeout. An Open Timeout is raised when a TCP connection cannot be initiated. A Read Timeout means that the TCP handshake was successful, but we were waiting too long for the other party to start writing. I realised that I had been wrong – the gateway container was running! It was started, and then, for some reason, it couldn’t respond. I started generating new working hypotheses: maybe it was busy garbage collecting? Maybe something was eating up the whole CPU?

I didn’t know how to check it (I would now), so I spent more time in “library” mode, googling weirder and weirder phrases. Until I finally found something similar:

Log output of a postgres container stops after running for a while which is causing subsequent database queries to hang due to failing to write to stderr.

One of the comments said:

As far as I can tell, docker-compose always attaches to all started containers, but only reads the logs from those configured by the user (the main service when using docker-compose run). This likely builds up backpressure for all other containers as their output buffers fill, but are never drained, because no log readers are set up by compose. Eventually, this backpressure causes the docker engine to stop processing the containers’ stdout/stderr. That’s why I see the issue with docker-compose run and docker-compose up, but not with docker-compose up -d, because it immediately detaches.

The issue was fixed in a newer version of Docker Compose, so I could just upgrade it. Or rather just write a ticket for our CI infra team, wait until it’s scheduled and see if my wild guess was right. Kind of a long process for verifying a hypothesis, so I went a different way.

I noticed that the container logs were flooded with heartbeat requests, so I made a small and safe change: I stopped logging the heartbeat.

And the issue disappeared.

With my hypothesis confirmed, I was armed to write a well-founded ticket asking for an upgrade to docker-compose. But what was more important – I stopped the bleeding, so the upgrade was no longer urgently needed. The box was very small, manageable, and no longer black!

At the beginning, the problem was a huge black box named “CI Infrastructure”. I started poking it by adding simple changes to the infra code, and it revealed some of its secrets. When this path stopped getting me any further, I buried myself in the documentation –I built a mental model of how it works and why it could break. This made the black box even smaller. I understood the problem better. Finally, I got to one small hypothesis to verify and with a simple test, I revealed the missing piece of the mystery.

And that’s the learning – when a bug occurs, its surroundings may be totally opaque. It’s OK not to understand the whole system when you start debugging. You can make the unknown smaller by balancing theory with experiments.

One experiment at a time, the black box shrinks a bit.