1

I'm running a Debian-based VPS (Linux vps 2.6.32-042stab092.3 #1 SMP Sun Jul 20 13:27:24 MSK 2014 x86_64 GNU/Linux) which is behaving a bit strange. Whenever a new connection is established to it, it performs a PTR lookup.

I'm running some performance tests on it on port 80, where a Python script on a remote machine continuously fetches a page on the VPS. For every page request a new PTR lookup is being made, which ends up in thousands of active DNS requests.

I was monitoring this with tcpdump -n port not 22 and host not MY_REMOTE_IP. So -n is to prevent lookups.

I'm also monitoring with ntop, where -n is also used.

If I stop ntop and look at tcpdump, I get the lookups. If I stop tcpdump and start ntop, I also get them. So it might be fair to assume that none of them is causing the lookup.

There's also xinetd running in the background, which apparently also uses PTR lookups. But if I stop that service, the lookups still occur.

Then there's /usr/sbin/rsyslogd -c5, which, when getting killed, also doesn't change the situation.

Same goes for rabbitmq-server and erlangs epmd. authbind also doesn't seem to be responsible, and screen as well and stopping openvpn, which is usually running as a server, also makes no difference.

Wuaht on earth could be causing this?

Here's the process tree.

init
`- SCREEN -AmdS py-http authbind python server.py ---scr:py-http
|  `- python server.py ---scr:py-http
`- /sbin/getty 38400 tty2
`- /sbin/getty 38400 console
`- /bin/sh /usr/sbin/rabbitmq-server
|  `- /usr/lib/erlang/erts-5.9.1/bin/beam.smp -W w -K true -A30 -P 1048576 -- -root /usr/lib/erlang -progname erl -- -home /var/lib/rabbitmq -- -pa /us
t start_sasl -config /etc/rabbitmq/rabbitmq -kernel inet_default_connect_o
|     `- inet_gethost 4
|     |  `- inet_gethost 4
`- /usr/lib/erlang/erts-5.9.1/bin/epmd -daemon
`- /usr/sbin/ntop -d -L -u ntop -P /var/lib/ntop --access-log-file /var/log/ntop/access.log -i venet0:0 -p /etc/ntop/protocol.list -O /var/log/ntop
`- /usr/bin/mongod --config /etc/mongod.conf
`- /usr/sbin/cron
`- /usr/sbin/xinetd -pidfile /var/run/xinetd.pid -stayalive -inetd_compat -inetd_ipv6
`- /usr/sbin/sshd
|  `- sshd: user [priv]
|     `- sshd: user@pts/0
|        `- -bash
|           `- htop
`- sendmail: MTA: accepting connections
`- /usr/sbin/openvpn --writepid /var/run/openvpn.server.pid --daemon ovpn-server --cd /etc/openvpn --config /etc/openvpn/server.conf
`- /usr/sbin/saslauthd -a pam -c -m /var/run/saslauthd -n 2
|  `- /usr/sbin/saslauthd -a pam -c -m /var/run/saslauthd -n 2
`- /usr/sbin/rsyslogd -c5
`- upstart-socket-bridge --daemon
`- /sbin/udevd --daemon
|  `- /sbin/udevd --daemon
|  `- /sbin/udevd --daemon
`- upstart-udev-bridge --daemon

Update

This lookup occurs on every new connection, be it on port 80, or 22, any port, it doesn't matter which one.

Result from Strace for one HTTP request

sendto(10, "C~\1\0\0\1\0\0\0\0\0\0\0016\00270\003168\003192\7in-add"..., 43, MSG_NOSIGNAL, NULL, 0) = 43
print statement in server.py -> request #5 from client 192.168.70.6
sendto(10, "\23\372\1\0\0\1\0\0\0\0\0\0\0016\00270\003168\003192\7in-add"..., 43, MSG_NOSIGNAL, NULL, 0) = 43
sendto(9, "HTTP/1.1 200 OK\r\nDate: Fri, 24 O"..., 146, 0, NULL, 0) = 146

Sysdig cannot be used, as it's not possible to install it on the VPS

iptables logging results in the following entries: For new ssh connections:

Oct 24 06:06:11 vps kernel: [6547020.638594] DNS Traffic match:IN= OUT=venet0 SRC=VPS_IP_ADDRESS DST=8.8.8.8 LEN=99 TOS=0x00 PREC=0x00 TTL=64 ID=56490 DF PROTO=UDP SPT=50366 DPT=53 LEN=79 UID=0 GID=0

For new http connections:

Oct 24 06:06:53 vps kernel: [6547062.417763] DNS Traffic match:IN= OUT=venet0 SRC=VPS_IP_ADDRESS DST=8.8.8.8 LEN=71 TOS=0x00 PREC=0x00 TTL=64 ID=32702 DF PROTO=UDP SPT=59091 DPT=53 LEN=51 UID=1000 GID=1000

ss results in

ESTAB      0      0            VPS_IP_ADDRESS:42414         8888:53     users:(("python",2375,10))
3

First, I'll note that the invocation of ntop in the process tree you shared, doesn't seem to have the -n flag:

/usr/sbin/ntop -d -L -u ntop -P /var/lib/ntop --access-log-file /var/log/ntop/access.log -i venet0:0 -p /etc/ntop/protocol.list -O /var/log/ntop

but I assume given your statements about the queries continuing even with ntop killed, that it is not the issue. Further, to clarify, I am assuming that the machine doing the the lookups is the same machine handling the requests on port 80.

Given that, the following are some debugging ideas:

ss

If the program in question is keeping the socket around for a while, you can likely use ss (or netstat) with the -p flag to find the owner of the source port that you should be seeing in your tcpdumps.

Strace

The first suspect should be the application handling the requests. I'm assuming that the following python process running under screen is the application you are testing?

 `- SCREEN -AmdS py-http authbind python server.py ---scr:py-http
|  `- python server.py ---scr:py-http

You might consider running this process under strace and see if it is generating the DNS traffic. For instance something like:

strace -e trace=sendmsg,sendto -f YOUR_PROGRAM_HERE

and then carefully looking at the output for messages that look like they were sent to port 53:

[pid  3367] sendmsg(20, {msg_name(16)={sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.1.254")}, msg_iov(1)=[{"\31\322\1\0\0\1\0\0\0\0\0\0\0014\0014\0018\0018\7in-addr\4arp"..., 38}], msg_controllen=0, msg_flags=0}, 0) = 38

ss in a loop

If the program in question is quickly closing its socket, it may be hard to get information about it from ss or netstat.

However, one possibility us is to write a script that polls the ss command repeatedly. You would be betting on getting lucky enough to catch one of the lookups:

while true; do ss -p -n -u | tail -n +2; done

You can add a filter to the ss command to narrow it down if you see lots of other UDP traffic on that machine. Whether this works or not depends on you getting lucky.

Sysdig

You could use the relatively new sysdig utility to look at all sendmsg or sendto system calls:

sudo sysdig evt.type=sendmsg or evt.type=sendto | grep ':53'

And the output will have the process name (in this case nslookup):

47852 01:15:33.454946732 4 nslookup (3349) > sendmsg fd=20(<4>) size=38 tuple=0.0.0.0:49847->192.168.1.254:53

iptables

iptables allows you to log the userid of the process that generated the packet. If most of your services are running as the same user, this won't be too helpful, but it could be if you have service-specific users. A set of iptable rules as follows:

iptables -N LOGGING
iptables -A OUTPUT -p udp --dport 53 -j LOGGING
iptables -A LOGGING -j LOG --log-prefix="DNS Traffic match:" --log-uid

would log all outbound dns traffic with the associated UID. Depending on your logging setup, you could find this via kmesg or whever your syslog messages go and the output would look something like:

Oct 24 01:09:53 localhost.localdomain kernel: DNS Traffic match:IN= OUT=enp0s3 SRC=10.0.2.15 DST=192.168.1.254 LEN=66 TOS=0x00 PREC=0x00 TTL=64 ID=35264 PROTO=UDP SPT=51767 DPT=53 LEN=46 UID=1000 GID=1000

From this output I can see that the process in question had UID of 1000, which at least narrows my search.

  • Thanks, I've added the results to the question. In short: haven't been able to get to the ground of this issue. – Daniel F Oct 24 '14 at 4:21
  • 1
    Actually, it looks to me like you /have/ found the issue. When you connect over 22, SSH is likely doing the dns lookup, you can stop it by adding UseDns no to your sshd config and restarting the daemon. On 80, it looks like your python process is clearly doing the lookup. – Steven D Oct 24 '14 at 7:41
  • Looks like you're right. I forgot to mention that I had tried UseDNS no, but after seeing that it had no effect, judging from the lookups caused by Python, and not looking specifically for the ones caused by SSH, I thougt this had no effect, and commented it out. I now also noticed that RabbitMQ's Management console, HTTP based, doesn't cause the lookups. For SSH I'll be leaving it on, but now I know that I need to focus on Python. Apparently other ports than 22 and 80 were not affected. Thanks a lot for your help. – Daniel F Oct 24 '14 at 8:00
  • Found it. in Twisted, request.getClient() causes such a lookup. That's why I had two lookups in the Strace: one for the print statement, and one from the return value. In both cases the string would get formed by using that function. – Daniel F Oct 24 '14 at 8:08

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.