A botnet summer story

Sixteen days, five wrong answers, and a default value that was set when people still used modems. This is what I did on my holiday in July 2020.

14 July

On vacation. Signals start appearing that something is off, and network duration is suddenly up. The chase begins.

15 July

First suspects are rogue crawlers. PetalBot and CXSense are all over the logs, which makes them look guilty. We ban them. Nothing changes.

NewRelic then points at an image resize script we use for social media sharing. That looks much more promising, so we spend a few days optimising it. At the end of it we have a considerably faster image resize script and exactly the same problem.

20 July

Now we suspect Redis is slowing down the infrastructure, and check whether we’ve hit the known bug caused by transparent huge pages. We haven’t.

Meanwhile the slowdowns turn up in other services as well, and the databases are getting overloaded too. The whole thing looks random, which makes it very hard to analyse.

24 July

Redis is cleared. We migrate to a clustered setup and the problem comes with us.

New suspect: the NewRelic plugin we’d installed not long before. The tool we were using to investigate becomes the thing we’re investigating.

27 July

I come back from what was technically a holiday and uninstall NewRelic. Things get better. I conclude that was it.

28 July

Things were not better. They were non-deterministic, which is a different thing and had been fooling me for two weeks.

Then I finally see the pattern. Every 40 minutes, between 10 and 11 in the morning and again between midnight and 1am, there’s a slowdown lasting about ten minutes. During the spikes there are long requests from a small set of Romanian IPs, hitting different pages in an order that doesn’t look like a person browsing. And it isn’t constant. It’s as if somebody is switching it on and off.

We already had a plan to move to Cloudflare. Now that I’m fairly sure the cause is external, I bring the plan forward and make what was a fairly risky move mid-incident, to get their protection and controls.

We move everything across, and nothing changes. Then I notice Bot Fight Mode is disabled by default. I turn it on, and once again the problem appears to be solved.

29 July

It isn’t solved. Cloudflare support tells me they can see something fishy happening to our site, but it sits comfortably below their threshold for automatic bot blocking.

That’s the part worth sitting with. Whoever was doing this had tuned it to stay under the line where anything automatic would react. Small enough to be ignored by the defences, large enough to hurt.

30 July

The answer is Apache, and specifically RequestReadTimeout from mod_reqtimeout. It controls how long the server will wait for a client to complete the TLS handshake, send its request headers, and send its body.

RequestReadTimeout handshake=5 header=10 body=30

In Apache 2.3.14 and earlier the directive defaults to disabled. So the server will wait, patiently and indefinitely, for a client that is sending its request very slowly. Open enough of those connections and hold them open and the server runs out of workers, without ever generating enough traffic to trip anything.

That default was reasonable once. When it was written, a client that took thirty seconds to send a request header was not an attacker, it was somebody on a modem. The generosity was for them.

No cliffhanger, sorry. The fix is to set the timeouts.