乐趣区

关于nginx:警惕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 号测试环境问题,如果没有排查出根因,谁晓得什么时候会再次发生?下次会不会引起更大范畴事变呢?

附录

  • ingress:https://kubernetes.io/zh-cn/d…
  • Nginx ingress:https://github.com/kubernetes…
  • endpoints:https://kubernetes.io/zh-cn/d…
  • 官网文档:https://kubernetes.github.io/…
  • kubectl:https://kubernetes.io/zh-cn/d…
  • Nginx config:http://nginx.org/en/docs/diri…
退出移动版