MinikubeのEFK AddonのFluentdの設定を読む

はじめに

Fluentdの設定がよくわかってなかったので、今更ながら入門してみる。
サンプルとしたのはMinikubeのEFK Addonで導入されるFluentdの設定ファイル諸々。

Fluentdのバージョンは0.12なので古い。
別の議論として、どのバージョンのFluentdを使うか、みたいなのはあると思う。

設定ファイルの取得

• Minikube
  • v1.9.2
• Kubernetes
  • v1.18.0

EFK Addonをenableにする。
Minikube起動時にenableにする場合は

minikube start --addons=efk

すでに起動済みのMinikubeに追加する場合は

minikube addons enable efk

でOK。
EFK Stackが立ち上がったら、下記コマンドで設定ファイルをとってくる

kubectl get configmap fluentd-es-config -n kube-system -o yaml

設定ファイルを眺める

ConfigMapには5つのファイルが入っていた。
それぞれ眺めてみる。

containers.input.conf

# Container Runtime Interfaceでログ出力の形はルール化されている模様
# multi_formatのパターンはこれを示しているのかも。
# CRI Log Example:
# 2016-02-17T00:04:05.931087621Z stdout [info:2016-02-16T16:04:05.930-08:00] Some log text here
<source>
  # tail Plugin(https://docs.fluentd.org/v/0.12/input/tail)
  # tail -Fコマンドのようなイメージ
  type tail

  # 読み込む対象のファイル
  # /var/log/containersはkubeletがsymlinkおいてる場所（だと思う）
  path /var/log/containers/*.log

  # fluentdがどこまで読んだかを記録しておくためのファイル
  pos_file /var/log/es-containers.log.pos

  # 時刻のフォーマット
  time_format %Y-%m-%dT%H:%M:%S.%NZ

  # Routingのためのタグ設定
  # 「*」をつけると、ファイル名ベースでタグ生成する
  # path /path/to/fileなら、'kubernetes.path.to.file'のような感じ
  tag kubernetes.*

  # ファイルの先頭から読むかどうかの設定
  read_from_head true

  # Multi format parser pluginの設定
  # http://repeatedly.github.io/ja/2014/07/release-fluent-plugin-multi-format-parser/
  # <pattern>を上から順番に試して、パース出来たらその結果を返す（らしい）
  format multi_format
  <pattern>
    format json
    time_key time
    time_format %Y-%m-%dT%H:%M:%S.%NZ
  </pattern>
  <pattern>
    format /^(?<time>.+)\b(?<stream>stdout|stderr)\b(?<log>.*)$/
    time_format %Y-%m-%dT%H:%M:%S.%N%:z
  </pattern>
</source>

主にコンテナ周りのログ設定。
一番お世話になりそうなところ。

Multi format parserのjsonの方は使われるんだろうか。
CRIのLogレイアウトが先頭にコメントにあるような形であれば、基本的には下のpatternが適用されるように見える。

forward.input.conf

# Takes the messages sent over TCP
<source>
  # forward Plugin [https://docs.fluentd.org/v/0.12/input/forward]
  # このPluginでTCPソケットから受け付ける
  # Default Port : 24224
  # Default Bind Adress : 0.0.0.0
  type forward
</source>

TCPソケットからメッセージを受信する設定。
ドキュメントを見るとFluentd to Fluentdなやりとりで利用されるようだが、DaemonSetで稼働しているFluentdに対してそのようなユースケースがあるかはちょっと思いつかなかった。

monitoring.conf

# fluent-plugin-prometheus [https://github.com/fluent/fluent-plugin-prometheus]
# Prometheus Exporter Plugin
# input plugin that exports metrics
<source>
  # Prometheusと連携するための設定
  # 他のPrometheus Pluginの情報をここに書かれた設定で公開する
  # Default Port : 24231
  # Default Bind Adress : 0.0.0.0
  # Default Path : /metrics
  @type prometheus
</source>

<source>
  # monitor_agent Plugin [https://docs.fluentd.org/input/monitor_agent]
  # Fluentdのメトリクスを公開するためのプラグイン
  # Default Port : 24220
  # Default Bind Address : 0.0.0.0
  @type monitor_agent
</source>

# monitor_agent Pluginを入力としてprometheus形式にするPlugin？
# input plugin that collects metrics from MonitorAgent
<source>
  @type prometheus_monitor
  <labels>
    host ${hostname}
  </labels>
</source>

# output Pluginに特化したメトリクス収集の設定
# num_errors、retry_waitなどのprometheus_monitorに含まれないようなメトリクスを収集する
# input plugin that collects metrics for output plugin
<source>
  @type prometheus_output_monitor
  <labels>
    host ${hostname}
  </labels>
</source>

# tail Pluginの内部メトリクスを収集するための設定。
# tail Pluginが正しく動いているかなどの情報が収集される模様。
# input plugin that collects metrics for in_tail plugin
<source>
  @type prometheus_tail_monitor
  <labels>
    host ${hostname}
  </labels>
</source>

メトリクス、Prometheus関連の設定。プラグイン自体が正しく機能しているか情報収集する。

output.conf

# kubernetes_metadata Pluginの設定
# このPluginによってNamespaceやannotationといったmetadataが付与される
# Enriches records with Kubernetes metadata
<filter kubernetes.**>
  type kubernetes_metadata
</filter>

# 'match **'なので、ContainerのログもsystemdのログもすべてElasticSearchに送られる
<match **>
  # Elasticserach Plugin [https://github.com/uken/fluent-plugin-elasticsearch]
  # Elasticsearchに送るための設定
  type elasticsearch

  # このPlugin（Elasticsearch）のログレベルの設定
  log_level info

  # tagをレコードに含めるかどうか
  include_tag_key true

  # Elasticsearchのホスト名
  host elasticsearch-logging

  # ElasticsearchのPort番号
  port 9200

  # Elasticsearchに送る際のindex名をlogstash formatにするかどうか
  # 'ture'の場合は'logstash-%Y,%m,%d'で送られる
  # index名をコントロールしたいときは、index_nameを使えば良さそう
  # （OpenShift 4.xのCluster Loggingでindex名が'.project'みたいになっていたのはここら辺の設定なのかも）
  logstash_format true

  # Bufferの設定 [https://docs.fluentd.org/v/0.12/buffer]
  # 参考[https://qiita.com/tatsu-yam/items/bd7006e483f3b3c64309]
  # 上記サイトの図がわかりやすい。
  # Set the chunk limits.
  buffer_chunk_limit 2M
  buffer_queue_limit 8
  flush_interval 5s

  # リトライの感覚は指数関数的に増えるような仕組みになっているが、それの上限を決める設定
  # （'5 minutes between retries'とあるが、30秒に設定されている。本当は300秒では？）
  # Never wait longer than 5 minutes between retries.
  max_retry_wait 30

  # ずっとリトライし続ける
  # レコードがサーバ側に増えていくので、その考慮は別途必要
  # Disable the limit on the number of retries (retry forever).
  disable_retry_limit

  # Queueに入ったchunkを処理するときのスレッド数
  # Use multiple threads for processing.
  num_threads 2
</match>

Elasticsearchへの出力設定。バッファリングなどの設定も入っているので、このあたりのチューニングは結構むずかしそう。

system.input.conf

主にNode上で直接稼働するプロセスに対する処理が多い。
下記に設定はされているものの、VirtualVoxでMinikubeを立てた場合には出力されていないログもちらほらあった。
etcd/kube-apiserverなどの設定もあるが、これらのコンポーネントはPodとして起動しているので、containers.input.confに記載された方法で収集されるんじゃないかと思う。（以前はMinikube VM上に直接立ってたとかかも？）

# Example:
# 2015-12-21 23:17:22,066 [salt.state       ][INFO    ] Completed state [net.ipv4.ip_forward] at time 23:17:22.066081
<source>
  type tail
  format /^(?<time>[^ ]* [^ ,]*)[^\[]*\[[^\]]*\]\[(?<severity>[^ \]]*) *\] (?<message>.*)$/
  time_format %Y-%m-%d %H:%M:%S
  # salt minionってなんだろうと思って調べたら下記とのこと
  # [https://unofficial-kubernetes.readthedocs.io/en/latest/admin/salt/]
  path /var/log/salt/minion
  pos_file /var/log/es-salt.pos
  tag salt
</source>

# Example:
# Dec 21 23:17:22 gke-foo-1-1-4b5cbd14-node-4eoj startupscript: Finished running startup script /var/run/google.startup.script
<source>
  type tail
  format syslog
  path /var/log/startupscript.log
  pos_file /var/log/es-startupscript.log.pos
  tag startupscript
</source>

# Examples:
# time="2016-02-04T06:51:03.053580605Z" level=info msg="GET /containers/json"
# time="2016-02-04T07:53:57.505612354Z" level=error msg="HTTP Error" err="No such image: -f" statusCode=404
<source>
  type tail
  format /^time="(?<time>[^)]*)" level=(?<severity>[^ ]*) msg="(?<message>[^"]*)"( err="(?<error>[^"]*)")?( statusCode=($<status_code>\d+))?/
  # Dockerプロセスのログ収集
  # 他のランタイムにした場合は、このあたりのカスタマイズも必要になると思う
  path /var/log/docker.log
  pos_file /var/log/es-docker.log.pos
  tag docker
</source>

# Example:
# 2016/02/04 06:52:38 filePurge: successfully removed file /var/etcd/data/member/wal/00000000000006d0-00000000010a23d1.wal
<source>
  type tail
  # Not parsing this, because it doesn't have anything particularly useful to
  # parse out of it (like severities).
  format none
  path /var/log/etcd.log
  pos_file /var/log/es-etcd.log.pos
  tag etcd
</source>

# Multi-line parsing is required for all the kube logs because very large log
# statements, such as those that include entire object bodies, get split into
# multiple lines by glog.

# Example:
# I0204 07:32:30.020537    3368 server.go:1048] POST /stats/container/: (13.972191ms) 200 [[Go-http-client/1.1] 10.244.1.3:40537]
<source>
  type tail
  # 複数行を読むためのformat設定
  # （Javaのスタックとレースとかもこれをうまく使えばできるのだろうか）
  format multiline
  multiline_flush_interval 5s
  format_firstline /^\w\d{4}/
  format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/
  time_format %m%d %H:%M:%S.%N
  path /var/log/kubelet.log
  pos_file /var/log/es-kubelet.log.pos
  tag kubelet
</source>

# Example:
# I1118 21:26:53.975789       6 proxier.go:1096] Port "nodePort for kube-system/default-http-backend:http" (:31429/tcp) was open before and is still needed
<source>
  type tail
  format multiline
  multiline_flush_interval 5s
  format_firstline /^\w\d{4}/
  format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/
  time_format %m%d %H:%M:%S.%N
  path /var/log/kube-proxy.log
  pos_file /var/log/es-kube-proxy.log.pos
  tag kube-proxy
</source>

# Example:
# I0204 07:00:19.604280       5 handlers.go:131] GET /api/v1/nodes: (1.624207ms) 200 [[kube-controller-manager/v1.1.3 (linux/amd64) kubernetes/6a81b50] 127.0.0.1:38266]
<source>
  type tail
  format multiline
  multiline_flush_interval 5s
  format_firstline /^\w\d{4}/
  format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/
  time_format %m%d %H:%M:%S.%N
  path /var/log/kube-apiserver.log
  pos_file /var/log/es-kube-apiserver.log.pos
  tag kube-apiserver
</source>

# Example:
# I0204 06:55:31.872680       5 servicecontroller.go:277] LB already exists and doesn't need update for service kube-system/kube-ui
<source>
  type tail
  format multiline
  multiline_flush_interval 5s
  format_firstline /^\w\d{4}/
  format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/
  time_format %m%d %H:%M:%S.%N
  path /var/log/kube-controller-manager.log
  pos_file /var/log/es-kube-controller-manager.log.pos
  tag kube-controller-manager
</source>

# Example:
# W0204 06:49:18.239674       7 reflector.go:245] pkg/scheduler/factory/factory.go:193: watch of *api.Service ended with: 401: The event in requested index is outdated and cleared (the requested history has been cleared [2578313/2577886]) [2579312]
<source>
  type tail
  format multiline
  multiline_flush_interval 5s
  format_firstline /^\w\d{4}/
  format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/
  time_format %m%d %H:%M:%S.%N
  path /var/log/kube-scheduler.log
  pos_file /var/log/es-kube-scheduler.log.pos
  tag kube-scheduler
</source>

# Example:
# I1104 10:36:20.242766       5 rescheduler.go:73] Running Rescheduler
<source>
  type tail
  format multiline
  multiline_flush_interval 5s
  format_firstline /^\w\d{4}/
  format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/
  time_format %m%d %H:%M:%S.%N
  path /var/log/rescheduler.log
  pos_file /var/log/es-rescheduler.log.pos
  tag rescheduler
</source>

# Example:
# I0603 15:31:05.793605       6 cluster_manager.go:230] Reading config from path /etc/gce.conf
<source>
  type tail
  format multiline
  multiline_flush_interval 5s
  format_firstline /^\w\d{4}/
  format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/
  time_format %m%d %H:%M:%S.%N
  path /var/log/glbc.log
  pos_file /var/log/es-glbc.log.pos
  tag glbc
</source>

# Example:
# I0603 15:31:05.793605       6 cluster_manager.go:230] Reading config from path /etc/gce.conf
<source>
  type tail
  format multiline
  multiline_flush_interval 5s
  format_firstline /^\w\d{4}/
  format1 /^(?<severity>\w)(?<time>\d{4} [^\s]*)\s+(?<pid>\d+)\s+(?<source>[^ \]]+)\] (?<message>.*)/
  time_format %m%d %H:%M:%S.%N
  path /var/log/cluster-autoscaler.log
  pos_file /var/log/es-cluster-autoscaler.log.pos
  tag cluster-autoscaler
</source>

# Logs from systemd-journal for interesting services.
<source>
  type systemd
  filters [{ "_SYSTEMD_UNIT": "docker.service" }]
  pos_file /var/log/gcp-journald-docker.pos
  read_from_head true
  tag docker
</source>

<source>
  type systemd
  filters [{ "_SYSTEMD_UNIT": "kubelet.service" }]
  pos_file /var/log/gcp-journald-kubelet.pos
  read_from_head true
  tag kubelet
</source>

<source>
  type systemd
  filters [{ "_SYSTEMD_UNIT": "node-problem-detector.service" }]
  pos_file /var/log/gcp-journald-node-problem-detector.pos
  read_from_head true
  tag node-problem-detector
</source>

Minikube VM上のファイルをみてみる

Minikubeにsshで入り、

minikube ssh

/var/logをls

ls /var/log

# ls -lah
total 68K
drwxr-xr-x  5 root root 4.0K Apr 30 00:54 .
drwxr-xr-x  8 root root  220 Apr 30 00:53 ..
drwxr-xr-x  2 root root 4.0K Apr 30 00:57 containers
-rw-r--r--  1 root root   66 Apr 30 00:54 es-cluster-autoscaler.log.pos
-rw-r--r--  1 root root 2.3K Apr 30 05:18 es-containers.log.pos
-rw-r--r--  1 root root   54 Apr 30 00:54 es-docker.log.pos
-rw-r--r--  1 root root   52 Apr 30 00:54 es-etcd.log.pos
-rw-r--r--  1 root root   52 Apr 30 00:54 es-glbc.log.pos
-rw-r--r--  1 root root   62 Apr 30 00:54 es-kube-apiserver.log.pos
-rw-r--r--  1 root root   71 Apr 30 00:54 es-kube-controller-manager.log.pos
-rw-r--r--  1 root root   58 Apr 30 00:54 es-kube-proxy.log.pos
-rw-r--r--  1 root root   62 Apr 30 00:54 es-kube-scheduler.log.pos
-rw-r--r--  1 root root   55 Apr 30 00:54 es-kubelet.log.pos
-rw-r--r--  1 root root   59 Apr 30 00:54 es-rescheduler.log.pos
-rw-r--r--  1 root root   55 Apr 30 00:54 es-salt.pos
-rw-r--r--  1 root root   61 Apr 30 00:54 es-startupscript.log.pos
drwxr-xr-x  2 root root 4.0K Apr 30 00:54 journal
drwxr-xr-x 14 root root 4.0K Apr 30 00:54 pods

containerのposファイルを見てみる。

# cat es-containers.log.pos 
/var/log/containers/kube-controller-manager-minikube_kube-system_kube-controller-manager-4c516d8904f8d1547a0eb53d0df41a7b9fe23107c788b480917177a825721319.log	0000000000009e26	000000000030146e
/var/log/containers/kube-scheduler-minikube_kube-system_kube-scheduler-aeb620916a9c3bf033630117079c3006a3b366627d556ebe9506d9171aa648e6.log	00000000000029ca	000000000030147c
/var/log/containers/elasticsearch-logging-vwlnb_kube-system_elasticsearch-logging-init-3bce1ce56e7934ccfc32d191f6f50d8d501e5b840b2c90aa4be9617ef65539e2.log	0000000000000060	0000000000301a0d
/var/log/containers/kube-proxy-drvh2_kube-system_kube-proxy-b62062f70d3c52811ef48d42f4dc182a7f29435a9056a7a74c2e8350a2207176.log	00000000000009b7	00000000003015a1
/var/log/containers/storage-provisioner_kube-system_storage-provisioner-782f2f9cbb8854c3498500e692e9a8a3bc56be372755c7793e54fbb82b1548c9.log	0000000000000000	00000000003017bb
/var/log/containers/coredns-66bff467f8-wt895_kube-system_coredns-5e94b1744c07551ba380b1eaa18ef8eac4eef26b1a107d47cb492d061a767abf.log	000000000000019b	0000000000301701
/var/log/containers/fluentd-es-xtbgx_kube-system_fluentd-es-56736d7605bf66f7be3a53df7161216b0e10e53c81a6938002c89a03c18f0803.log	00000000000061c9	0000000000302a82
/var/log/containers/coredns-66bff467f8-gvbzn_kube-system_coredns-c0871bebf2aba728022e1b5119c5ab02b403b2f7cc04ece5eca1a3695fd073b8.log	000000000000019d	00000000003016fd
/var/log/containers/metrics-server-7bc6d75975-5fqnn_kube-system_metrics-server-7d48ad432cc0f44ecb57f232dcec872ef8de8dcb43b2bd65b8eeb7a4dccd11dd.log	00000000000006ea	00000000003017e5
/var/log/containers/kube-apiserver-minikube_kube-system_kube-apiserver-90652df19c311437d42108173e98ba8b59ac640b8a9cb2ac006e5e8d18cfeb63.log	000000000002a8d3	0000000000301470
/var/log/containers/etcd-minikube_kube-system_etcd-e5851c319e3978903d13c78183f3025834cbfd1fd9335ba666534ffa0252ebec.log	000000000001ca5d	0000000000301478
/var/log/containers/kibana-logging-btxjv_kube-system_kibana-logging-bd4a55879a656c0308d12b418b0dee10492eeacefd1b8c49f710f9d4ca3c79ee.log	0000000000002889	0000000000302ac6
/var/log/containers/elasticsearch-logging-vwlnb_kube-system_elasticsearch-logging-aa3dc4d6e8b7af54ad95b5fe5e06203345edd91ef57e504dedd66c6c634d3508.log	000000000000341f00000000000018cce

コンテナごとに1行ずつ記載されていた。

所感

MinikubeのEFKスタックをベースにFluentdの設定の一例を眺めてみたが、大まかな設定の流れはつかめたと思う。
OpenShift 4.xのCluster Loggingを触ったことがあるが、あっちはMulti Tenancyな仕組みを取り揃えているのでProject（Kubernetesで言うNamespace）ごとにElasticsearchのIndexが割り当てられていたりOpenShiftのユーザとElasticSearchの閲覧権限を統合させていたりとなかなかすごい。

このあたりの設定をｺﾞﾆｮｺﾞﾆｮするとサポートがどうのとかいろいろあるので、手を入れるかどうかというのは難しい所。

TODO

次に深堀するとなると下記とかやった方が良さそう。
時間を見つけてやる。

0.x系と1.x系の違い

GKEは0.x系を使ってそうな雰囲気。
1系に寄せてった方がよいので違いを理解しておく。

GKEのfluentdの設定を眺める

GKEはStackdriver Pluginとかの設定がされているはず。
比較してみる。

バッファリング周り

「Fluentdはログ欠損することあるでしょ！」とよく言われるので。
それが発生する可能性や、対応策について順序だてて正しい説明をしたい。

参考：
[http://blog.livedoor.jp/sonots/archives/44690980.html:embed:cite]
[https://chroju.github.io/blog/2018/08/13/fluent_1_0_no_logs_would_be_missing/:embed:cite]

kubernetes_metadata Plugin周り

「アプリケーションのログにPod名とかいれた方が良いの？」とよく聞かれる。
Metadataとして何がとれるかとかどのような挙動を知っておいたほうが良い。
Throttlingなどで速度調整をするとMetadataが取れなくなって「Orphaned」なレコードとして扱われることもあるようなので、その辺りもおさえておきたい。

[https://docs.openshift.com/container-platform/4.2/logging/config/cluster-logging-collector.html#cluster-logging-collector-throttling_cluster-logging-collector:embed:cite]