golang dns 查询超时故障定位

曹东 · · 2458 次点击 · · 开始浏览    
这是一个创建于 的文章,其中的信息可能已经有所发展或是发生改变。

近来线上反向代理出现异常日志:lookup 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=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 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 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还存在较大的压力?果真如此,为啥只有有限的几个域名出现问题?

仓促写成,如有纰漏,欢迎指正!


有疑问加站长微信联系(非本文作者)

本文来自:知乎专栏

感谢作者:曹东

查看原文:golang dns 查询超时故障定位

入群交流(和以上内容无关):加入Go大咖交流群,或添加微信:liuxiaoyan-s 备注:入群;或加QQ群:692541889

2458 次点击  
加入收藏 微博
暂无回复
添加一条新回复 (您需要 登录 后才能回复 没有账号 ?)
  • 请尽量让自己的回复能够对别人有帮助
  • 支持 Markdown 格式, **粗体**、~~删除线~~、`单行代码`
  • 支持 @ 本站用户;支持表情(输入 : 提示),见 Emoji cheat sheet
  • 图片支持拖拽、截图粘贴等方式上传