mediocre-blog/_posts/2015-03-11-rabbit-hole.md

---
title: Rabbit Hole
description: >-
    Complex systems sometimes require complex debugging.
---

We've begun rolling out [SkyDNS][skydns] at my job, which has been pretty neat.
We're basing a couple future projects around being able to use it, and it's made
dynamic configuration and service discovery nice and easy.

This post chronicles catching a bug because of our switch to SkyDNS, and how we
discover its root cause. I like to call these kinds of bugs "rabbit holes"; they
look shallow at first, but anytime you make a little progress forward a little
more is always required, until you discover the ending somewhere totally
unrelated to the start.

## The Bug

We are seeing *tons* of these in the SkyDNS log:

```
[skydns] Feb 20 17:21:15.168 INFO      | no nameservers defined or name too short, can not forward
```

I fire up tcpdump to see if I can see anything interesting, and sure enough run
across a bunch of these:

```
# tcpdump -vvv -s 0 -l -n port 53
tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 65535 bytes
    ...
    $fen_ip.50257 > $skydns_ip.domain: [udp sum ok] 16218+ A? unknown. (25)
    $fen_ip.27372 > $skydns_ip.domain: [udp sum ok] 16218+ A? unknown. (25)
    $fen_ip.35634 > $skydns_ip.domain: [udp sum ok] 59227+ A? unknown. (25)
    $fen_ip.64363 > $skydns_ip.domain: [udp sum ok] 59227+ A? unknown. (25)
```

It appears that some of our front end nodes (FENs) are making tons of DNS
fequests trying to find the A record of `unknown`. Something on our FENs is
doing something insane and is breaking.

## The FENs

Hopping over to my favorite FEN we're able to see the packets in question
leaving on a tcpdump as well, but that's not helpful for finding the root cause.
We have lots of processes running on the FENs and any number of them could be
doing something crazy.

We fire up sysdig, which is similar to systemtap and strace in that it allows
you to hook into the kernel and view various kernel activites in real time, but
it's easier to use than both. The following command dumps all UDP packets being
sent and what process is sending them:

```
# sysdig fd.l4proto=udp
...
2528950 22:17:35.260606188 0 php-fpm (21477) < connect res=0 tuple=$fen_ip:61173->$skydns_ip:53
2528961 22:17:35.260611327 0 php-fpm (21477) > sendto fd=102(<4u>$fen_ip:61173->$skydns_ip:53) size=25 tuple=NULL
2528991 22:17:35.260631917 0 php-fpm (21477) < sendto res=25 data=.r...........unknown.....
2530470 22:17:35.261879032 0 php-fpm (21477) > ioctl fd=102(<4u>$fen_ip:61173->$skydns_ip:53) request=541B argument=7FFF82DC8728
2530472 22:17:35.261880574 0 php-fpm (21477) < ioctl res=0
2530474 22:17:35.261881226 0 php-fpm (21477) > recvfrom fd=102(<4u>$fen_ip:61173->$skydns_ip:53) size=1024
2530476 22:17:35.261883424 0 php-fpm (21477) < recvfrom res=25 data=.r...........unknown..... tuple=$skydns_ip:53->$fen_ip:61173
2530485 22:17:35.261888997 0 php-fpm (21477) > close fd=102(<4u>$fen_ip:61173->$skydns_ip:53)
2530488 22:17:35.261892626 0 php-fpm (21477) < close res=0
```

Aha! We can see php-fpm is requesting something over udp with the string
`unknown` in it. We've now narrowed down the guilty process, the rest should be
easy right?

## Which PHP?

Unfortunately we're a PHP shop; knowing that php-fpm is doing something on a FEN
narrows down the guilty codebase little. Taking the FEN out of our load-balancer
stops the requests for `unknown`, so we *can* say that it's some user-facing
code that is the culprit. Our setup on the FENs involves users hitting nginx
for static content and nginx proxying PHP requests back to php-fpm. Since all
our virtual domains are defined in nginx, we are able to do something horrible.

On the particular FEN we're on we make a guess about which virtual domain the
problem is likely coming from (our main app), and proxy all traffic from all
other domains to a different FEN. We still see requests for `unknown` leaving
the box, so we've narrowed the problem down a little more.

## The Despair

Nothing in our code is doing any direct DNS calls as far as we can find, and we
don't see any places PHP might be doing it for us. We have lots of PHP
extensions in place, all written in C and all black boxes; any of them could be
the culprit. Grepping through the likely candidates' source code for the string
`unknown` proves fruitless.

We try xdebug at this point. xdebug is a profiler for php which will create
cachegrind files for the running code. With cachegrind you can see every
function which was ever called, how long spent within each function, a full
call-graph, and lots more. Unfortunately xdebug outputs cachegrind files on a
per-php-fpm-process basis, and overwrites the previous file on each new request.
So xdebug is pretty much useless, since what is in the cachegrind file isn't
necessarily what spawned the DNS request.

## Gotcha (sorta)

We turn back to the tried and true method of dumping all the traffic using
tcpdump and perusing through that manually.

What we find is that nearly everytime there is a DNS request for `unknown`, if
we scroll up a bit there is (usually) a particular request to memcache. The
requested key is always in the style of `function-name:someid:otherstuff`. When
looking in the code around that function name we find this ominous looking call:

```php
$ipAddress = getIPAddress();
$geoipInfo = getCountryInfoFromIP($ipAddress);
```

This points us in the right direction. On a hunch we add some debug
logging to print out the `$ipAddress` variable, and sure enough it comes back as
`unknown`. AHA!

So what we surmise is happening is that for some reason our geoip extension,
which we use to get the location data of an IP address and which
`getCountryInfoFromIP` calls, is seeing something which is *not* an IP address
and trying to resolve it.

## Gotcha (for real)

So the question becomes: why are we getting the string `unknown` as an IP
address?

Adding some debug logging around the area we find before showed that
`$_SERVER['REMOTE_ADDR']`, which is the variable populated with the IP address
of the client, is sometimes `unknown`. We guess that this has something to do
with some magic we are doing on nginx's side to populate `REMOTE_ADDR` with the
real IP address of the client in the case of them going through a proxy.

Many proxies send along the header `X-Forwarded-For` to indicate the real IP of
the client they're proxying for, otherwise the server would only see the proxy's
IP. In our setup I decided that in those cases we should set the `REMOTE_ADDR`
to the real client IP so our application logic doesn't even have to worry about
it. There are a couple problems with this which render it a bad decision, one
being that if some misbahaving proxy was to, say, start sending
`X-Forwarded-For: unknown` then some written applications might mistake that to
mean the client's IP is `unknown`.

## The Fix

The fix here was two-fold:

1) We now always set `$_SERVER['REMOTE_ADDR']` to be the remote address of the
requests, regardless of if it's a proxy, and also send the application the
`X-Forwarded-For` header to do with as it pleases.

2) Inside our app we look at all the headers sent and do some processing to
decide what the actual client IP is. PHP can handle a lot more complex logic
than nginx can, so we can do things like check to make sure the IP is an IP, and
also that it's not some NAT'd internal ip, and so forth.

And that's it. From some weird log messages on our DNS servers to an nginx
mis-configuration on an almost unrelated set of servers, this is one of those
strange bugs that never has a nice solution and goes unsolved for a long time.
Spending the time to dive down the rabbit hole and find the answer is often
tedious, but also often very rewarding.

[skydns]: https://github.com/skynetservices/skydns