正常访问--Istio访问日志ResponseFlag重现与解析00

Sep 27, 2023 · 2 min read · KubeCon 访问日志 ResponseFlags ·

Share on:

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

在详细展开每种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的日志