golang dns 查询超时故障定位

近来线上反向代理出现异常日志：lookup http://xxx.xxx.com on 10.0.0.1:53: dial udp 10.0.0.1:53: i/o timeout，显然是dns查询超时导致。但问题是，golang中dial udp的操作只是单纯的创建epoll对象，并不存在真正的i/o操作，谈何超时一说？

既然如此，先尝试线下复现，再来定位。

运行环境

• CentOS release 6.4 (Final) 虚机
  
• go version go1.7 linux/amd64
  

模拟现场

代码地址
• 配置crontab任务。每分钟执行一次，每秒钟并发300次查询，每次任务执行5秒
• */1 * * * * cd /home/d.cao && ./dnsquery_cost -host=http://xxx.xxx.com -epoch=10 -batch=30 -duration=5 >> /home/d.cao/run.log 2>&1 &
  
• 并发数 = epoch * batch
• duration为持续时间，单位秒
• 一段时间后，日志中出现了：2017/06/23 15:20:08 lookup http://xxx.xxx.com on 10.0.0.1:53: dial udp 10.0.0.1:53: i/o timeout

实验结论

• 可以复现，排除偶然情况（udp丢包）
• 排除线上服务代码bug
• 猜测：1，库代码实现上的bug；2，机器运行环境问题

源码追溯

既然从简单的日志得不出更多的结论，那就源码追溯吧。

• 调用链
• - LookupHost(host string)
• -- goLookupHostOrder(ctx context.Context, name string, order hostLookupOrder) 【dns查询，golang有两个实现版本：1，cgo，glibc实现；2，纯go实现，默认情况。可以通过环境变量GODEBUG=

netdns=cgo进行切换

• 】
• --- tryOneName(ctx context.Context, cfg *dnsConfig, name string, qtype uint16)
• ---- exchange(ctx context.Context, server, name string, qtype uint16) 【in src/net/dnsclient_unix.go】

层级不深，exchange函数为dns查询的最终实现。

• 代码注释

• 问题定位

查看d.dialDNS和d.dnsRoundTrip的实现知晓，dial udp 10.0.0.1:53: i/o timeout 出现在dialDNS函数中，即确实在dial udp的时候超时了！如果我的超时时间设置在毫秒级，这个结论是可接收的，但超时时间长达10秒，这就不合理了。

回退到tryOneName函数，发现有一段重试逻辑，且超时设置在重试逻辑之前，而不是每次重试设置一个超时：

意味着：1，如果cfg.attempts大于1或cfg.servers数目大于1，tryOneName返回的错误都只是最终失败时的错误；2，如果第一次exchange调用超时后，剩下的尝试都将在d.dialDNS调用时立马返回，且error.Error()为“dial udp 10.0.0.x:53: i/o timeout”。

• 浮出水面
• linux下cfg表示/etc/resolv.conf配置文件的对象
• 其中servers对应nameserver（最多三台），attempts对应options中的attemtps字段，timeout对应options中的timeout字段
• attempts默认为2
• timeout默认为5（秒）
• 经查看，服务器上/etc/resolv.conf配置中，最后一台nameserver恰恰为10.0.0.1（共三台）；未设置options。
• 结论
• 由于golang库代码关于超时和重试逻辑的诡异实现（和glibc实现不符），导致打印出的异常日志并不是问题的症结所在，从而产生了误导。
• 真正导致查询超时，发生在读dns查询响应的时候
• 验证
• 编辑/etc/resolv.conf
• 只保留一台nameserver
• 添加options attempts:1
• 一会后，run.log中果然出现了“2017/06/23 19:26:26 lookup http://xxx.xxx.com on 10.0.0.1:53: read udp 10.0.0.1:49757->10.0.0.1:53: i/o timeout”。读udp超时！！！符合预期。

解决方案

• dns server排查问题，给出解决方案
• dns client缓存
• 其实，我们机器上使用了dnsmasq（详情请点击连接跳转）做dns缓存，因此我们先看看如何很tricky的修复问题吧。
• 在追溯源码的时候，注意到函数hostLookupOrder，这个函数决定了DNS查询的顺序逻辑。linux下有一个/etc/hosts文件，是一个域名静态映射，hostLookupOrder决定了hosts文件查询与否和先后顺序。
• fix方法：调整golang dns查询的默认顺序。优先进行dns查询，当dns查询失败后，再进行hosts匹配
• 具体操作：1，在/etc/hosts中添加想要兜底的域名和对应的静态ip；2，修改/etc/nsswitch.conf中的hosts条目为“hosts: dns files”，即优先dns查询，后hosts文件查询

写在最后

虽然还未能定位出具体的read udp失败的原因，但经过上述tricky的操作后，线上dial udp i/o timeout的异常消失了。最后，遗留两点：1，golang库中关于超时和重试那块逻辑，很是困惑；2，在dnsmasq存在的情况下，dns server还存在较大的压力？果真如此，为啥只有有限的几个域名出现问题？

仓促写成，如有纰漏，欢迎指正！

---