背景形容

  当下越来越多的企业正在拥抱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-test68 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//查问上游服务endpointskubectl 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.gofunc (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:yamlnginx.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...