URX(上游超过重试次数)--Istio访问日志ResponseFlag重现与解析04
KubeCon 2023在上海做的一个关于Istio访问日志的演讲《Detailed Parse and Reproduce Response Flags of Istio Access Log Based on Production Use Case》。解析和重现了在当时解决客户问题时碰到的各种应答日志。
第四个关注的Response Flag是URX，全称是 UpstreamRetryLimitExceded ，官方定义表示"The request was rejected because the upstream retry limit (HTTP) or maximum connect attempts (TCP) was reached.."
含义：
URX表示超过了HTTP的请求重试阈值，或者TCP的重连阈值，而导致访问被拒绝。这时客户端的访问日志中会记录URX。
重现环境：
- 客户端Pod，注入了Sidecar。
- 目标服务，一个Cluster类型的Kubernetes服务，多个服务实例。服务端Pod可以注入Siecar，也可以不用注入。
重现步骤：
第一步： 从注入了网格代理的客户端Pod中通过目标名和服务端口访问目标服务，观察代理的访问日志，得到正常的200响应码。从服务端和客户端的访问日志上都可以看到服务在目标服务的多个实例上负载均衡。正常访问参照本系列的环境部分描述。
第二步： 在第一个正常用例基础上修改服务的target port为错误的服务端口888。
1apiVersion: v1
2kind: Service
3metadata:
4 name: nginx
5 namespace: accesslog
6spec:
7 ports:
8 - name: http
9 port: 80
10 protocol: TCP
11 targetPort: 888 # Modify target port 80->888，make service instance request failed
12 selector:
13 app: nginx
14 type: ClusterIP
第三步： 在客户端容器中curl 目标服务，得到503错误，提示连接失败。
第四步： 观察客户端容器的访问日志出现503 URX，表示请求次数超过了重试次数后错误。
1[2023-08-19T08:38:56.203Z] "GET / HTTP/1.1" 503 URX via_upstream - "-" 0 145 51 51 "-" "curl/7.52.1" "1bd7e9c8-0881-41b2-a964-525cad938d00" "nginx.accesslog" "10.66.0.28:888" outbound|80|v1|nginx.accesslog.svc.cluster.local 10.66.0.24:57388 10.246.91.131:80 10.66.0.24:37236 - -
第五步： 观察服务端日志中记录503UF，结合上一个用例UF的理解，是服务端sidecar连接他的上游，即目标服务的一个实例，因为实例端口错误，连接失败了，报503UF。
1[2023-08-19T08:38:56.207Z] "GET / HTTP/1.1" 503 UF upstream_reset_before_response_started{connection_failure,delayed_connect_error:_111} - "delayed_connect_error:_111" 0 145 0 - "-" "curl/7.52.1" "1bd7e9c8-0881-41b2-a964-525cad938d00" "nginx.accesslog" "10.66.0.28:888" inbound|888|| - 10.66.0.28:888 10.66.0.24:57376 outbound_.80_.v1_.nginx.accesslog.svc.cluster.local default
2[2023-08-19T08:38:56.234Z] "GET / HTTP/1.1" 503 UF upstream_reset_before_response_started{connection_failure,delayed_connect_error:_111} - "delayed_connect_error:_111" 0 145 0 - "-" "curl/7.52.1" "1bd7e9c8-0881-41b2-a964-525cad938d00" "nginx.accesslog" "10.66.0.28:888" inbound|888|| - 10.66.0.28:888 10.66.0.24:57384 outbound_.80_.v1_.nginx.accesslog.svc.cluster.local default
3[2023-08-19T08:38:56.254Z] "GET / HTTP/1.1" 503 UF upstream_reset_before_response_started{connection_failure,delayed_connect_error:_111} - "delayed_connect_error:_111" 0 145 0 - "-" "curl/7.52.1" "1bd7e9c8-0881-41b2-a964-525cad938d00" "nginx.accesslog" "10.66.0.28:888" inbound|888|| - 10.66.0.28:888 10.66.0.24:57388 outbound_.80_.v1_.nginx.accesslog.svc.cluster.local default
第六步： 再详细解析下两组日志可以看到客户端Pod一次请求，在客户端生成一次outbound日志，在服务端产生三次inbound日志，request Id 都相同。说明客户端发起第一次原始请求失败后，还自动发起了另外2次重试。Istio中对网格管理的服务默认进行2次重试，可以配置修改。这个场景中服务targetPod错误，导致三次访问都失败了。失败后客户端日志报URX，服务端上游服务不健康，符合上一个用例UF的条件，日志记录UF。
应对建议：
提高服务的质量，保证成功率，保证服务在有限重试后能正常的被访问。