traefik 的离奇 502 排除和优化

我是 LEE，老李，一个在 IT 行业摸爬滚打 16 年的技术老兵。

事件背景

公司前一段时间完成了 Thanos 向 VictoriaMetrics 的整体迁移，现在 VictoriaMetrics 作为我们主要容器系统数据收集和保存的支撑系统，当然也围绕着 VictoriaMetrics 做很多定制化开发。

最近有研发反应有部分监控自省程序出现了访问不同容器集群中的 VMSelect 读取数据时候，随机出现返回 502 的情况，这个已经影响到了正常的监控数据抽取和数据分析，实际对整体监控的准确性带来严重的影响，自此我决定出动，解决这个问题。

现象获取

通过整个业务流程图中可能导致 502 的节点，我们都投入的时间逐一查询日志和记录，然后通过时间轴比对，我们发现真正可能出现 502 的问题出现在了 Traefik 和 VMSelect 之间。 这个让我们非常疑惑，为什么 Traefik 和 VMSelect 都在同一个集群内部，属于内网转发，不应该出现这样的问题。

• 流程图

  Client ---> 内部网络 ---> CLB ---> Traefik ---> VMSelect

• traefik 日志

  

  traefik 502 日志

• traefik 故障日志

  {
      "ClientPort": "46735",
      "StartLocal": "2022-07-20T04:54:14.992323307Z",
      "entryPointName": "web",
      "request_User-Agent": "Go-http-client/1.1",
      "StartUTC": "2022-07-20T04:54:14.992323307Z",
      "OriginDuration": 12322022,
      "RequestProtocol": "HTTP/1.1",
      "ClientAddr": "10.11.96.50:46735",
      "msg": "",
      "Overhead": 143008,
      "RequestMethod": "POST",
      "ClientHost": "10.24.18.40, 10.24.18.40",
      "time": "2022-07-20T04:54:15Z",
      "RequestScheme": "http",
      "OriginStatus": 502,
      "request_X-Forwarded-For": "10.24.18.40, 10.24.18.40",
      "RequestContentSize": 0,
      "ServiceURL": {
          "RawPath": "",
          "RawQuery": "",
          "Host": "10.252.28.229:8481",
          "Fragment": "",
          "Opaque": "",
          "Scheme": "http",
          "ForceQuery": false,
          "RawFragment": "",
          "Path": ""
      },
      "DownstreamContentSize": 11,
      "Duration": 12465030,
      "request_Globalticket": "28838-1658292854.993-ops-q1-463-1341541174",
      "request_X-Real-Ip": "10.11.96.50",
      "level": "info",
      "DownstreamStatus": 502,
      "RetryAttempts": 0,
      "ServiceName": "victoria-vmselect-victoria-metrics-k8s-stack-8481@kubernetes",
      "RequestPath": "/select/0/prometheus/api/v1/query_range",
      "RequestPort": "80",
      "OriginContentSize": 11,
      "RequestCount": 23219174,
      "ServiceAddr": "10.252.28.229:8481"
  }
  

原理分析

在定位 Traefik 和 VMSelect 之间 存在问题的时候，我们仍然在后端 VMSelect 里检查日志，没有看到对应的请求，确认请求没有到 VMSelect 的节点上，那么做实了可能 502 的情况。

同时我们也仔细检查了 Traefik 的日志，我们发现一个奇怪的问题：假设发生了 502 的问题，就是后面没有可用的节点，那么在 Traefik 日志中为什么会出现 DownstreamStatus 和 OriginStatus 两者字段都是 502 的情况。

按照 Traefik 官方的解释 OriginStatus 代表的是后端的服务器返回的状态代码，在没有后端的情况下这个 OriginStatus 值怎么来的。带着这个疑问我继续回去看 Traefik 的源代码，希望能够找到这个太能解释的原因。

https://doc.traefik.io/traefik/observability/access-logs/#limiting-the-fieldsincluding-headers

果真功夫不符有心人，我们找到了对应的代码，以及可能存在的问题。

func buildProxy(passHostHeader *bool, responseForwarding *dynamic.ResponseForwarding, roundTripper http.RoundTripper, bufferPool httputil.BufferPool) (http.Handler, error) {

        ...

        Transport:     roundTripper,
        FlushInterval: time.Duration(flushInterval),
        BufferPool:    bufferPool,
        ErrorHandler: func(w http.ResponseWriter, request *http.Request, err error) {
            statusCode := http.StatusInternalServerError

            switch {
            case errors.Is(err, io.EOF):   // tcp io 流终端，无法连接到后端服务器，判断为 502 正常
                statusCode = http.StatusBadGateway
            case errors.Is(err, context.Canceled):
                statusCode = StatusClientClosedRequest
            default:
                var netErr net.Error
                if errors.As(err, &netErr) {  // 获得 net 包在网络中的所有错误
                    if netErr.Timeout() {  // 判断是否是连接超时（traefik --> upstream server）
                        statusCode = http.StatusGatewayTimeout
                    } else {
                        statusCode = http.StatusBadGateway  // 除了超时，都是 502 错误。这里太鲁莽了
                    }
                }
            }

            log.Debugf("'%d %s' caused by: %v", statusCode, statusText(statusCode), err) // debug 才会输出
            w.WriteHeader(statusCode)
            _, werr := w.Write([]byte(statusText(statusCode)))
            if werr != nil {
                log.Debugf("Error while writing status code", werr)
            }
        },
    }

    return proxy, nil
}

通过对代码的分析，我觉得问题就出现在这一段代码上。 这段代码的意思是在构建 http 转发模型的时候，构建一个 ErrorHandler 处理方法，告诉 Middleware 中的 ServeHTTP 这个方法，如果出现异常就使用 ErrorHandler 来处理不可控的场景。

既然如此，我作为底层平台的维护和设计者，有必要了解当出现了 502 的时候，是具体时间点，什么会话，什么原因导致的问题。不光我，还有很多研发和运维也都希望知道。

处理方法

当然有心的小伙伴通过对上面的代码阅读已经发现了一个地方是可以解决问题的，就是下面这个 console 输出。

log.Debugf("'%d %s' caused by: %v", statusCode, statusText(statusCode), err) // debug 才会输出

知道了原因，知道了逻辑，那顺理成章的就有了解决方案：

1. 调整日志输出等级，因为 Traefik 本身输出日志就回降低系统性能，全面打开 debug 等级的日志更加不合理。
2. 丰富输出的内容，不光要知道 502 的状态码，错误信息，我们还要知道对应的请求会话的相关的 Metadata, 这样也能方便排查

我这边做了如下的修改，当然其他的小伙伴可以根据需要自己添加，我这边主要是辅助 502 的定位

log.Warnf("'%d %s' caused by: %v, request_host: %s, request_url: %s, client_addr: %s, ", statusCode, statusText(statusCode), err, request.Host, request.URL.Path, request.RemoteAddr)

这里输出了 502 的错误原因，相关出现 502 的请求会话的 URL，域名，以及对端地址

有了这些输出，我们就不怕后面出现异常的时候，因为我们没有数据支撑，导致我们不能够对当时的情景复现。

最终效果

这里我演示几条输出的日志效果

# tcp io 流终端，无法连接到后端服务器，判断为 502 正常
'502 Bad Gateway' caused by: EOF

# 除了超时，都是 502 的情况
'502 Bad Gateway' caused by: dial tcp 172.18.0.4:4000: connect: connection refused, request_host: victoria-vmselect-victoria-metrics-k8s-stack.xxxx.com, request_url: /select/0/prometheus/api/v1/query_range, client_addr: 10.24.18.40,