正常访问--Istio访问日志ResponseFlag重现与解析00
KubeCon 2023在上海做的一个关于Istio访问日志的演讲《Detailed Parse and Reproduce Response Flags of Istio Access Log Based on Production Use Case》。解析和重现了在当时解决客户问题时碰到的各种应答日志。
在详细展开每种Response Flag前先介绍下本系列的必要前置信息。包括访问日志的背景、机制，以及重现这些Response Flag的基本环境，方便有兴趣的同学参照练习。
机制
早期的访问日志一般由应用程序输出，即要求用户在业务代码中记录每次访问。在服务网格中，和指标、调用链等可观测性能力类似，Istio通过非侵入方式提供访问日志的收集。
过程大致是：
1.网格数据面拦截流量，并根据配置的访问日志格式输出访问日志。
2.数据面根据配置的ALS(Access log Service)地址上报访问日志。
3.ALS服务端收集日志，存储在日志存储，如ES中，或其他的日志系统中。
4.服务端日志检索工具如Kibana或其他日服务索日志。
这是一个一般性流程机制，在Istio中日志可以通过ALS的gRPC的服务收集日志，也可以写日志文件、标准输出或者对接OpenTelemetry等通道，即各种标准接口对接各种日志系统和通道，日志格式可以动态定义。
环境
这是我这次实践的环境。
在一个accesslog的命名空间下，我们创建了两个服务。两个服务均注入了Sidecar。源服务内有curl命令，我们会通过curl访问目标服务，生成访问日志。目标服务是一个端口是80的Nginx容器。
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: 80
12 selector:
13 app: nginx
14 type: ClusterIP
可以看到整个环境是比较干净简单，我们会尽量在最简单的环境上构造各种不同的场景，重现大多数常见的Response Flag，方便大家理解。
1# kubectl get po -naccesslog -owide
2NAME READY STATUS RESTARTS AGE IP NODE
3nginx-57d5c48b96-2wdnb 2/2 Running 0 3d17h 10.66.0.28 172.16.0.24
4nginx-57d5c48b96-k9gzh 2/2 Running 0 18h 10.66.1.2 172.16.0.35
5client-589f87c6f9-hnh5x 2/2 Running 0 7d 10.66.0.24 172.16.0.24
1# kubectl get svc -naccesslog
2NAME TYPE CLUSTER-IP EXTERNAL-IP PORT(S) AGE
3nginx ClusterIP 10.246.91.131 <none> 80/TCP 7d
4client ClusterIP 10.246.71.113 <none> 8080/TCP 7d
格式
这是用例中的访问日志格式。Istio的访问日志格式可以动态定义，在控制面配置后会动态应用到各个数据面上。
这里没有配置特定的日志格式，从数据面的ConfigDump看应用到的是默认的访问日志格式。
1 "access_log": [
2 {
3 "name": "envoy.access_loggers.file",
4 "typed_config": {
5 "@type": "type.googleapis.com/envoy.extensions.access_loggers.file.v3.FileAccessLog",
6 "path": "/dev/stdout",
7 "log_format": {
8 "text_format_source": {
9 "inline_string": "[%START_TIME%] \"%REQ(:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL%\" %RESPONSE_CODE% %RESPONSE_FLAGS% %RESPONSE_CODE_DETAILS% %CONNECTION_TERMINATION_DETAILS% \"%UPSTREAM_TRANSPORT_FAILURE_REASON%\" %BYTES_RECEIVED% %BYTES_SENT% %DURATION% %RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)% \"%REQ(X-FORWARDED-FOR)%\" \"%REQ(USER-AGENT)%\" \"%REQ(X-REQUEST-ID)%\" \"%REQ(:AUTHORITY)%\" \"%UPSTREAM_HOST%\" %UPSTREAM_CLUSTER% %UPSTREAM_LOCAL_ADDRESS% %DOWNSTREAM_LOCAL_ADDRESS% %DOWNSTREAM_REMOTE_ADDRESS% %REQUESTED_SERVER_NAME% %ROUTE_NAME%\n"
10 }
11 }
12 }
13 }
14 ]
访问
这是我们的第一个访问日志的用例。在正常场景下，从源服务的容器中通过服务名curl目标服务。如果服务运行正常，源服务中会得到200 OK的访问结果。同时，在源服务的访问日志中会记录Outbound的流量。在目标服务的访问日志中会记录Inbound流量。
通过源和目标两个日志中request Id可以看到这是同一个请求。在正常场景下，从源服务的容器中通过服务名curl目标服务。如果服务运行正常，源服务中会得到200 OK的访问结果。
同时，在源服务的访问日志中会记录Outbound的流量。在目标服务的访问日志中会记录Inbound流量。通过源和目标两个日志中request Id可以看到这是同一个请求。
1[2023-08-19T08:21:07.115Z] "GET / HTTP/1.1" 200 - via_upstream - "-" 0 615 16 16 "-" "curl/7.52.1" "9d407fb5-ee88-4afd-bdd5-2caa22084c89" "nginx.accesslog" "10.66.0.28:80" outbound|80|v1|nginx.accesslog.svc.cluster.local 10.66.0.24:56896 10.246.91.131:80 10.66.0.24:50854 - -
1[2023-08-19T08:21:07.120Z] "GET / HTTP/1.1" 200 - via_upstream - "-" 0 615 0 0 "-" "curl/7.52.1" "9d407fb5-ee88-4afd-bdd5-2caa22084c89" "nginx.accesslog" "10.66.0.28:80" inbound|80|| 127.0.0.6:50739 10.66.0.28:80 10.66.0.24:56896 outbound_.80_.v1_.nginx.accesslog.svc.cluster.local default
文本类型的日志字段对应解析如下，方便读者对应。后续每种Response Flag的日志也是采用完全相同的日志格式。
| Access log Field | Client Side Outbound | Server Side Inbound |
|---|---|---|
| [%START_TIME%] | [2023-08-19T08:21:07.115Z] | [2023-08-19T08:21:07.120Z] |
| %REQ(:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL% | GET / HTTP/1.1 | GET / HTTP/1.1 |
| RESPONSE_CODE | 200 | 200 |
| RESPONSE_FLAGS | - | - |
| RESPONSE_CODE_DETAILS | via_upstream | via_upstream |
| CONNECTION_TERMINATION_DETAILS | - | - |
| UPSTREAM_TRANSPORT_FAILURE_REASON | - | - |
| BYTES_RECEIVED | 0 | 0 |
| BYTES_SENT | 615 | 615 |
| DURATION | 16 | 0 |
| RESP(X-ENVOY-UPSTREAM-SERVICE-TIME) | 16 | 0 |
| REQ(X-FORWARDED-FOR) | - | - |
| REQ(USER-AGENT) | curl/7.52.1 | curl/7.52.1 |
| REQ(X-REQUEST-ID) | 9d407fb5-ee88-4afd-bdd5-2caa22084c89 | 9d407fb5-ee88-4afd-bdd5-2caa22084c89 |
| REQ(:AUTHORITY) | nginx.accesslog | nginx.accesslog |
| UPSTREAM_HOST | 10.66.0.28:80 | 10.66.0.28:80 |
| UPSTREAM_CLUSTER | outbound|80|v1|nginx.accesslog.svc.cluster.local | inbound|80|| |
| UPSTREAM_LOCAL_ADDRESS | 10.66.0.24:56896 | 127.0.0.6:50739 |
| DOWNSTREAM_LOCAL_ADDRESS | 10.246.91.131:80 | 10.66.0.28:80 |
| DOWNSTREAM_REMOTE_ADDRESS | 10.66.0.24:50854 | 10.66.0.24:56896 |
| REQUESTED_SERVER_NAME | - | outbound_.80_.v1_.nginx.accesslog.svc.cluster.local |
| ROUTE_NAME | default |
后面每个场景都会follow这个的形式。
1.明确构造的条件重现用例的场景
2.详细的重现步骤
3.客户端请求的实际返回分析
4.一个服务间访问关系的图解析访问中的细节，
5.然后是实际的访问日志。会观察客户端outbound日志和服务端inbound的日志