Istioのログ機能のカスタマイズ(Lua)
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スクリプトを追加して任意の操作をリクエスト処理の途中に差し込む機能があり，それを使ってロギングしている事例があった．
Luaスクリプトを組み込んだEnvoyプロキシのコンテナイメージを作りIstioで使う方法が簡単に思いついた．Istioのソースコードを追いかけるのは大変そうなので，できれば簡単にできる方法がほかにないか調査してみる．
IstioのEnvoyFilter
以下はEnvoyにあるFIlterをIstioで使う方法が書いてあった．
上記のドキュメントに書いてあった以下の記述は，まさにやりたいことを表している．
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公式の構成ファイルを参照するのが最適だと思う．
- Envoyのドキュメント
- 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でログを書き出すコード
```yaml:my-envoy-filter.yml 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](https://www.envoyproxy.io/docs/envoy/latest/configuration/http/http_filters/lua_filter#script-examples)
Luaスクリプトを以下に修正して実行してみる．
```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エンジニア ブログ
以下の記事は見つけたものの古いため，参考にならなかった．
以下にスクリプトを変更した．
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
- Envoy Filter
- tutorial-istio-envoy-lua-filters/envoy-filter.yaml
- Config Map (Luaパーサを含む)
- tutorial-istio-envoy-lua-filters/configmap-istio-system.yaml
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)
ログフォーマットをカスタマイズする．
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.
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