出處：https://www.servicemesher.com/blog/istio-debug-with-envoy-log

這是使用 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

Envoy 流量模型

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

監聽，接受連線根據使用者流量操縱規則，進行流量特徵識別進行流量操縱，如負載均衡，轉發，拒絕等

在以上流程中， Envoy 接受請求流量叫做 Downstream，Envoy 發出請求流量叫做Upstream。在處理Downstream 和 Upstream 過程中， 分別會涉及2個流量端點，即請求的發起端和接收端：

在這個過程中， envoy 會根據使用者規則，計算出符合條件的轉發目的主機集合，這個集合叫做 UPSTREAM_CLUSTER, 並根據負載均衡規則，從這個集合中選擇一個 host 作為流量轉發的接收端點，這個 host 就是 UPSTREAM_HOST。

以上就是 envoy 請求處理的 流量五元組資訊， 這是 envoy 日誌裡最重要的部分，通過這個五元組我們可以準確的觀測流量「從哪裡來」和「到哪裡去」。

UPSTREAM_CLUSTERDOWNSTREAM_REMOTE_ADDRESSDOWNSTREAM_LOCAL_ADDRESSUPSTREAM_LOCAL_ADDRESSUPSTREAM_HOSTHelloworld 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 服務來舉例說明：

該檔案定義了 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 日誌：

用一張圖來說明：

從日誌中我們可以分析出：

對於 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 : 隨機埠」

Envoy 日誌格式

envoy 允許定製日誌格式， 格式通過若干「Command Operators」組合，用於提取請求資訊，istio 沒有使用 envoy 預設的日誌格式， istio 定製的訪問日誌格式如下：

完整的「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

匹配執行的路由名稱

場景一：判斷異常返回是來自業務還是 sidecar？

比如我們希望所有請求 helloworld 都路由到 v1 版本，建立對應的 virtual service：

% kubectl apply -f hello-v1-virtualservice.yamlapiVersion: networking.istio.io/v1alpha3kind: VirtualServicemetadata:  name: hellospec:  hosts:    - "helloworld"  http:    - route:      - destination:          host: helloworld          subset: v1          port:            number: 4000

從 sleep 中訪問發現響應 503：

如果沒有上下文，我們很難判斷 503 是來自業務容器還是 sidecar，檢視 sleep 和 hello 的 envoy 日誌，可以發現：hello pod 的envoy 沒有接受到請求，sleep pod 的 envoy 裡日誌：

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

通過簡單的分析就可以找到原因， 我們在VirtualService 中使用的 Destination 沒有定義，將其補上：

% kubectl apply -f hello-v1-destinationrule.yamlapiVersion: networking.istio.io/v1alpha3kind: DestinationRulemetadata:  name: hellospec:  host: helloworld  subsets:    - name: v1      labels:        version: v1

再次訪問請求正常，日誌中response_flags 為空：

場景二：除錯 istio mTLS 神坑

我們在現有環境中開啟 mTLS: 在 istio-system namespace 中配置 mTLS 所需 meshpolicy 和 destinationrule，分別代表服務端和客戶端開啟 mTLS （省略 了 istio-policy istio-telemetry 相關的調整）。

% kubectl -n istio-system apply -f mtls-init.yamlmeshpolicy.authentication.istio.io/default configureddestinationrule.networking.istio.io/default createdapiVersion: authentication.istio.io/v1alpha1kind: MeshPolicymetadata:  name: defaultspec:  peers:  - mtls: {}---apiVersion: networking.istio.io/v1alpha3kind: DestinationRulemetadata:  labels:    release: istio  name: default  namespace: istio-systemspec:  host: '*.local'  trafficPolicy:    tls:      mode: ISTIO_MUTUAL

片刻後， sleep 再次訪問 helloworld 出現connection termination異常，sleep envoy 中有如下日誌：

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\\=debugcurl -XPOST http://localhost:15000/logging\\?conn_handler\\=debugcurl -XPOST http://localhost:15000/logging\\?connection\\=debugcurl -XPOST http://localhost:15000/logging\\?router\\=debug

這時我們可以看到，流量的確到達了 helloworld，但是在 TLS 握手階段發生了錯誤：

進一步分析，我們可以發現是因為服務端（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.yamlapiVersion: networking.istio.io/v1alpha3kind: DestinationRulemetadata:  name: hellospec:  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.

社群也有對這塊的實現進行反思和重新設計：

未來版本中我們應該可以看到 mTLS 定義的優化。

小結

envoy 日誌記錄了 mesh 中流量走向和特徵的關鍵資訊，是資料面問題除錯的利器。除此之外，流量問題的排查還可以分析 xDS 內容, 以及istio 官方的命令列工具 istioctl 等等。