SREチームの前多です。以前、Google Cloudが提供するサービスメッシュのAnthos Service Meshの入門記事を書きました。
この記事のまとめで私は、Istio (Anthos Service MeshのベースのOSS) を詳しく知るには、envoyのことをもっと知る必要があると書きました。 そしてサービスメッシュで何かエラーが起きているとき、それはサービスメッシュ自体ではなく インフラやアプリケーションのバグや設定ミスがサービスメッシュによってあぶり出されるということも述べました。
先日、サービスメッシュ上でPod間のgRPC通信が特定条件で失敗し、サイドカーがない場合のみ通信が成功するという事象が起きていました。
gRPCのライブラリのアップデートやIssueの調査しましたが、原因がわからずサイドカーを外すしかないかと思っていました。 最終手段として送信元PodのOutbound通信のサイドカー経由を外してみたところ、送信先のPodのサイドカーで、HTTP2のヘッダサイズが大きすぎるというエラーが出ていることを見つけました。
わかってみればなんということはなく、アプリケーションのミスで特定条件下で想定外に大きいgPRC Metadataを作っていて、OutboundのサイドカーのHTTP2クライアントでヘッダ長超過のエラーを出していたというのが原因でした。 アプリケーションでエラーハンドリングを詳細に行うか、送信元サイドカーの送信ログを出していれば、もっと早く原因がわかったかもしれません。
結局のところ、サイドカーが異常な通信をブロックしていたので、サービスメッシュ自体がバグを出してはいませんでした。 そして、サービスメッシュでも異常であることを記録しないと原因判明に時間がかかってしまうという教訓を得ました。
というわけでこの記事では、サービスメッシュ・サイドカーがおかしい場合にどのようなデバッグができるかを紹介します。
なお、弊社ではKubernetesの実行環境としてGKE, IstioについてはAnthos Service Meshを使用しています。 今回紹介する内容も弊社環境にて確認した内容となりますが、他の環境でも利用できるでしょう。
envoy サイドカー のおさらい
アプリケーションコンテナとサイドカーの関係は以下の図のようになります。
Istioは、各Podにenvoyをサイドカーコンテナとして挿入します。
envoyはPodの通信の入(Inbound)と出(Outbound)のどちらもサイドカー経由にします。
つまり、サービスメッシュ内の2つのPodの通信は、
PodAコンテナ -> Pod Aのサイドカー(Outboundポート) -> Pod Bのサイドカー(Inboundポート) -> Pod B コンテナ
という経路を辿ります。
もう少し踏み込むと、 Inbound通信は、L4とL7のInbound Listenerが構成され、アプリケーションコンテナに通信が行きます。 (L4向けのListenerはTCP用、L7はHTTPやgRPCなどのプロトコルごとのListenerとなっていてほとんどの場合でL7が使われる)
Outbound通信では、通信先ごと(サービスメッシュ内のk8sのサービスごと、および外部通信先)にClusterが構成されます。 そしてClusterごと(サービスごとに)にL4(TCP)/L7(HTTPなど)のOutbound Listenerが作られます。 最終的に、アプリケーションコンテナからの外部通信アドレスに応じてOutbount Listnerが振り分けられます。
Listenerはenvoyの待ち受けアドレスやポート、プロトコルの設定で、Clusterはenvoyの通信先に関するアドレス、ポート、プロトコル、分散方法などの設定です。詳細は envoyのアーキテクチャ をみると良いでしょう。
SaaSサービスなどサービスメッシュ外の通信は、何も設定しない場合はPassthrough Clusterというデフォルトの外部通信用クラスタとListenerが使用されます。 外部通信は通常HTTPSなので、ほとんどの場合でL4(TCP)が使われます。 ( Service Entryや Egress Gateway を使用すると、 通信先ごとにClusterを分けられるので外部通信先ごとのログやメトリクスを識別できる)
このようにサイドカー内部の構成を知っておくと、これから紹介するデバッグ手法やログ、メトリクスの分類などで役に立つでしょう。
envoy admin コンソールを開く
envoyは各種設定の参照や変更ができる admin コンソール があります。 Istioで挿入されるサイドカーやIngress gatewayも、adminコンソールにアクセスすれば有用な情報が得られます。
Istio envoyコンテナのadminポートは15000です(istioの使用ポート )。 このポートにport-forwardします。
例えば次のコマンドで、あるラベルのサービスのpod1つのサイドカーのadminコンソールにlocalhost:15000でアクセスできるようにします。
app=<your app>
namespace=<your namesapcae>
kubectl port-forward -n ${namespace} $(kubectl get pod -n ${namespace} -l app=${app} -o jsonpath="{.items[0].metadata.name}") 15000:15000
以下のようなUIが表示されると思います。
いくつかデバッグ時に役にたつメニューを紹介します。
Config Dump
envoyのconfigはprotobufをスキーマとするJSON/YAMLで設定します。config dumpはその内容を全てJSONで表示するので、 この内容を読み解ければ、Istioの各種設定ファイルからどのようにenvoyが構成されるのかがわかります。 ただし、読み解くには時間がかかるでしょう。一助として envoyのhigh level アーキテクチャが参考になると思います。
この設定により、自分で設定したIstioのマニフェストや、EnvoyFilterなどが想定通りにサイドカーに反映されているかがわかるほか、 通信プロトコルごとのタイムアウトや上限値などを把握したりします。
メトリクス
statsエンドポイントは、各種メトリクスを表示します。OpenMetrics形式にも対応しています。 Istioはenvoyのメトリクスを一部カスタマイズしていますので、Istioが提供するメトリクスを使うと良いでしょう。
様々なメトリクスがありますが、私の経験ではoutbound通信のエラー調査で使うことが多いです。 例えば、istio_requests_totalメトリクスをみると通信先、通信エラーごとのカウントがわかります。
通信先は destination_service_name などのラベルで表現されます。前述したenvoyのクラスターに相当します。
通信エラーは response_flags というラベルでわかります。
response_flagsの詳細は envoy access log のページに記載されています。
通信が切断された理由がこれで判明するので、自分か相手かどちらに原因があったのかが判断できます。
また、メトリクスについてはadminコンソールを開かなくてもPodの15020ポートでデフォルトで提供されるので、 PrometheusやDatadogなどで収集できます。
以下の図は、サイドカーの外部通信(passthrough cluster)のメトリクスをDatadogで収集して可視化している例です。
ほとんどの通信は成功しているのに加え、response flagsがDC(DownstreamConnectionTermination)およびUC(UpstreamConnectionTermination)の記録もあります。
そのためごくわずかの通信がタイムアウトで切断されているようです。
ログレベルの変更
loggingエンドポイントで、envoyサイドカーのログレベルをコンポーネント単位で変更できます。デフォルトのログレベルはwarningですが、 debugに設定すると通信ごとに詳細な内容をログに出せます。 冒頭で触れた特定条件での通信エラーは、ログレベルを一時変更して再現させることで何が起きたのかが詳細に調査できるでしょう。
ログレベルの変更はコンソール上からでもできますが、port-fowardしている状態なら、curlなどでもできます。 次の例は、主に通信関連のコンポーネントについてログレベルをdebugにする例です。
curl -XPOST http://localhost:15000/logging \ -d "paths=connection:debug,grpc:debug,http:debug,http2:debug,ext_authz:debug"
この状態でpodのistio-proxyコンテナ(サイドカーのコンテナ名) のログを見ると、通信ごとに次のような内容が表示されます。
kubectl logs <pod_name> istio-proxy
2024-05-13T09:04:00.103315Z debug envoy http external/envoy/source/common/http/conn_manager_impl.cc:1118 [C340][S8971455977285060032] request headers complete (end_stream=true):
':authority', '10.12.0.240:15021'
':path', '/healthz/ready'
':method', 'GET'
'user-agent', 'kube-probe/1.27'
'accept', '*/*'
'connection', 'close'
thread=47
2024-05-13T09:04:00.103329Z debug envoy http external/envoy/source/common/http/conn_manager_impl.cc:1101 [C340][S8971455977285060032] request end stream thread=47
2024-05-13T09:04:00.103359Z debug envoy connection external/envoy/source/common/network/connection_impl.h:98 [C340] current connecting state: false thread=47
2024-05-13T09:04:00.104007Z debug envoy http external/envoy/source/common/http/conn_manager_impl.cc:1708 [C340][S8971455977285060032] closing connection due to connection close header thread=47
調査が終われば、ログレベルを戻します。 また、Podが再起動したりすると設定が元に戻るので、長時間の調査は注意してください。
サイドカーのアクセスログを出力する
弊社では、調査用にL7 Inbound Listenerのアクセスログを常に収集しています。 ですが、状況に応じてOutbound Listenerのログも収集できると役に立ちます。
例えば次のような EnvoyFilter リソースを使用すると、特定のPodのOutbound通信のみアクセスログを出力できます。 EnvoyFilterは、Istioが提供するマニフェストでは設定できないような細かいカスタマイズを直接envoyサイドカーに行う機能です。 利用するにあたってはenvoyの知識も必要なので、config dumpと睨めっこしながら試行錯誤すると良いでしょう。
また、アクセスログのフォーマットは envoy log format を参照してください。
--- apiVersion: networking.istio.io/v1alpha3 kind: EnvoyFilter metadata: name: sidecar-outbound-accesslog namespace: <Outboundログを出力したいPodのnamespace> # target pod workspace spec: workloadSelector: labels: app: <Outboundログを出力したいPodのlabel> # target pod label configPatches: # sample 1 L4 outbound log( 例えば 外部 HTTPアクセス) - applyTo: NETWORK_FILTER match: context: SIDECAR_OUTBOUND # outbound通信の指定 listener: filterChain: filter: name: "envoy.filters.network.tcp_proxy" #L4 Listenerは tcp filterをターゲットにする patch: operation: MERGE value: typed_config: "@type": "type.googleapis.com/envoy.extensions.filters.network.tcp_proxy.v3.TcpProxy" access_log: - name: envoy.file_access_log typed_config: "@type": "type.googleapis.com/envoy.extensions.access_loggers.file.v3.FileAccessLog" path: /dev/stdout typed_json_format: "time": "%START_TIME%" "direction": "out_l4" "response_flags": "%RESPONSE_FLAGS%" "response_code_details": "%RESPONSE_CODE_DETAILS%" "connection_termination_details": "%CONNECTION_TERMINATION_DETAILS%" "bytes_received": "%BYTES_RECEIVED%" "bytes_sent": "%BYTES_SENT%" "duration": "%DURATION%" "upstream_host": "%UPSTREAM_HOST%" "upstream_cluster": "%UPSTREAM_CLUSTER%" "upstream_local_address": "%UPSTREAM_LOCAL_ADDRESS%" "upstream_transport_failure_reason": "%UPSTREAM_TRANSPORT_FAILURE_REASON%" # sample 2 outbound L7通信のログ (Pod間通信) - applyTo: NETWORK_FILTER match: context: SIDECAR_OUTBOUND listener: filterChain: filter: name: "envoy.filters.network.http_connection_manager" #L7 Listenerは http connection managerをターゲットにする patch: operation: MERGE value: typed_config: "@type": "type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager" access_log: - name: envoy.file_access_log typed_config: "@type": "type.googleapis.com/envoy.extensions.access_loggers.file.v3.FileAccessLog" path: /dev/stdout typed_json_format: # envoy default + caddi log standard "direction": "out_l7" "time": "%START_TIME%" "route_name": "%ROUTE_NAME%" "status_code": "%RESPONSE_CODE%" "response_flags": "%RESPONSE_FLAGS%" "response_code_details": "%RESPONSE_CODE_DETAILS%" "connection_termination_details": "%CONNECTION_TERMINATION_DETAILS%" "bytes_received": "%BYTES_RECEIVED%" "bytes_sent": "%BYTES_SENT%" "duration": "%DURATION%" "upstream_service_time": "%RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)%" "user_agent": "%REQ(USER-AGENT)%" "request_id": "%REQ(X-REQUEST-ID)%" "client_ip": "%REQ(True-Client-IP)%" "authority": "%REQ(:AUTHORITY)%" "upstream_host": "%UPSTREAM_HOST%" "upstream_cluster": "%UPSTREAM_CLUSTER%" "upstream_local_address": "%UPSTREAM_LOCAL_ADDRESS%" "upstream_transport_failure_reason": "%UPSTREAM_TRANSPORT_FAILURE_REASON%" "grpc_status_details": "%GRPC_STATUS%" "grpc_status_code": "%GRPC_STATUS_NUMBER%" "request": "type": "%PROTOCOL%" "method": "%REQ(:METHOD)%" "path": "%REQ(X-ENVOY-ORIGINAL-PATH?:PATH)%"
前述した通り、Outbound通信は通信先によってL4(TCP), L7(HTTP)の区別があリます。
網羅的にログを出したい場合は、上記のようにTcpFilterにも設定が必要です。
また、L4(TCP)の場合は、HTTPに関する詳細情報をログに出すことはできません。
(参考)Telemetry APIによるログ出力の設定
なお、現在ではアクセスログの出力は、Telemetry APIのAccess Logging でも行うことができます。 筆者らがAnthos Service Meshを使用したときにはまだアルファ版だったので採用していませんでした。 今後は検証した上で、 Telemetry APIに定義を移行するかもしれません。
まとめ
Istioのenvoyサイドカーのデバッグ、可視化について解説しました。 これでなんとなくサービスメッシュが悪者扱いされることがなくなることを祈っています。
