container kubernetes istio 微服务 mesh envoy

istio 数据面调试指南

Posted on February 12, 2020

1. 问题背景

这是使用 istio 最常见的困境：在微服务中引入 envoy 作为代理后，当流量访问和预期行为不符时，用户很难快速确定问题是出在哪个环节。客户端收到的异常响应，诸如 403、404、503 或者连接中断等，可能是链路中任一 sidecar 执行流量管控的结果， 但也有可能是来自某个服务的合理逻辑响应。

特别的，当 service mesh 系统的维护者和应用程序的开发者来自不同的团队时，问题尤为凸显。

在 mesh 中引入全链路跟踪系统，可以解决部分问题，我们可以知道请求到达了哪些工作负载，但是对于中断的异常请求，我们仍然很难确定原因。 因为本着最大透明化（Maximize Transparency）的设计目标，istio 的遥测系统会尽量屏蔽掉 sidecar 的存在。另一方面，用户自行维护一套全链路跟踪系统成本也很高，受限于遥测采样率和有限的协议支持，我们通常无法采集所有链路数据。

幸运的是，envoy 本身可以记录流量的信息，本文主要介绍如何利用 envoy 日志，对类似问题进行定位。

demo 环境为腾讯云 TKE，isito 版本 1.4.3，代码归档于：github.com/zhongfox/envoy-log-demo

2. Envoy 流量模型

我们先看看 envoy 的流量模型：

  1. 监听，接受连接
  2. 根据用户流量操纵规则，进行流量特征识别
  3. 进行流量操纵，如负载均衡，转发，拒绝等

在以上流程中， Envoy 接受请求流量叫做 Downstream，Envoy 发出请求流量叫做Upstream。在处理Downstream 和 Upstream 过程中， 分别会涉及2个流量端点，即请求的发起端和接收端：

image-20200212134617057

在这个过程中， envoy 会根据用户规则，计算出符合条件的转发目的主机集合，这个集合叫做 UPSTREAM_CLUSTER, 并根据负载均衡规则，从这个集合中选择一个 host 作为流量转发的接收端点，这个 host 就是 UPSTREAM_HOST。

以上就是 envoy 请求处理的 流量五元组信息， 这是 envoy 日志里最重要的部分，通过这个五元组我们可以准确的观测流量「从哪里来」和「到哪里去」。

  • UPSTREAM_CLUSTER
  • DOWNSTREAM_REMOTE_ADDRESS
  • DOWNSTREAM_LOCAL_ADDRESS
  • UPSTREAM_LOCAL_ADDRESS
  • UPSTREAM_HOST

3. Helloworld example

在 Istio 场景中，envoy 既可以是正向代理，也可以是反向代理。在上图中， 如果envoy 处理的是 outbound 流量， 业务容器是作为 Downstream 端点（右边）；如果 envoy 处理的是 inbound 流量， 业务容器是作为 Upstream 端点（左边）。

Istio 中默认不开启 envoy 中的访问日志，需要手动打开，将 istio 配置中 accessLogFile 设置为 /dev/stdout：

% kubectl -n istio-system edit cm istio
......
# Set accessLogFile to empty string to disable access log.
accessLogFile: "/dev/stdout" # 开启日志

accessLogEncoding: 'JSON' # 默认日志是单行格式， 可选设置为 JSON
......

我们以 sleep pod 访问 hello 服务来举例说明：

kubectl apply -f sleep-hello.yaml

image-20200212222251433

该文件定义了 2个版本的 helloworld 和一个 sleep Pod，helloworld service 的端口是 4000， 而 pod 的端口是5000。

从 sleep Pod 中去访问 helloworld 服务, 确认应用正常：

% SLEEP_POD=$(kubectl get pod -l app=sleep -o jsonpath="{.items[0].metadata.name}")
% HELLO_V1_POD=$(kubectl get pod -l app=helloworld -l version=v1 -o jsonpath="{.items[0].metadata.name}")
% kubectl exec -it $SLEEP_POD -csleep -- sh
/ # curl helloworld:4000/hello

这时候我们可以去分析 2 个 pod 各自的envoy 日志：

image-20200212222055391

用一张图来说明：

image-20200218100343328

从日志中我们可以分析出：

对于 sleep pod， sleep app 发出的流量目的端是 hello service ip 和 service port，sleep envoy 处理的是 outbound 流量， envoy 根据规则选择的 「UPSTREAM_CLUSTER 」是outbound|4000||helloworld.default.svc.cluster.local , 然后转发给其中的一个 「UPSTREAM_HOST 」, 也就是 hello pod 的 ip 和port。

对于 hello pod，其 envoy 处理的是 inbound 流量，envoy 根据规则选择的 「UPSTREAM_CLUSTER 」 是inbound|4000|http|helloworld.default.svc.cluster.local , 其中的 「UPSTREAM_HOST 」 是 「127.0.0.1:5000 」, 也就是该 pod 里的 hello app。

因此，我们可以总结出 istio 中流量端点值的逻辑规则：

UPSTREAM_HOST

上游主机的 host，表示从 envoy 发出的请求的目的端，通常是「ip:port」

通常来说，对于 outbound cluster，此值是「上游pod-ip : pod-port」 ，而对于 inbound cluster，此值是「127.0.0.1 : pod-port」

UPSTREAM_LOCAL_ADDRESS

上游连接中，当前 envoy 的本地地址，此值是「当前pod-ip : 随机端口」

DOWNSTREAM_LOCAL_ADDRESS

下游连接中，当前 envoy 的本地地址。

通常来说，对于 outbound cluster，此值是「目的service-ip : service-port 」，而对于 inbound cluster，此值是「当前pod-ip : pod-port」

DOWNSTREAM_REMOTE_ADDRESS

下游连接中远端地址。

通常来说，对于 outbound cluster，此值是「当前pod-ip : 随机端口 」，而对于 inbound cluster，此值是「下游pod-ip : 随机端口」

4. Envoy 日志格式

envoy 允许定制日志格式， 格式通过若干「Command Operators」组合，用于提取请求信息，istio 没有使用 envoy 默认的日志格式， istio 定制的访问日志格式如下：

image-20200205002607125

完整的「Command Operators」含义可查阅 Envoy Access logging Command Operators

除了以上流量五元组，流量分析中常用的重要信息还有：

RESPONSE_CODE

响应状态码

RESPONSE_FLAGS

很重要的信息，envoy 中自定义的响应标志位， 可以认为是envoy 附加的流量状态码。

如 「NR」表示找不到路由，「UH」表示upstream cluster 中没有健康的 host，「RL」表示触发 rate limit，「UO」触发断路器。

RESPONSE_FLAGS 可选值有十几个，这些信息在调试中非常关键。

X-REQUEST-ID

一次 C 到 S 的 http 请求，envoy 会在 C 端生产 request id，并附加到 header 中，传递到 S 端，在 2 端的日志中都会记录该值， 因此可以通过这个 ID 关联请求的上下游。注意不要和全链路跟踪中的 trace id 混淆。

ROUTE_NAME

匹配执行的路由名称

5. 场景一：判断异常返回是来自业务还是 sidecar？

比如我们希望所有请求 helloworld 都路由到 v1 版本，创建对应的 virtual service：

% kubectl apply -f hello-v1-virtualservice.yaml

apiVersion: networking.istio.io/v1alpha3
kind: VirtualService
metadata:
  name: hello
spec:
  hosts:
    - "helloworld"
  http:
    - route:
      - destination:
          host: helloworld
          subset: v1
          port:
            number: 4000

从 sleep 中访问发现响应 503：

image-20200212222518280

如果没有上下文，我们很难判断 503 是来自业务容器还是 sidecar，查看 sleep 和 hello 的 envoy 日志，可以发现：hello pod 的envoy 没有接受到请求，sleep pod 的 envoy 里日志：

image-20200212222631659

其中"response_flags": "NR" 表示「No route configured」，也就是 envoy 找不到路由，我们可以判断出该异常是有 envoy 返回。

通过简单的分析就可以找到原因， 我们在VirtualService 中使用的 Destination 没有定义，将其补上：

% kubectl apply -f hello-v1-destinationrule.yaml

apiVersion: networking.istio.io/v1alpha3
kind: DestinationRule
metadata:
  name: hello
spec:
  host: helloworld
  subsets:
    - name: v1
      labels:
        version: v1

再次访问请求正常，日志中response_flags 为空：

image-20200212222913583

6. 场景二：调试 istio mtls 神坑

我们在现有环境中开启 mtls: 在 istio-system namespace 中配置mtls 所需 meshpolicy 和 destinationrule，分别代表服务端和客户端开启 mtls （省略 了 istio-policy istio-telemetry 相关的调整）。

% kubectl -n istio-system apply -f mtls-init.yaml
meshpolicy.authentication.istio.io/default configured
destinationrule.networking.istio.io/default created

apiVersion: authentication.istio.io/v1alpha1
kind: MeshPolicy
metadata:
  name: default
spec:
  peers:
  - mtls: {}
---
apiVersion: networking.istio.io/v1alpha3
kind: DestinationRule
metadata:
  labels:
    release: istio
  name: default
  namespace: istio-system
spec:
  host: '*.local'
  trafficPolicy:
    tls:
      mode: ISTIO_MUTUAL

片刻后， sleep 再次访问 helloworld 出现connection termination异常，sleep envoy 中有如下日志：

image-20200212123932832

Sleep envoy "response_flags": "UC" 表示 Upstream 端终止了连接， "upstream_host": "172.16.0.15:5000"可以看出流量是发往了 helloworld v1 pod，进而查看 helloworld pod envoy 日志，发现居然没有日志！

一时间我们没法判断流量是因何终止。

这种情况，我们可以考虑开启更高级别的日志记录，envoy 默认的日志级别是 warning，我们可以调整为 debug 或者trace。

在 istio 中 有 2 种方式调整 envoy 日志级别， 第一种是在 istio 全局配置中调整， 这会修改 mesh 中所有 envoy 的日志级别，第二种方式，如果已经知道调试的目标 Pod， 我们可以给该 pod envoy 下发指令，只修改目标 envoy 的日志级别。

登录 helloworld pod，通过 admin api 将日志级别改为 debug：

% kubectl exec -it $HELLO_V1_POD -chelloworld -- sh
# curl -XPOST http://localhost:15000/logging\?level\=info

以上操作会改动这个 envoy 的所有日志目标，还可以只修改指定目标的日志级别，以减少日志量，比如：

curl -XPOST http://localhost:15000/logging\?filter\=debug
curl -XPOST http://localhost:15000/logging\?conn_handler\=debug
curl -XPOST http://localhost:15000/logging\?connection\=debug
curl -XPOST http://localhost:15000/logging\?router\=debug

这时我们可以看到，流量的确到达了 helloworld，但是在 TLS 握手阶段发生了错误：

image-20200212131616274

进一步分析，我们可以发现是因为服务端（helloworld）开启了 mtls，但是客户端（sleep）却没有开启，为什么 istio-system 中的 default destination rule 没有起作用？

原来我们在上一个 demo 中增加的 helloworld DestinationRule中， 默认是没有 mtls 定义（所以不开启 mtls），这个 DR 会在 helloworld pod 中覆盖 istio-system 中的 default destination rule。

我们在 helloworld DestinationRule 中补充 mtls 配置：

% kubectl apply -f hello-v1-destinationrule-with-mtls.yaml

apiVersion: networking.istio.io/v1alpha3
kind: DestinationRule
metadata:
  name: hello
spec:
  host: helloworld
  trafficPolicy:
    tls:
      mode: ISTIO_MUTUAL
  subsets:
    - name: v1
      labels:
        version: v1

再次测试，访问正常。

这种 istio mtls 用户接口极度不友好，虽然 mtls 默认做到了全局透明， 业务感知不到 mtls 的存在， 但是一旦业务定义了 DestinationRule，DestinationRule 就必须要知道当前 mtls 是否开启，并作出调整。试想 mtls 配置交由安全团队负责，而业务团队负责各自的 DestinationRule，2个 团队的耦合会非常严重。

Istio 官方在文档里做了提示：

Don’t forget that destination rules are also used for non-auth reasons such as setting up canarying, but the same order of precedence applies. So if a service requires a specific destination rule for any reason - for example, for a configuration load balancer - the rule must contain a similar TLS block with ISTIO_MUTUAL mode, as otherwise it will override the mesh- or namespace-wide TLS settings and disable TLS.

社区也有对这块的实现进行反思和重新设计：

image-20200212133704748

未来版本中我们应该可以看到 mtls 定义的优化。

7. 小结

除了 envoy 日志，数据面调试的工具常见的还有 xDS 信息，istio 官方的命令行工具 istioctl 等等，篇幅有限，后面有时间再介绍。

FEATURED TAGS
firefox javascript ruby 面向对象 git http 并发 读书笔记 rails 代码规范 tcp 缓存 nodejs 原型链 events emitter redis nosql 程序设计 调试 web架构 分布式 集群 koa 性能优化 微服务 kafka go 分布式跟踪 全链路 linux kubernetes container istio mesh envoy