DI(注入延时故障)--Istio访问日志ResponseFlag重现与解析09

calendar Oct 6, 2023 · 1 min read · KubeCon 访问日志 ResponseFlags DI  ·
Share on: linkedin copy

KubeCon 2023在上海做的一个关于Istio访问日志的演讲。解析和重现了在当时解决客户问题时碰到的各种应答日志。

第九个关注的Response Flag是DI，全称是DelayInjected，官方定义表示The request processing was delayed for a period specified via fault injection.

含义：

DI表示请求中注入了一个延时故障。在VirtualService中配置了延时故障注入时，会在服务请求时产生配置的延时，并在访问日志中会记录DI的应答标记。

DI服务访问

重现环境：

  • 客户端Pod，注入了Sidecar。
  • 目标服务，一个Cluster类型的Kubernetes服务，多个服务实例。服务端Pod可以注入Siecar，也可以不用注入。

重现步骤：

第一步： 从注入了网格代理的客户端Pod中通过目标名和服务端口访问目标服务，观察代理的访问日志，得到正常的200响应码。从服务端和客户端的访问日志上都可以看到服务在目标服务的多个实例上负载均衡。正常访问参照本系列的环境部分描述。

第二步： 修改目标服务的VirtualService，在路由上配置10秒的延时。

 1apiVersion: networking.istio.io/v1beta1
 2kind: VirtualService
 3metadata:
 4  name: nginx-80
 5  namespace: accesslog
 6spec:
 7  hosts:
 8  - nginx
 9  http:
10  - fault:
11      delay:
12        fixedDelay: 10s
13        percentage:
14          value: 100
15    route:
16    - destination:
17        host: nginx.accesslog.svc.cluster.local
18        subset: v1

第三步： .在客户端容器中还是使用原有方式访问目标服务，可以看到得到了一个404错误，表示请求的资源不存在。在客户端容器中还是原有方式curl目标服务，在图上标记的位置，延迟了10秒后返回应答。

DI客户端访问

**第四步：**观察客户端访问日志中记录了200 DI。

1[2023-08-20T03:21:03.863Z] "GET / HTTP/1.1" 200 DI via_upstream - "-" 0 615 10000 0 "-" "curl/7.52.1" "3a52e6e3-df38-47af-912d-a21d65de4d79" "nginx.accesslog" "10.66.0.28:80" outbound|80|v1|nginx.accesslog.svc.cluster.local 10.66.0.24:60450 10.246.91.131:80 10.66.0.24:42038 - -

第五步： 观察服务端日志。在服务端的日志中和正常日志完全相同，记录200的正常响应。

1[2023-08-20T03:21:13.863Z] "GET / HTTP/1.1" 200 - via_upstream - "-" 0 615 0 0 "-" "curl/7.52.1" "3a52e6e3-df38-47af-912d-a21d65de4d79" "nginx.accesslog" "10.66.0.28:80" inbound|80|| 127.0.0.6:49911 10.66.0.28:80 10.66.0.24:60450 outbound_.80_.v1_.nginx.accesslog.svc.cluster.local default

第六步： 观察服务的耗时字段可以看到在源服务的outbound日志中耗时10秒，而服务端的耗时是0秒。也反映了延时注入的效果，即使真正服务应答不怎么花时间，在客户端的应用程序看来耗费了10秒钟，客户端和服务端本身没有做任何修改。这也是网格透明的流量能力的一个比较生动的体现。 这里只是注入延时增加了服务响应时间，还是得到了正常的响应，因此服务端和客户端的HTTP响应码都是200。

应对建议

访问日志中记录了人为注入的故障，无需特殊处理。