Istioのログ機能のカスタマイズ(Lua)

Tags:

Istioの導入

Istioをインストールする．

https://istio.io/latest/docs/setup/getting-started/

インストールコマンド

istioctl install --set profile=default -y --set meshConfig.accessLogFile=/dev/stdout

ロギング方法の調査

Istioのサイドカープロキシとして動作するEnvoyでリクエストBodyをロギングできる方法がないか調査する．

Request Body logging · Issue #4724 · envoyproxy/envoy

上記のフォーラムをみると，EnvoyにはLuaスクリプトを追加して任意の操作をリクエスト処理の途中に差し込む機能があり，それを使ってロギングしている事例があった．

service-mesh-patterns/envoy-lua-filters at c22ae3850c2b34515c88a91459542af872d55e24 · kenju/service-mesh-patterns

Luaスクリプトを組み込んだEnvoyプロキシのコンテナイメージを作りIstioで使う方法が簡単に思いついた．Istioのソースコードを追いかけるのは大変そうなので，できれば簡単にできる方法がほかにないか調査してみる．

IstioのEnvoyFilter

以下はEnvoyにあるFIlterをIstioで使う方法が書いてあった．

Istio / Envoy Filter

上記のドキュメントに書いてあった以下の記述は，まさにやりたいことを表している．

EnvoyFilter provides a mechanism to customize the Envoy configuration generated by Istio Pilot. Use EnvoyFilter to modify values for certain fields, add specific filters, or even add entirely new listeners, clusters, etc.

ドキュメントにはLuaを使ったカスタマイズの例も記載されていた．

Luaを使ったカスマイズ例

apiVersion: networking.istio.io/v1alpha3
kind: EnvoyFilter
metadata:
  name: reviews-lua
  namespace: bookinfo
spec:
  workloadSelector:
    labels:
      app: reviews
  configPatches:
    ## The first patch adds the lua filter to the listener/http connection manager
  - applyTo: HTTP_FILTER
    match:
      context: SIDECAR_INBOUND
      listener:
        portNumber: 8080
        filterChain:
          filter:
            name: "envoy.filters.network.http_connection_manager"
            subFilter:
              name: "envoy.filters.http.router"
    patch:
      operation: INSERT_BEFORE
      value: ## lua filter specification
       name: envoy.filters.http.lua
       typed_config:
          "@type": "type.googleapis.com/envoy.extensions.filters.http.lua.v3.Lua"
          inlineCode: |
            function envoy_on_request(request_handle)
              -- Make an HTTP call to an upstream host with the following headers, body, and timeout.
              local headers, body = request_handle:httpCall(
               "lua_cluster",
               {
                [":method"] = "POST",
                [":path"] = "/acl",
                [":authority"] = "internal.org.net"
               },
              "authorize call",
              5000)
            end            
  ## The second patch adds the cluster that is referenced by the lua code
  ## cds match is omitted as a new cluster is being added
  - applyTo: CLUSTER
    match:
      context: SIDECAR_OUTBOUND
    patch:
      operation: ADD
      value: ## cluster specification
        name: "lua_cluster"
        type: STRICT_DNS
        connect_timeout: 0.5s
        lb_policy: ROUND_ROBIN
        load_assignment:
          cluster_name: lua_cluster
          endpoints:
          - lb_endpoints:
            - endpoint:
                address:
                  socket_address:
                    protocol: TCP
                    address: "internal.org.net"
                    port_value: 8888

Envoy Filterを確かめてみる

koyama@koyama-develop1:~$ kubectl get envoyfilter -A
NAMESPACE      NAME                    AGE
istio-system   stats-filter-1.13       20h
istio-system   stats-filter-1.16       20h
istio-system   stats-filter-1.14       20h
istio-system   tcp-stats-filter-1.14   20h
istio-system   tcp-stats-filter-1.15   20h
istio-system   tcp-stats-filter-1.13   20h
istio-system   tcp-stats-filter-1.16   20h
istio-system   stats-filter-1.15       20h

試しに1つのEnvoy Filterを確認してみる

kubectl get envoyfilter stats-filter-1.13 -o yaml

結果

apiVersion: networking.istio.io/v1alpha3
kind: EnvoyFilter
metadata:
  annotations:
    meta.helm.sh/release-name: istiod
    meta.helm.sh/release-namespace: istio-system
  creationTimestamp: "2023-01-04T08:00:28Z"
  generation: 1
  labels:
    app.kubernetes.io/managed-by: Helm
    istio.io/rev: default
  name: stats-filter-1.13
  namespace: istio-system
  resourceVersion: "31335"
  uid: af393e07-567f-49a8-b3a3-100d64c07a38
spec:
  configPatches:
  - applyTo: HTTP_FILTER
    match:
      context: SIDECAR_OUTBOUND
      listener:
        filterChain:
          filter:
            name: envoy.filters.network.http_connection_manager
            subFilter:
              name: envoy.filters.http.router
      proxy:
        proxyVersion: ^1\.13.*
    patch:
      operation: INSERT_BEFORE
      value:
        name: istio.stats
        typed_config:
          '@type': type.googleapis.com/udpa.type.v1.TypedStruct
          type_url: type.googleapis.com/envoy.extensions.filters.http.wasm.v3.Wasm
          value:
            config:
              configuration:
                '@type': type.googleapis.com/google.protobuf.StringValue
                value: |
                  {
                    "debug": "false",
                    "stat_prefix": "istio"
                  }                  
              root_id: stats_outbound
              vm_config:
                code:
                  local:
                    inline_string: envoy.wasm.stats
                runtime: envoy.wasm.runtime.null
                vm_id: stats_outbound

EnvoyFilterの自作

スクリプトの書き方は以下にある．しかし，調べる限りではIstioのEnvoy Filterの記述は独自の部分があるようで inlineCode と inline_string のように記述に違いがある．そのため，Istio公式の構成ファイルを参照するのが最適だと思う．

サンプルを改変してロギングしてみる

サンプルをいじって書いてみた．

apiVersion: networking.istio.io/v1alpha3
kind: EnvoyFilter
metadata:
  name: front-end-lua
  namespace: sock-shop
spec:
  workloadSelector:
    labels:
      name: front-end
  configPatches:
    ## The first patch adds the lua filter to the listener/http connection manager
  - applyTo: HTTP_FILTER
    match:
      context: SIDECAR_INBOUND
      listener:
        portNumber: 8080
        filterChain:
          filter:
            name: "envoy.filters.network.http_connection_manager"
            subFilter:
              name: "envoy.filters.http.router"
    patch:
      operation: INSERT_BEFORE
      value: ## lua filter specification
       name: envoy.filters.http.lua
       typed_config:
          "@type": "type.googleapis.com/envoy.extensions.filters.http.lua.v3.Lua"
          inlineCode: |
            function envoy_on_request(request_handle)
              -- Make an HTTP call to an upstream host with the following headers, body, and timeout.
              local headers, body = request_handle:httpCall(
               "lua_cluster",
               {
                [":method"] = "GET",
                [":path"] = "/get",
                [":authority"] = "httpbin.org"
               },
              "authorize call",
              5000)
            end

参考になりそうなLuaスクリプトを見つけた．以下を使えばロギングができそう．

handle:logDebug()

ログ機能を含んだコードを作成する．

apiVersion: networking.istio.io/v1alpha3
kind: EnvoyFilter
metadata:
  name: front-end-lua
  namespace: sock-shop
spec:
  workloadSelector:
    labels:
      name: front-end
  configPatches:
    - applyTo: HTTP_FILTER
      match:
        context: SIDECAR_INBOUND
        listener:
          portNumber: 8079
          filterChain:
            filter:
              name: "envoy.filters.network.http_connection_manager"
              subFilter:
                name: "envoy.filters.http.router"
      patch:
        operation: ADD
        value:
         name: envoy.filters.http.lua
         typed_config:
            "@type": "type.googleapis.com/envoy.extensions.filters.http.lua.v3.Lua"
            inlineCode: |
              function envoy_on_request(request_handle)
                request_handle:logDebug("Hello World")
              end

デプロイ結果を以下のコマンドで確認する．

kubectl get pod

以下がコマンドの結果である．

NAME                            READY   STATUS    RESTARTS   AGE
carts-db-84db597c89-2rm2f       2/2     Running   0          29h
catalogue-db-669d5dbf48-qql9j   2/2     Running   0          29h
carts-78d7c69cb8-8cd8k          2/2     Running   0          29h
orders-db-5b75567447-lhw7h      2/2     Running   0          29h
orders-6697b9d66d-9km66         2/2     Running   0          29h
rabbitmq-6c7dfd98f6-zrdrq       3/3     Running   0          29h
queue-master-747c9f9cf9-8mw8w   2/2     Running   0          29h
shipping-74586cc59d-brjkv       2/2     Running   0          29h
user-db-bcc86b99d-jkpvk         2/2     Running   0          29h
session-db-6747f74f56-zdhpw     2/2     Running   0          29h
catalogue-7dc9464f59-7zv92      2/2     Running   0          29h
payment-ff86cd6f8-mjdbj         2/2     Running   0          29h
user-5b695f9cbd-nhbsc           2/2     Running   0          29h
front-end-7d89d49d6b-q4pz8      1/2     Running   0          96s

エラーが出て 1/2 でIstio ProxyのPodが起動していない可能性が高い．

Istio ProxyのPodが起動せず

Istio Proxyのログを参照してみる．

kubectl logs front-end-7d89d49d6b-q4pz8 -c istio-proxy

以下はログの一部である．

2023-01-05T14:50:24.386259Z	warning	envoy config	gRPC config for type.googleapis.com/envoy.config.listener.v3.Listener rejected: Error adding/updating listener(s) virtualInbound: Error: terminal filter named envoy.filters.http.router of type envoy.filters.http.router must be the last filter in a http filter chain.
2023-01-05T14:50:25.220790Z	warn	Envoy proxy is NOT ready: config received from XDS server, but was rejected: cds updates: 1 successful, 0 rejected; lds updates: 0 successful, 1 rejected
2023-01-05T14:50:25.579736Z	warn	Envoy proxy is NOT ready: config received from XDS server, but was rejected: cds updates: 1 successful, 0 rejected; lds updates: 0 successful, 1 rejected

operatorがADDになっていることが原因だと考えた．operatorはフィルタの挿入する順序を指定するパラメータである．このパラメータがADDになっていたことで，上記の envoy.filters.http.router の順序に関するエラーが出ていたと推測した．

EnvoyFilterの修正

構成ファイルの一部を以下に修正した．

spec:
  configPatches:
    - patch:
        operation: INSERT_BEFORE

デプロイが上手く出来た．

kubectl get pod

きちんとPodがREADYになっている．

NAME                            READY   STATUS    RESTARTS   AGE
...
front-end-7d89d49d6b-q4pz8      2/2     Running   0          8d

ログを確認してみる．

kubectl logs front-end-7d89d49d6b-q4pz8 -c front-end
kubectl logs front-end-7d89d49d6b-q4pz8 -c istio-proxy

残念ながらログがなかった．

Istioの再インストール

以下のフォーラムを見たところアクセスログが /dev/stdout に書き出されていないことが原因ではないかと指摘されていた．

Where can I find logs created by request_handle:logInfo(“Hello World.”) - General - Discuss Istio

Istioを再インストールするが状況は変化せず．

以下のインストールコマンドを実行して /dev/stdout へログを書き出すよう変更する．

istioctl install --set profile=default -y --set meshConfig.accessLogFile=/dev/stdout

ログレベルの変更

Googleで「envoyfilter log」検索してみると以下の記事がHitした． 記事ではログレベルが低いことが原因だと書かれている．

EnvoyFilter [ lua filter ] is not printing log on console · Issue #11592 · envoyproxy/envoy

ログレベルは「trace, debug, info, warning, error, critical, off」がある．

istio-proxy の log level を変更する · 1Q77

ログレベルを最も高いCriticalでプリントしてみる．

Criticalでログを書き出すコード

apiVersion: networking.istio.io/v1alpha3
kind: EnvoyFilter
metadata:
  name: front-end-lua
  namespace: sock-shop
spec:
  workloadSelector:
    labels:
      name: front-end
  configPatches:
    - applyTo: HTTP_FILTER
      match:
        context: SIDECAR_INBOUND
        listener:
          portNumber: 8079
          filterChain:
            filter:
              name: "envoy.filters.network.http_connection_manager"
              subFilter:
                name: "envoy.filters.http.router"
      patch:
        operation: INSERT_BEFORE
        value:
         name: envoy.filters.http.lua
         typed_config:
           "@type": "type.googleapis.com/envoy.extensions.filters.http.lua.v3.Lua"
           inlineCode: |
             function envoy_on_request(request_handle)
               request_handle:logCritical("Hello World")
             end

上記のコードを以下のコマンドで適用する．

kubectl apply -f my-envoy-filter.yml

以下のコマンドでログを確かめてみる．

kubectl logs front-end-7d89d49d6b-nqjhh -c istio-proxy | grep Hello | head

ログを読むとCriticalのログレベルでログが書き出されている． :tada::tada::tada:

2023-01-14T12:39:42.014038Z	critical	envoy lua	script log: Hello World
2023-01-14T12:39:42.047969Z	critical	envoy lua	script log: Hello World
2023-01-14T12:39:42.050635Z	critical	envoy lua	script log: Hello World
2023-01-14T12:39:42.070074Z	critical	envoy lua	script log: Hello World
2023-01-14T12:39:42.070404Z	critical	envoy lua	script log: Hello World
2023-01-14T12:39:42.073717Z	critical	envoy lua	script log: Hello World
2023-01-14T12:39:42.074783Z	critical	envoy lua	script log: Hello World
2023-01-14T12:39:42.075592Z	critical	envoy lua	script log: Hello World
2023-01-14T12:39:42.107378Z	critical	envoy lua	script log: Hello World
2023-01-14T12:39:42.107470Z	critical	envoy lua	script log: Hello World

HTTP Requst Bodyを取得する

以下のドキュメントを見ながらLuaのスクリプトをカスタマイズしていく．

Lua — envoy 1.25.0-dev-4fb3ee documentation

Luaスクリプトを以下に修正して実行してみる．

function envoy_on_request(request_handle)
  request_handle:logCritical("Hello World 2")
  local body_length = request_handle:body():length()
  request_handle:logCritical("Body Length:"..body_length)
end

以下のコマンドでログを確認してみる．

kubectl logs front-end-7d89d49d6b-nqjhh -c istio-proxy | grep lua

以下のログが見つかった．正しくBodyがとれていることがわかる．POSTでBodyがない場合はエラーが出る．

2023-01-15T01:52:45.971727Z	critical	envoy lua	script log: Hello World 2
2023-01-15T01:52:45.971858Z	error	envoy lua	script log: [string "function envoy_on_request(request_handle)..."]:3: attempt to index a nil value
2023-01-15T01:53:05.152811Z	critical	envoy lua	script log: Hello World 2
2023-01-15T01:53:05.152855Z	critical	envoy lua	script log: Body Length:54

Luaスクリプトを以下に修正して実行してみる．

function envoy_on_request(request_handle)
  request_handle:logCritical("Hello World 5")
  local index = 0
  for chunk in request_handle:bodyChunks() do
    local len = chunk:length()
    local result = chunk:getBytes(index, len)
    index = index + len
    request_handle:logCritical("Body:"..result)
  end
end

以下のコマンドでログを確認する．

kubectl logs front-end-7d89d49d6b-nqjhh -c istio-proxy | grep lua

ログにリクエストBodyを書き出せた．

2023-01-15T02:28:52.041025Z	critical	envoy lua	script log: Hello World 5
2023-01-15T02:28:52.041821Z	critical	envoy lua	script log: Body:{"longNum":"121214234135","expires":"03/22","ccv":"231"}
2023-01-15T02:28:52.042011Z	error	envoy lua	script log: [string "function envoy_on_request(request_handle)..."]:6: index/length must be >= 0 and (index + length) must be <= buffer size
2023-01-15T02:28:52.104863Z	critical	envoy lua	script log: Hello World 5

Google検索をしていたところ，スクエニの記事を見つけた．これを使えばLuaスクリプトをシンプルに書ける気がした．

突然の災害に備える Envoy Lua filter | スクエニ ITエンジニア ブログ

以下の記事は見つけたものの古いため，参考にならなかった．

tutorial-istio-envoy-lua-filters/README.md at master · ibm-cloud-architecture/tutorial-istio-envoy-lua-filters

以下にスクリプトを変更した．

function envoy_on_request(request_handle)
  request_handle:logCritical("Hello World 12")
  local body_obj = request_handle:body()
  if body_obj ~= nil then
    local body_bytes = body_obj:getBytes(0, body_obj:length())
    request_handle:logCritical("Body:"..body_bytes)
  end
end

その結果，以下のログが得られた．

2023-01-16T02:33:24.955013Z	critical	envoy lua	script log: Hello World 12
2023-01-16T02:33:24.955067Z	critical	envoy lua	script log: Body:{"id":"3395a43e-2d88-40de-b95f-e00e1502085b","quantity":"1"}
2023-01-16T02:33:25.147389Z	critical	envoy lua	script log: Hello World 12
2023-01-16T02:33:25.182442Z	critical	envoy lua	script log: Hello World 12
2023-01-16T02:33:25.186764Z	critical	envoy lua	script log: Hello World 12

JSONのパース

EnvoyにはJSONのパーサが内包されていない．そのため，コンテナ外からJSONパーサのLua実装をコンテナ内に追加する必要がある．

[Question] How can I filter json body in lua? · Issue #8251 · envoyproxy/envoy

一般に以下のJSONパーサを使っている．

rxi/json.lua: A lightweight JSON library for Lua

以下の記事はIstioにJSONパーサを追加する方法を紹介している．

ibm-cloud-architecture/tutorial-istio-envoy-lua-filters

ConfigMapでjson-luaを作成する．構成ファイルは上記のConfig Mapを流用する．

$ kubectl get configmap -n istio-system
NAME                                  DATA   AGE
kube-root-ca.crt                      1      11d
istio-ca-root-cert                    1      11d
istio                                 2      40h
istio-sidecar-injector                2      40h
lua-libs                              2      26s
istio-gateway-deployment-leader       0      11d
istio-gateway-status-leader           0      11d
istio-namespace-controller-election   0      11d
istio-leader                          0      11d

IstioのIngress Gatewayを以下のコマンドで変更する．

kubectl edit deployment istio-ingressgateway -n istio-system

変更箇所(1) proxyのコンテナのvolumeMountsを編集する．

volumeMounts:
- mountPath: /var/lib/lua
  name: config-volume-lua

変更箇所(2) proxyのコンテナのVolumeを編集する．

volumes:
- name: config-volume-lua
  configMap:
    name: lua-libs
    items:
    - key: JSON.lua
      path: JSON.lua
    - key: uuid.lua
      path: uuid.lua

上記の手順で作業するも，luaスクリプトはistio-proxyに配置されず． GitHubにある他のコードを見ると以下のようにIstio Gatewayにセットすることを想定した実装にみえる． そのため，Istio Proxyには変更が適用されていないと思われる．

spec:
  filters:
  - listenerMatch:
      portNumber: 80
      listenerType: GATEWAY
      listenerProtocol: HTTP

Istioのサイドカープロキシの構成を変更する方法がないか調査したところ以下を発見した．

Istio / Installing the Sidecar

kubectl -n istio-system get configmap istio-sidecar-injector -o=jsonpath='{.data.config}' > inject-config.yaml
kubectl -n istio-system get configmap istio-sidecar-injector -o=jsonpath='{.data.values}' > inject-values.yaml
kubectl -n istio-system get configmap istio -o=jsonpath='{.data.mesh}' > mesh-config.yaml

Istio Proxyのサイドカーのテンプレートを編集する．

vim inject-config.yml

volumesへ以下を追記する．

volumes:
- name: config-volume-lua
  configMap:
    name: lua-libs
    items:
    - key: JSON.lua
      path: JSON.lua
    - key: uuid.lua
      path: uuid.lua

volumeMountsへ以下を追記する．

volumeMounts:
- mountPath: /var/lib/lua
  name: config-volume-lua

Configを適用する．

basedir=custom-istio
istioctl kube-inject \
--injectConfigFile $basedir/inject-config.yml \
--meshConfigFile $basedir/mesh-config.yml \
--valuesFile $basedir/inject-values.yml \
--filename sock-shop/complete-demo.yml > sock-shop/complete-demo-custom.yml

volumeMountsが適用されていないことがわかった．そこで別でyamlを開いて書き換えるコードを作成した．

python istio-customizer.py

IstioにカスタマイズしたSock Shopをデプロイする．

kubectl create namespace sock-shop
kubectl label namespace sock-shop istio-injection=enabled
kubectl apply -f sock-shop/istio-gw.yml

kubectl apply -f sock-shop/complete-demo-custom2.yml

Podが起動できるか確かめる．

koyama@koyama-develop1:~/istio-rbsa$ k get pod
NAME                            READY   STATUS    RESTARTS   AGE
carts-85b8c9bccb-bf2l4          2/2     Running   0          5h55m
carts-db-7548fcbdf5-pdfmd       2/2     Running   0          5h55m
orders-5c8dd9448-d2mbt          2/2     Running   0          5h55m
shipping-7c658d96db-hg49d       2/2     Running   0          5h55m
session-db-54598d79-fg8pm       2/2     Running   0          5h55m
catalogue-db-845c97cd64-56769   2/2     Running   0          5h55m
queue-master-6b889c4c86-c6zlj   2/2     Running   0          5h55m
orders-db-79f77c9ddf-hstgj      2/2     Running   0          5h55m
rabbitmq-55479745f4-rn5tw       3/3     Running   0          5h55m
user-db-7945984dc8-rh5h7        2/2     Running   0          5h55m
front-end-798c6cd544-rpldn      2/2     Running   0          5h55m
catalogue-bc969d685-dtxcm       2/2     Running   0          5h55m
payment-7f657d8fc6-dh6rb        2/2     Running   0          5h55m
user-fb4cd6788-fdk8h            2/2     Running   0          5h55m

PodにLuaがマウントされているか確かめる．

k exec -it front-end-798c6cd544-rpldn -c istio-proxy -- sh

上手くマウントできている．

$ ls /var/lib/lua
JSON.lua  uuid.lua

以下のフィルタを追加してログを確認する．

JSON = (loadfile "/var/lib/lua/JSON.lua")()
function envoy_on_request(request_handle)
  request_handle:logCritical("Hello World 14")
  local body_obj = request_handle:body()
  if body_obj ~= nil then
    local body_bytes = body_obj:getBytes(0, body_obj:length())
    request_handle:logCritical("Body:"..body_bytes)
    local raw_json_text = tostring(body_bytes)
    local lua_value = JSON:decode(raw_json_text)
    request_handle:logCritical("Body:"..tostring(lua_value["id"]))
  end
end

kubectl apply -f my-envoy-filter.yml

ログを確認する．

pod_name=$(kubectl get pod -n sock-shop | grep front-end | awk '{print $1}')
kubectl logs $pod_name -n sock-shop -c istio-proxy | grep lua

Sock Shopでカート追加を行うとログにBodyが書き出されている．またJSONのidのみが取り出せている．

2023-01-21T13:11:37.838986Z	critical	envoy lua	script log: Hello World 14
2023-01-21T13:11:37.839053Z	critical	envoy lua	script log: Body:{"id":"03fef6ac-1896-4ce8-bd69-b798f85c6e0b"}
2023-01-21T13:11:37.839111Z	critical	envoy lua	script log: Body:03fef6ac-1896-4ce8-bd69-b798f85c6e0b
2023-01-21T13:11:39.367154Z	critical	envoy lua	script log: Hello World 14

JSONのデータ個数の集計

lua, for で配列、ハッシュの中身を全部表示する - u16suzuの blog

Luaで再帰的に要素数を数えるコードを作成した．

h = {{a=1, b=2, c=3}, {a=4, b=5, c=6}}
h2 = {a=1, b=2, c=3}

aggre = {}

function element_counts(request_body, depth)
  local counter = 0
  for k,v in pairs(request_body) do
    if type(v) == "table" then
      -- print("dive")
      element_counts(v, depth+1)
    else
      counter = counter + 1
    end
  end
  -- print(counter)
  if aggre[depth] == nil then
    aggre[depth] = counter
  else
    aggre[depth] = counter + aggre[depth]
  end
end

element_counts(h, 1)

for k,v in pairs(aggre) do
  print("depth=", k, "counts=", v)
end

Envoy Filterに完成したLuaコードを組み込み

JSON = (loadfile "/var/lib/lua/JSON.lua")()
aggre = {}
function element_counts(request_handle, request_body, depth)
  request_handle:logCritical("invoke; depth="..tostring(depth))
  local counter = 0
  for k,v in pairs(request_body) do
    if type(v) == "table" then
      counter = counter + 1
      element_counts(request_handle, v, depth+1)
    else
      counter = counter + 1
    end
  end
  if aggre[depth] == nil then
    aggre[depth] = counter
  else
    aggre[depth] = counter + aggre[depth]
  end
end
function envoy_on_request(request_handle)
  request_handle:logCritical("Start envoy_on_request 2")
  local body_obj = request_handle:body()
  if body_obj ~= nil then
    local body_bytes = body_obj:getBytes(0, body_obj:length())
    request_handle:logCritical("Body:"..body_bytes)
    local raw_json_text = tostring(body_bytes)
    local body_json = JSON:decode(raw_json_text)
    element_counts(request_handle, body_json, 0)
    for k,v in pairs(aggre) do
      request_handle:logCritical("depth="..tostring(k).." counts="..tostring(v))
    end
    request_handle:logCritical("reset aggre")
    aggre = {}
  end
end

実際の動作したときのログを以下に示す．

2023-01-22T06:32:13.074107Z	critical	envoy lua	script log: Body:{"key": "value", "key2": {"k":"v"}}
2023-01-22T06:32:13.074149Z	critical	envoy lua	script log: invoke; depth=0
2023-01-22T06:32:13.074167Z	critical	envoy lua	script log: invoke; depth=1
2023-01-22T06:32:13.074172Z	critical	envoy lua	script log: depth=0 counts=2
2023-01-22T06:32:13.074176Z	critical	envoy lua	script log: depth=1 counts=1
2023-01-22T06:32:13.074179Z	critical	envoy lua	script log: reset aggre

以下のcurlコマンドでHTTPリクエストを送信している．

curl -XPOST -d '{"key": "value", "key2": {"k":"v"}}' http://192.168.5.208/

ログへの拡張フィールドの書き出し

拡張フィールドをHTTPヘッダに追加する．

Lua — envoy 1.26.0-dev-f0fdc8 documentation

request_handle:headers():add("log-suffix", log_suffix)

ログフォーマットをカスタマイズする．

Istio / Envoy Access Logs

Access logging — envoy 1.26.0-dev-f0fdc8 documentation

%REQ(X?Y):Z%が任意のヘッダのロギングに使えるそう．Istioのデフォルトのログ形式にも同様の記述がある．

istioctl install --set profile=default -y --set meshConfig.accessLogFile=/dev/stdout --set meshConfig.accessLogFormat='[%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% %REQ(LOG-SUFFIX)%'

ログに書き出すべき属性はHTTPリクエストのヘッダではなくHTTPレスポンスだと気づいた．そのため修正する．

istioctl install --set profile=default -y --set meshConfig.accessLogFile=/dev/stdout --set meshConfig.accessLogFormat='[%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% %RESP(LOG-SUFFIX)%'

EnvoyFilterの適用先がWorkloadSelectorで限定されているので，解除する． なお，WorkloadSelectorは必須のフィールドではないため，指定がなければすべてのリソースに適用される．

NOTE 3: To apply an EnvoyFilter resource to all workloads (sidecars and gateways) in the system, define the resource in the config root namespace, without a workloadSelector.

Istio / Envoy Filter

apiVersion: networking.istio.io/v1alpha3
kind: EnvoyFilter
metadata:
  name: front-end-lua
  namespace: sock-shop
spec:
  ## workloadSelector:
  ##   labels:
  ##     name: front-end

ログを確認してみると，カート追加時にログが追加で書き出されたことが確認できた．これは，cartのマイクロサービスのIstio ProxyがLuaでHTTPレスポンスから計算したRBSIをHTTPヘッダのLOG-SUFFIXに渡したことで，frontendサービスでHTTPレスポンスヘッダを受け取れ，書き出せたことで実現できている．

[2023-01-24T00:35:56.555Z] "POST /cart HTTP/1.1" 201 - via_upstream - "-" 45 0 33 32 "10.42.0.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/109.0.0.0 Safari/537.36" "4f2d327d-bc21-427a-829e-b8c3f0a4a85e" "192.168.5.208" "10.42.0.206:8079" inbound|8079|| 127.0.0.6:44855 10.42.0.206:8079 10.42.0.1:0 outbound_.80_._.front-end.sock-shop.svc.cluster.local default 1

適用の対象はHTTPレスポンスであるため，修正をする．関数名をenvoy_on_responseに変更する．

-- Called on the response path.
function envoy_on_response(response_handle)
  -- Do something.
  end

同様にログを書き出せた．

2023-01-24T11:57:38.144478Z	critical	envoy lua	script log: Body2:[{"id":"3395a43e-2d88-40de-b95f-e00e1502085b","name":"Colourful","description":"proident occaecat irure et excepteur labore minim nisi amet irure","imageUrl":["/catalogue/images/colourful_socks.jpg","/catalogue/images/colourful_socks.jpg"],"price":18,"count":438,"tag":["brown"]},{"id":"837ab141-399e-4c1f-9abc-bace40296bac","name":"Cat socks","description":"consequat amet cupidatat minim laborum tempor elit ex consequat in","imageUrl":["/catalogue/images/catsocks.jpg","/catalogue/images/catsocks2.jpg"],"price":15,"count":175,"tag":["brown"]},{"id":"zzz4f044-b040-410d-8ead-4de0446aec7e","name":"Classic","description":"Keep it simple.","imageUrl":["/catalogue/images/classic.jpg","/catalogue/images/classic2.jpg"],"price":12,"count":127,"tag":["brown"]}]
2023-01-24T11:57:38.144738Z	critical	envoy lua	script log: invoke; depth=1
2023-01-24T11:57:38.144750Z	critical	envoy lua	script log: invoke; depth=2
2023-01-24T11:57:38.144755Z	critical	envoy lua	script log: invoke; depth=3
2023-01-24T11:57:38.144759Z	critical	envoy lua	script log: invoke; depth=3
2023-01-24T11:57:38.144764Z	critical	envoy lua	script log: invoke; depth=2
2023-01-24T11:57:38.144768Z	critical	envoy lua	script log: invoke; depth=3
2023-01-24T11:57:38.144872Z	critical	envoy lua	script log: invoke; depth=3
2023-01-24T11:57:38.144881Z	critical	envoy lua	script log: invoke; depth=2
2023-01-24T11:57:38.144885Z	critical	envoy lua	script log: invoke; depth=3
2023-01-24T11:57:38.144889Z	critical	envoy lua	script log: invoke; depth=3
2023-01-24T11:57:38.144896Z	critical	envoy lua	script log: 3, 21, 9
2023-01-24T11:57:38.168217Z	critical	envoy lua	script log: Received
2023-01-24T11:57:38.169226Z	critical	envoy lua	script log: Start envoy_on_response 1

[2023-01-24T11:57:38.133Z] "GET /catalogue?sort=id&size=3&tags=brown HTTP/1.1" 200 - via_upstream - "-" 0 760 11 10 "10.42.0.1" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/109.0.0.0 Safari/537.36" "7cbc0a6d-2516-477a-a79b-3a8b68cc475c" "192.168.5.208" "10.42.0.34:8079" inbound|8079|| 127.0.0.6:42331 10.42.0.34:8079 10.42.0.1:0 outbound_.80_._.front-end.sock-shop.svc.cluster.local default 3, 21, 9