关于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…