警惕!Nginx ingress就这么挂了

背景描述

  当下越来越多的企业正在拥抱k8s,如笔者公司基本所有服务都已容器化部署。

  容器化场景下,ingress是一种通过http协议暴露k8s内部服务的api对象,也就是说ingress是k8s集群所有服务的访问入口。基于ingress的流量访问链路如下图所示:

  ingress解决方案不少,k8s默认推荐的是Nginx Ingress,这也是本篇文章的主角。

7.18 线上服务504

  7.18号晚上21点左右,笔者正在小区楼下跳绳(中年码农大肚子危机),看到工作群反馈有业务晚上19点左右出现大量504。业务同学和SRE进行了初步排查分析,19点左右业务有发版,发现问题后也执行了回滚操作;排查发现Nginx ingress转发请求到了不存在的pod IP。难道是Nginx ingress同步上游节点IP有异常,期间也重启了上游服务,问题未解决,19点30分左右,业务恢复。

  查询Nginx ingress访问日志,18点49分业务开始出现504,请求响应时间5秒(proxy_connect_timeout 5s),Nginx ingress返回504。另外,18点49分之前(HTTP 200)请求的上游服务IP,与18点49分之后(HTTP 504)请求的上游IP相同。

  18点49分业务服务出现异常了?容器同学查询监控发现,该服务在18点49分重新调度了,也就是说,18点49分上游服务的IP已经变了,老的IP地址不可访问了,所以服务才出现504。

  kibana查询7.18号19点左右访问日志,发现不止这一个服务504,还有一个服务也出现大量504,而且现象完全一致。两个服务都是19:31分左右恢复。

  pod已重新调度,Nginx ingress为什么没有更新上游服务IP?

  查找线上环境nginx-ingress-controller日志,发现日志采集(多种日志格式采集到一个topic,解析时可能丢弃了部分日志)有些问题,kibana查询不到有效日志。排查陷入僵局。

7.19 Nginx ingress技术调研

  由于之前从来没有接触过Nginx ingress,也不了解其配置同步逻辑,7.19号决定简单研究下Nginx ingress底层原理,以备不时之需。

  github地址为 https://github.com/kubernetes... 。服务启动后,包含两个进程:1)nginx-ingress-controller进程基于Golang实现,负责监听k8s ingress资源,转换生成nginx.conf配置文件;2)nginx进程其实就是openresty,另外还基于lua提供本地接口,用于更新上游服务IP。

6 www-data 13h34 /nginx-ingress-controller --configmap=default/nginx-test-config --ingress-class=nginx-test
68 www-data 0:15 nginx: master process /usr/local/nginx/sbin/nginx -c /etc/nginx/nginx.conf

  nginx-ingress-controller同步的配置主要可以分为下面两类:

  • ingress规则,需要转化为server + location配置,而且需要注意的是,所有服务的ingress配置最终转换合并到一个配置文件nginx.conf,导致这个文件非常大,一般至少几十万行。另外,这类配置的变更是需要reload nginx进程的。
  • 上游服务IP,nginx-ingress-controller监听endpoints,并通过本地接口通知nginx进程,更新上游服务IP地址(http://127.0.0.1:10246/config...)。

  查看nginx.conf配置,configuration接口访问日志没有打开,无法确定当时nginx-ingress-controller有没有通过这个接口更新上游IP。

  另外由于日志采集问题,也无法查看nginx-ingress-controller日志,7.18号问题,只能靠猜测了。。。只是心里隐隐有点好奇,为什么两个服务都是在7.18号晚19:31恢复正常?那一时刻发生什么了?难道这起case是容器平台造成的?

7.21 测试环境502

  7.21号中午12点左右,测试容器平台和网关平台白屏,调试发现,前端某静态资源获取异常,前端伙伴排查修复。

  7.21号下午14:10分,反馈容器平台和网关平台前端所有接口请求全部502。kibana查询网关日志,发现全部是Nginx ingress返回502。

  502不是网关造成的,继续协助容器团队排查吧,毕竟网关团队在分析5xx问题是比较有经验的。登录测试环境Nginx ingress所在节点(还好之前排查问题申请过节点权限,而ingress访问日志kibana貌似没有采集),grep异常服务访问日志。

  7.21号下午15点左右,初步确定原因,与7.18号情况类似,Nginx ingress请求的上游服务IP是错误的。

//error日志如下
connect() failed (113: host is unreachable) while connecting to upstream, upstream: http://xxxx:80/
//access日志记录了上游服务的ingressName,serviceName
//查询上游服务endpoints
kubectl get endpoints xxxx -n xxxx

  上游服务的IP为什么又是错误的?nginx-ingress-controller配置同步有异常了?那好吧,重启下上游服务试试。

  重启了两次,还是没有恢复,502异常。

  7.21号下午15:10分左右,既然已经确定nginx-ingress-controller同步配置异常,要不重启下Nginx ingress?即使配置比较多,理论上分钟内也可以重建配置。(事后证明,理论果然只是理论)

  7.21号下午15:15分重启两个Nginx ingress节点,重启成功后,故障彻底扩散了,大量服务404。(PS 这时候还被业务方调侃了,经过两小时的努力,502变404了)

  404大概率是丢了配置,网关查询404域名,查看Nginx ingress配置文件nginx.conf,发现两个配置文件都丢失了部分域名配置。

  这些域名的ingress丢了?但是查询发现ingress正常啊,而且查看nginx-ingress-controller启动日志(记录所有资源变更事件),确实获取到了该域名的ingress,为什么会丢失配置呢?是不是重启异常了?要不然再重启一次。

  再看看Nginx ingress节点监控,发现一个节点负载非常高,难道是这个原因吗?

  时间已经到了下午16点多了,重启下Nginx ingress节点吧,数分钟后,节点重启成功,Nginx ingress服务重启成功。

  7.21号下午16:30分左右,业务基本恢复正常,但是还存在部分404请求,发现请求都是在另一个节点(未重启节点)上,网关修改upstream,摘掉该节点,业务完全恢复。

  一个下午就这么心惊胆战的度过了,而事故的原因依然未知。。。

7.22 深入分析

  7.21号测试环境故障依然是一个迷,事后想想和7.18线上问题非常类似。另外,为什么Nginx ingress重启会丢失大量配置呢?下次要再发生类似的问题怎办么?依然束手无策吗?

  只能再去深入研究nginx-ingress-controller配置同步逻辑了。

//ingress-nginx/internal/ingress/controller/controller.go
func (n *NGINXController) syncIngress(interface{}) error {
 //获取所有ingress规则
 ings := n.store.ListIngresses
 
 //配置转化,包括上游IP配置
 pcfg := n.getConfiguration(ings)
 
 if 非纯upstream节点变更 {
 klog.Infof("Configuration changes detected, backend reload required.")
 
 //更新nginx.conf
 if 更新失败 {
 klog.Errorf("Unexpected failure reloading the backend:\n%v", err)
 return err
 }
 klog.Infof("Backend successfully reloaded.")
 }
 
 //更新upstream节点配置(接口方式)
 if 更新失败 {
 klog.Warningf("Dynamic reconfiguration failed: %v", err)
 }
}

  同步配置都有记录详细的日志,7.21号测试环境可以查询日志,那一条一条日志搜索呗。此时也发现原来日志已采集,可以在kibana搜索。

  果然,搜索到了大量的"Configuration changes detected, backend reload required",然后搜索对应的"Backend successfully reloaded"却只有寥寥几条日志。那就是更新配置失败了,再搜索"Unexpected failure reloading the backend",果然有很多。但是这条日志后面的换行符是什么鬼,err关键词到底是什么,该怎么搜索。

  细化时间线,放宽筛选条件,一条一条日志找找看,果然,找到了对应的错误信息:

nginx: [emerg] "underscores_in_headers" directive is not allowed here in /tmp/nginx-cfg185859647:251712

  原来是nginx.conf语法错误,而且所有ingress配置会打包为一个配置文件,只要出现语法错误,那么所有后续所有ingress变更,以及upstream变更,都无法同步。

  这是什么配置,为什么会语法错误呢?看一下这个配置的官方说明,以及生成nginx.conf的模板:

Syntax: underscores_in_headers on | off;
Default: 
underscores_in_headers off;
Context: http, server
//只能配置在http以及server,不能配置在location
//模板
http {
 
 underscores_in_headers {{ if $cfg.EnableUnderscoresInHeaders }}on{{ else }}off{{ end }};
 
 //生成server配置
 {{ range $server := $servers }}
 server {
 
 }
 {{ end }}
}

  出问题的配置underscores_in_headers只在模板里http配置块有啊,只能是转化ingress生成server时引入的,而且一定是在location配置块引入的。

  更改nginx.conf配置还有两种方式:1)修改configmap,检查了下configma配置,没有异常,而且这个一般不会变更,暂时跳过;2)ingress变更引起,大概率就是了。

  那么到底是哪一个ingress引入的呢?按关键字"underscores_in_headers"搜索7.21号下午日志,突然发现在14点出问题之前,就有大量报错。扩大搜索时间范围,发现语法错误在7.21号11:57就出现了。

  既然确定了7.21号11:57第一次出现语法错误,而且这个语法错误肯定是ingress变更引起的,那么只需要查找ingress变更记录就行了。找一个测试服务,打开浏览器调试模式,提交ingress变更,抓到接口地址,kibana搜索11:57分左右的ingress变更日志。

  还真找到了,7.21号11:57分有业务编辑ingress,提交配置如下:

nginx.ingress.kubernetes.io/configuration-snippet":"underscores_in_headers on;"

  原来是通过注解方式引入的。查看官方文档对这个注解的解释:

//using this annotation you can add additional configuration to the NGINX location. For example:
yaml
nginx.ingress.kubernetes.io/configuration-snippet: |
 more_set_headers "Request-Id: $req_id";

  终于水落石出了,这个注解的配置会生成在location,而恰恰underscores_in_headers是不允许出现在location的!

  再扩大时间范围,搜索这个ingress的变更记录,7.21号下午16:30分变更,删掉了这个注解。原来如此,16:30分故障恢复也是一个巧合!至于16:30分后还出现部分404,是因为另一个节点没有重启,事件处理是有序串行的,之前处理异常的事件还在消费,即使不摘除过一会也会恢复的。

  至此,真相大白。

7.18 问题回顾

  7.21号问题算是搞清楚了。那么7.18号线上问题呢,是否也是如此?赶紧查询线上日志,不幸的是日志已经清除,kibana也查不到了。

  幸运的是,想起来机器上一般还会压缩存储钱前几天的日志。网关也就10个节点左右,一个节点一个节点登录看一下呗。这里查什么呢?依然是无法查询nginx-ingress-controller的日志,但是还记得不,7.18号晚31分两个服务同时恢复,那么如果问题同测试环境,一定是那一时刻ingress变更导致的恢复。

  历尽千山万水,终于找到了日志:

//2022-07-18T19:31:53+08:00,找到一条ingress变更记录;
//参照ingressName,查找7.18号19点之前变更历时
//2022-07-18T18:29:51+08:00
"nginx.ingress.kubernetes.io/proxy-next-upstream":"on"
Syntax: proxy_next_upstream error | timeout | invalid_header | http_500 | http_502 | http_503 | http_504 | http_403 | http_404 | http_429 | non_idempotent | off ...;
Default: 
proxy_next_upstream error timeout;
Context: http, server, location

  proxy_next_upstream配置的值不是简单的on!就是他导致的上游IP同步失败,而7.18号晚19点左右,恰好有两个服务重新调度了,IP改变了,所以才504。

  这么看来,7.21号测试环境问题也带来了正向收益,不然难以定位到7.18号线上问题的根本原因。而且这个问题还是个不定时炸弹,谁知道什么时候会再发生,下次发生又会引起多大故障!

反思总结

  • 理论果然只是理论,现实往往更残酷,理论上认为重启会重新构建配置,可以解决问题,但是重启却反而扩大了故障面;
  • 重启不能万能的,在重启之前要认真评估分析重启恢复的可能性;
  • 所有的开源组件,不能只是简单使用,平时应该积累,探究其底层原理,不然真正遇到问题将束手无策;特别是系统的核心依赖组件!
  • 核心系统/组件一定要有预案,分析可能出现的情况,提前制定一些止损手段,不然等故障发生了,干瞪眼吗?
  • 日志采集非常重要,遇到问题没有日志,难道靠猜吗?
  • 不要放过任何一个问题,7.18号线上问题,7.21号测试环境问题,如果没有排查出根因,谁知道什么时候会再次发生?下次会不会引起更大范围事故呢?

附录

作者:西红柿原文地址:https://segmentfault.com/a/1190000042215772

%s 个评论

要回复文章请先登录注册