id:nekop です。この記事はOpenShift Advent Calendar 2024のエントリです。
最初に結論を書いておきます。OpenShift Logging ClusterLogForwarderでのVector AtLeastOnce設定はちょっとログ生成が多いタイミングがあってもログロストしない、ログ転送スループットは10MB/sくらい、対応できるログ生成レートは5k lines/sくらい、です。
OpenShift Logging 5.9から ClusterLogForwarder のVectorにTuning項目が指定できるようになっています。6.1のAPIでは以下のようにoutputsの各type配下に定義します。
$ oc explain ClusterLogForwarder.spec.outputs.http.tuning
GROUP: observability.openshift.io
KIND: ClusterLogForwarder
VERSION: v1
FIELD: tuning <Object>
DESCRIPTION:
Tuning specs tuning for the output
FIELDS:
compression <string>
enum: none, gzip, snappy, zlib
Compression causes data to be compressed before sending over the network.
deliveryMode <string>
enum: AtLeastOnce, AtMostOnce
DeliveryMode sets the delivery mode for log forwarding.
maxRetryDuration <integer>
MaxRetryDuration is the maximum time to wait between retry attempts after a
delivery failure.
maxWrite <Object>
MaxWrite limits the maximum payload in terms of bytes of a single "send" to
the output.
minRetryDuration <integer>
MinRetryDuration is the minimum time to wait between attempts to retry after
delivery a failure.
この中で今回注目する項目は deliveryMode で、旧来の動作である AtMostOnce の他に、新しい指定となる AtLeastOnce が選択できます。
デフォルトの AtMostOnce ではSink(出力先)のバッファはmax_events=500のin-memory bufferで、バッファがフルになったときのアクションはwhen_full=drop_newestとなっています。つまり、500 eventsを超えてSourceから読み込まれてバッファに積まれようとしたログは即座に捨てられます。ログを大量に出力するPodをデプロイした、といったときに、かなりの量のログがロストします。逆に言うと、ログのバースト出力はほとんど捨てることになるので、ログ転送が詰まったり、リソース100%利用で張り付いたり、ログ転送先を高負荷にしてしまって結果全ノードやシステム全体に影響したり、といった様々な問題の発生を抑止できることになります。
新しい設定である AtLeastOnce ではSink(出力先)のバッファは256MBのdisk bufferになり、バッファがフルになったときのアクションはwhen_full=blockとなります。バッファフルの状況となった場合はSourceのログ読み込みが停止することになります。AtLeastOnceでもログ生成の速度がログ転送の速度を上回ったままの状態が継続するとログファイルのローテーションの都合でログはロストします。OpenShiftではコンテナのログファイルはデフォルト50Miでローテーションされます。ログローテーションされて現在のファイルの名前が変更されたり、削除されたとしても、ログ読み込みのプロセスはオープン中のファイルディスクリプタをファイルの終端まで継続して読みつづけることができるため、一回のローテーションでは問題にはなりません。Vectorのログファイルの読み込みは現在のファイルの処理が終わってから次の新規ファイルを読む、という動作をするので、ログ読み込みがブロックされたままローテーションが2回発生すると、まったく読む機会のないままローテーションされてVectorが検知できない、読み込み対象ではなくなってしまうログファイルが発生します。また、AtMostOnceの場合はログを大量に生成しているわけではない他のコンテナのログも巻き込まれてロストしますが、AtLeastOnceではログファイルのローテーションをトリガーとしてログファイル単位でロストすることになるので、基本的には大量のログを出力しているコンテナのみがログロストの対象となります。
どちらの設定にしても、ログ生成スピードがログ転送スピードより速い場合はログ転送が追いつかない状況となり、ログロストが発生します。この部分について見ていきましょう。
ログ生成は例えばshell scriptシングルスレッドループecho出力で100k lines/sほどの量が簡単に生成できます。ログ転送でのペイロードはほぼ空のメッセージのログでもメタデータがいろいろついて2kbくらいになるので、ログ行数100kの場合のログ転送量は200MBくらいになります。
VectorのAtLeastOnceでのログ転送スループットは10MB/sくらいなので、上記をベースに逆算するとバッファに貯まらないログ生成量は5k lines/sくらいです。ノード上の全コンテナ合計のログ生成レートがこれ以上ある場合、ログロストを防止するためにはコンテナ側でログ出力を抑止したり、ログ転送時にフィルタしたりといった対応が必要になります。ちなみに古いOpenShift Loggingで利用されていたfluentd構成ではログ転送の速度はVector AtLeastOnceの1/10である1MB/s程度であり、ログローテーションの速度に追いつかなくてログロスト発生する報告がかなり多かったのでした。
実際にログ転送のテストをした様子を観察してみましょう。環境はOpenShift 4.16.24 AWS IPI ap-northeast-1d, Control plane m6a.xlarge (4vCPU, 16GB mem) * 3、workerなしの3 Node Compact Cluster構成, OpenShift Logging 6.1.0です。
以下の3つのコンポーネントを作成します。
- DaemonSet/logproducer: ログ生成を行うDaemonSet
- ClusterLogForwarder/logperf-collector: ログ転送を行うClusterLogForwarder
- deploy/vector-http: ログ転送先となるVector
test-logperfというnamespaceを作成、vector-httpというhttpでログを受けてファイルにログを吐くカスタムのVectorコンテナをログ転送先とします。DaemonSet/logproducerは単にカウンタをログ出力するだけのPodで、1M行のログを出力します。有効化、無効化はnodeSelectorで制御します。ClusterLogForwarderでの転送元のログはlogproducer podに絞ります。
TARGET_PROJECT=test-logperf
oc new-project $TARGET_PROJECT
oc -n $TARGET_PROJECT create sa app-log-collector
oc -n $TARGET_PROJECT adm policy add-cluster-role-to-user collect-application-logs -z app-log-collector
oc -n $TARGET_PROJECT create -f - <<EOF
apiVersion: observability.openshift.io/v1
kind: ClusterLogForwarder
metadata:
name: logperf-collector
spec:
serviceAccount:
name: app-log-collector
collection:
type: vector
inputs:
- name: logperf
type: application
application:
namespaces:
- test-logperf
filters:
- name: only-logproducer
type: drop
drop:
- test:
- field: .kubernetes.labels."app"
notMatches: "logproducer"
outputs:
- name: ext-vector-http
type: http
http:
url: 'http://vector-http.$TARGET_PROJECT.svc:8080'
tuning:
deliveryMode: AtLeastOnce
pipelines:
- name: forward-to-ext-vector-http
inputRefs:
- logperf
outputRefs:
- ext-vector-http
filterRefs:
- only-logproducer
EOF
cat <<EOF > vector.toml
expire_metrics_secs = 60
[api]
enabled = true
[sources.http_server_source]
type = "http_server"
address = "0.0.0.0:8080"
decoding.codec = "json"
[sinks.file_sink]
type = "file"
inputs = [ "http_server_source" ]
path = "/tmp/vector-%Y-%m-%d.log"
encoding.codec = "json"
EOF
oc -n $TARGET_PROJECT create configmap vector-http --from-file=vector.toml
oc -n $TARGET_PROJECT create deployment vector-http --image=quay.io/openshift-logging/vector:6.1 --port=8080 --replicas=0
oc -n $TARGET_PROJECT set volume deploy/vector-http --add --name=vector-http-config --configmap-name=vector-http --mount-path=/etc/vector
oc -n $TARGET_PROJECT expose deploy/vector-http
oc -n $TARGET_PROJECT patch deploy/vector-http -p 'spec:
template:
spec:
containers:
- name: vector
command:
- /usr/bin/vector
- --config
- /etc/vector/vector.toml'
oc -n $TARGET_PROJECT scale deploy/vector-http --replicas=1
oc create deployment logproducer --image=registry.access.redhat.com/ubi9/ubi:9.4 --replicas=0 --dry-run=client -o yaml | sed -e 's/Deployment/DaemonSet/' | oc create -f -
oc patch daemonset logproducer -p 'spec:
template:
spec:
nodeSelector:
foo: bar
terminationGracePeriodSeconds: 1
containers:
- name: ubi
command:
- /bin/bash
- -c
- |
#!/bin/bash
date > /tmp/start
for i in {1..1000000}; do
echo $i
done
date > /tmp/end
exec tail -f /dev/null'
このスクリプトを実行すると各コンポーネントが作成されます。DaemonSet/logproducerは最初はマッチしないnodeSelectorを指定しているので、このステップではPodは作成されません。
$ oc get ds,pod NAME DESIRED CURRENT READY UP-TO-DATE AVAILABLE NODE SELECTOR AGE daemonset.apps/logperf-collector 3 3 3 3 3 kubernetes.io/os=linux 37s daemonset.apps/logproducer 0 0 0 0 0 foo=bar 2m38s NAME READY STATUS RESTARTS AGE pod/logperf-collector-85k9l 1/1 Running 0 37s pod/logperf-collector-9nqfj 1/1 Running 0 37s pod/logperf-collector-nzb27 1/1 Running 0 37s pod/vector-http-6ccddf74f5-pw2cw 1/1 Running 0 6s
ログ生成して転送してみます。各ノード1M linesのログで2GBほどの転送量があり、150秒ほどログ転送が継続します。
$ oc -n $TARGET_PROJECT patch daemonset/logproducer --type json -p '[{"op":"remove","path":"/spec/template/spec/nodeSelector"}]'
結果を確認していきましょう。転送先の出力ファイル、生のコンテナログファイル、Vectorのディスクを確認していきます。
# 転送先確認、3M lines 5.8GBを156秒でファイル出力
$ oc -n $TARGET_PROJECT exec $(oc -n $TARGET_PROJECT get pod -l app=vector-http --no-headers -o name) -- sh -c "ls -hla /tmp; stat /tmp/vector*.log; wc -l /tmp/vector*.log; head -n1 /tmp/vector*.log; tail -1 /tmp/vector*.log"
total 5.8G
drwxrwxrwt. 1 root root 35 Dec 3 02:08 .
dr-xr-xr-x. 1 root root 39 Dec 3 01:46 ..
-rw-r--r--. 1 1000750000 root 5.8G Dec 3 02:10 vector-2024-12-03.log
File: /tmp/vector-2024-12-03.log
Size: 6183657496 Blocks: 12077472 IO Block: 4096 regular file
Device: 300091h/3145873d Inode: 144116618 Links: 1
Access: (0644/-rw-r--r--) Uid: (1000750000/1000750000) Gid: ( 0/ root)
Access: 2024-12-03 02:08:09.698688637 +0000
Modify: 2024-12-03 02:10:45.767486134 +0000
Change: 2024-12-03 02:10:45.767486134 +0000
Birth: 2024-12-03 02:08:09.698688637 +0000
3000000 /tmp/vector-2024-12-03.log
{"@timestamp":"2024-12-03T02:08:03.064174456Z","hostname":"ip-10-0-46-252.ap-northeast-1.compute.internal","kubernetes":{"annotations":{"k8s.ovn.org/pod-networks":"{\"default\":{\"ip_addresses\":[\"10.129.0.64/23\"],\"mac_address\":\"0a:58:0a:81:00:40\",\"gateway_ips\":[\"10.129.0.1\"],\"routes\":[{\"dest\":\"10.128.0.0/14\",\"nextHop\":\"10.129.0.1\"},{\"dest\":\"172.30.0.0/16\",\"nextHop\":\"10.129.0.1\"},{\"dest\":\"100.64.0.0/16\",\"nextHop\":\"10.129.0.1\"}],\"ip_address\":\"10.129.0.64/23\",\"gateway_ip\":\"10.129.0.1\"}}","k8s.v1.cni.cncf.io/network-status":"[{\n \"name\": \"ovn-kubernetes\",\n \"interface\": \"eth0\",\n \"ips\": [\n \"10.129.0.64\"\n ],\n \"mac\": \"0a:58:0a:81:00:40\",\n \"default\": true,\n \"dns\": {}\n}]","openshift.io/scc":"restricted-v2","seccomp.security.alpha.kubernetes.io/pod":"runtime/default"},"container_id":"cri-o://52d56dd1775b20999d5a9295798f3802100cc7b2f34948308f7401665e6ffb22","container_image":"registry.access.redhat.com/ubi9/ubi:9.4","container_image_id":"registry.access.redhat.com/ubi9/ubi@sha256:970d60bb110b60c175f5b261596957a6c8ccfbd0b252d6a1d28b1655d25cb3a8","container_iostream":"stdout","container_name":"ubi","labels":{"app":"logproducer","controller-revision-hash":"67855d8d76","pod-template-generation":"3"},"namespace_id":"771ef9a2-9308-47b0-8ba6-b0a2548f9119","namespace_labels":{"kubernetes_io_metadata_name":"test-logperf","pod-security_kubernetes_io_audit":"privileged","pod-security_kubernetes_io_audit-version":"v1.24","pod-security_kubernetes_io_warn":"privileged","pod-security_kubernetes_io_warn-version":"v1.24"},"namespace_name":"test-logperf","pod_id":"f8035995-5988-46dc-a7a7-bff2ed82ed7a","pod_ip":"10.129.0.64","pod_name":"logproducer-kqt6q","pod_owner":"DaemonSet/logproducer"},"level":"default","log_source":"container","log_type":"application","message":"1","openshift":{"cluster_id":"a4e39017-6292-4e8d-9f55-8cc36ec5483c","sequence":1733191688532906012},"path":"/","source_type":"http_server","timestamp":"2024-12-03T02:08:09.639301026Z"}
{"@timestamp":"2024-12-03T02:08:06.775781632Z","hostname":"ip-10-0-20-197.ap-northeast-1.compute.internal","kubernetes":{"annotations":{"k8s.ovn.org/pod-networks":"{\"default\":{\"ip_addresses\":[\"10.128.0.102/23\"],\"mac_address\":\"0a:58:0a:80:00:66\",\"gateway_ips\":[\"10.128.0.1\"],\"routes\":[{\"dest\":\"10.128.0.0/14\",\"nextHop\":\"10.128.0.1\"},{\"dest\":\"172.30.0.0/16\",\"nextHop\":\"10.128.0.1\"},{\"dest\":\"100.64.0.0/16\",\"nextHop\":\"10.128.0.1\"}],\"ip_address\":\"10.128.0.102/23\",\"gateway_ip\":\"10.128.0.1\"}}","k8s.v1.cni.cncf.io/network-status":"[{\n \"name\": \"ovn-kubernetes\",\n \"interface\": \"eth0\",\n \"ips\": [\n \"10.128.0.102\"\n ],\n \"mac\": \"0a:58:0a:80:00:66\",\n \"default\": true,\n \"dns\": {}\n}]","openshift.io/scc":"restricted-v2","seccomp.security.alpha.kubernetes.io/pod":"runtime/default"},"container_id":"cri-o://938d549f836e6d4105339c92810e9c3904cba0771a2a40388f16b8f5130dcb82","container_image":"registry.access.redhat.com/ubi9/ubi:9.4","container_image_id":"registry.access.redhat.com/ubi9/ubi@sha256:970d60bb110b60c175f5b261596957a6c8ccfbd0b252d6a1d28b1655d25cb3a8","container_iostream":"stdout","container_name":"ubi","labels":{"app":"logproducer","controller-revision-hash":"67855d8d76","pod-template-generation":"3"},"namespace_id":"771ef9a2-9308-47b0-8ba6-b0a2548f9119","namespace_labels":{"kubernetes_io_metadata_name":"test-logperf","pod-security_kubernetes_io_audit":"privileged","pod-security_kubernetes_io_audit-version":"v1.24","pod-security_kubernetes_io_warn":"privileged","pod-security_kubernetes_io_warn-version":"v1.24"},"namespace_name":"test-logperf","pod_id":"642ed500-490b-497c-bafc-170308754347","pod_ip":"10.128.0.102","pod_name":"logproducer-2zwng","pod_owner":"DaemonSet/logproducer"},"level":"default","log_source":"container","log_type":"application","message":"1000000","openshift":{"cluster_id":"a4e39017-6292-4e8d-9f55-8cc36ec5483c","sequence":1733191842616457947},"path":"/","source_type":"http_server","timestamp":"2024-12-03T02:10:45.708882902Z"}
# 生ログ確認
$ oc -n $TARGET_PROJECT exec $(oc -n $TARGET_PROJECT get pod -l app.kubernetes.io/component=collector --no-headers -o name | head -n1) -- sh -c "ls -l /var/log/pods/test-logperf_logproducer-*/ubi/0.log; head -n1 /var/log/pods/test-logperf_logproducer-*/ubi/0.log; tail -n1 /var/log/pods/test-logperf_logproducer-*/ubi/0.log"
-rw-------. 1 root root 51888896 Dec 3 02:08 /var/log/pods/test-logperf_logproducer-xsskx_85679f37-c4a5-40f8-bc31-3d24268d7350/ubi/0.log
2024-12-03T02:08:03.077703851+00:00 stdout F 1
2024-12-03T02:08:06.643391132+00:00 stdout F 1000000
# Vectorのcheckpointファイルとdisk buffer確認
$ oc -n $TARGET_PROJECT exec $(oc -n $TARGET_PROJECT get pod -l app.kubernetes.io/component=collector --no-headers -o name | head -n1) -- ls -lR /var/lib/vector/
/var/lib/vector/:
total 0
drwxr-xr-x. 3 root root 31 Dec 3 01:45 test-logperf
/var/lib/vector/test-logperf:
total 0
drwxr-xr-x. 4 root root 51 Dec 2 04:52 logperf-collector
/var/lib/vector/test-logperf/logperf-collector:
total 0
drwxr-xr-x. 3 root root 16 Dec 2 04:52 buffer
drwxr-xr-x. 2 root root 30 Dec 3 02:09 input_logperf_container
/var/lib/vector/test-logperf/logperf-collector/buffer:
total 0
drwxr-xr-x. 3 root root 36 Dec 2 04:52 v2
/var/lib/vector/test-logperf/logperf-collector/buffer/v2:
total 0
drwxr-xr-x. 2 root root 68 Dec 3 02:10 output_ext_vector_http
/var/lib/vector/test-logperf/logperf-collector/buffer/v2/output_ext_vector_http:
total 14544
-rw-r-----. 1 root root 14886288 Dec 3 02:09 buffer-data-74.dat
-rw-r-----. 1 root root 24 Dec 3 02:10 buffer.db
-rw-r--r--. 1 root root 0 Dec 3 01:45 buffer.lock
/var/lib/vector/test-logperf/logperf-collector/input_logperf_container:
total 4
-rw-r--r--. 1 root root 2120 Dec 3 02:09 checkpoints.json
テストを繰り返すときはdaemonset/logproducer停止、vector-http podの再作成、optionalでcollector podの再作成、daemonset/logproducer開始です。
$ oc -n $TARGET_PROJECT patch daemonset/logproducer --type json -p '[{"op":"add","path":"/spec/template/spec/nodeSelector","value":{"foo":"bar"}}]'
$ oc -n $TARGET_PROJECT delete pod -l app=vector-http
$ oc -n $TARGET_PROJECT delete pod -l app.kubernetes.io/component=collector
$ oc -n $TARGET_PROJECT edit daemonset/logproducer # ログ生成量の変更など必要があれば設定変更
$ oc -n $TARGET_PROJECT patch daemonset/logproducer --type json -p '[{"op":"remove","path":"/spec/template/spec/nodeSelector"}]'
