为何telnet到127.0.0.1会有5秒延迟?

最近在写一个简单的HTTP客户端/服务器端。在验证服务器端的时候,用到了telnet工具。但是在每次telnet连接的时候,都会有数秒的延迟。按说telnet连接到本地,不会有网络延迟存在。那这几秒的延迟出在哪个环节上呢?

我们可以借助strace来分析telnet背后的细节。这个工具能够追踪进程的一切系统调用。

strace用法如下,-tt选项能够显示毫秒精度的时间戳。

1strace -tt telnet 127.0.0.1 9000 >& /tmp/strace.log

检查log(相关片段如下所示),原来poll系统调用等待了5秒。往前看,有创建一个socket,然后连接到192.168.11.1的53端口。53端口是用来做DNS解析的,这里解析的对象是机器的hostname,vm-dev。但是这个IP根本不可达,所以poll只能干等,直到超时。

12345678910111221:21:16.032995 socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 321:21:16.033027 connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.11.1")}, 16) = 021:21:16.033066 gettimeofday({1488547276, 33072}, NULL) = 021:21:16.033085 poll([{fd=3, events=POLLOUT}], 1, 0) = 1 ([{fd=3, revents=POLLOUT}])21:21:16.033107 sendto(3, "\3655\1\0\0\1\0\0\0\0\0\0\6vm-dev\0\0\1\0\1", 24, MSG_NOSIGNAL, NULL, 0) = 2421:21:16.033201 poll([{fd=3, events=POLLIN|POLLOUT}], 1, 5000) = 1 ([{fd=3, revents=POLLOUT}])21:21:16.033226 sendto(3, "W-\1\0\0\1\0\0\0\0\0\0\6vm-dev\0\0\34\0\1", 24, MSG_NOSIGNAL, NULL, 0) = 2421:21:16.033275 gettimeofday({1488547276, 33284}, NULL) = 021:21:16.033295 poll([{fd=3, events=POLLIN}], 1, 4999) = 0 (Timeout)21:21:21.037931 socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 421:21:21.037995 connect(4, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.4.4")}, 16) = 0I

这里有两个问题,我用telnet连接到127.0.0.1,为什么要解析客户机的hostname?那个192.168.11.1的DNS地址哪里来的?

Linux的DNS服务器地址存放在 /etc/resolv.conf 中,strace抓到的系统调用log也能看到读取这个文件的记录。在这个文件里面确实找到了上面见到的IP地址,192.168.11.1。这个Linux系统跑在虚拟机里面,宿主系统是OS X。前一段时间我曾经给OS X系统配置过DNS地址,就是上面的IP地址。看样子虚拟机也把这个配置拿进来用了。不过最近局域网的网段改了,那个DNS地址却没记得删掉。现在那个地址自然是不可达的。

那还剩下一个关键问题,telnet为什么要解析系统的hostname?没办法,只能从telnet的源代码入手了。把gdb叫过来,安装需要的debug模块,在5秒延迟的时候敲CTRL+C暂停telnet进程,检查进程的调用栈。调用栈长这样,

1234567#8 0x00007ffff76dff30 in getaddrinfo (name=0x7fffffffe0f0 "vm-dev", service=, hints=0x7fffffffe0b0, pai=0x7fffffffe0e0) at ../sysdeps/posix/getaddrinfo.c:2385#9 0x00007ffff7ff0def in env_init () at commands.c:1676#10 0x00007ffff7ff7439 in init_telnet () at telnet.c:145#11 0x00007ffff7ff1bc3 in tninit () at main.c:68#12 0x00007ffff7ff1be8 in main (argc=3, argv=0x7fffffffe2e8) at main.c:123

调用栈中的getaddrinfo函数就是用来做DNS解析的。这跟strace观察到的结果一致。用list看一下commands.c:1676的源代码。原来telnet为了给某个环境变量DISPLAY赋值,尝试着获取一个更规范的系统hostname(按照源码,hostname里面要有.字符),也就是DNS解析结果的cname字段。

按照telnet的rfc描述,DISPLAY环境变量的用处和格式如下。

12345DISPLAY This variable is used to transmit the X display location of the client. The format for the value of the DISPLAY variable is: :[.]

至此,5秒的延迟算是水落石出了。解决这个问题很简单,删掉那个不可达的DNS地址就行了。

这个问题也很容易重现。步骤如下,

启动httpd服务,sudo service httpd start

修改/etc/resolv.conf文件,最开始加上nameserver 192.168.11.1

telnet 127.0.0.1 80,就可以重现了。

记得把/etc/resolv.conf改回去。:-p