Juju-62q's blog

参加記録やメモ書き、思考のまとめをしています

Datadog Logsでklogをよしなに扱う

Kubernetes Logging Datadog

f:id:Juju_62q:20200414220621p:plain

TL;DR

klog_parser %{regex("[A-Z]"):klog_level}%{date("MMdd HH:mm:ss.SSSSSS"):date}\s+%{integer:thread_num}\s+%{data:file_name}\:%{integer:line}\]\s+%{data:msg}

これで

I0413 11:04:16.323941       1 main.go:176] Communication with server successful

これが

{
  "klog_level": "I",
  "date": 1586775856323,
  "thread_num": 1,
  "file_name": "main.go",
  "line": 176,
  "msg": "Communication with server successful"
}

こうなる。

Datadog Logsとk8sコンポーネントのログ

Datadog Agentを適当に動かしてk8sのコンポーネントのログを回収しようとすると以下のように全てErrorログとして出力される場合がある。

f:id:Juju_62q:20200414222413p:plain

ログがIから始まっていることからわかるように、これらのログは本来全てInfoログある。 この現象の原因はstderrに出力していることである。 なぜかはよく知らないが、k8sのエコシステムではログをファイルに吐くのが標準でstderrに吐くためのオプションが用意されていることが多い。 少なくともmetrics-server, cluster-autoscaler, external-dns, alb-ingress-controller , nginx-ingress-controllerあたりはexampleのmanifestを動かした時にstderr（ファイルにも）にログを出力する。 なお、stdoutやstderrは実質ファイルじゃんというツッコミは今回は受け付けないものとします。

さて、ファイルでなくstderrに吐くオプションがあるのはおそらくコンテナをステートレスに保つための工夫であると思われる（なんでstdoutじゃないかは知らないので教えてくださいmm）。 一方でInfoログがErrorログとしてたまるとアラートも発砲しにくいし正直困ってしまう。よってこれに対処する。

ログフォーマット

Kubernetesのエコシステムでは多くの場合klogというログ形式が利用される1。 klogは以下のリポジトリで管理されているもので、glogがメンテされなくなったのを受けてk8sコミュニティで命名を変えて管理するようになったものである。

github.com

ちなみにフォーマットはこんな感じである。

I0413 11:04:16.323941       1 main.go:176] Communication with server successful

先頭の文字が (I, W, E, F) になっていてそれぞれ (Info, Warning, Error, Fatal) のログレベルを示している。 続けて日時、スレッドID、ファイル名、行、メッセージと並ぶ。

いわゆる構造化されていないログである。パッとみる分にはフォーマットが定まっているのでわかりやすいが機械が適切に情報を抜き出すにはちょっとして小細工をする必要がある。

なお、例えばcluster-autoscalerにはJSONのログを出して欲しいというISSUEがあったりする。 klogを利用している背景については詳しくないが緩く期待したいところである。

github.com

klogをDatadog Logsでよしなに扱う

やることは3つである。

  1. klogをJSONに変換
  2. log_levelをDatadog Logsが理解できる形式に変更
  3. log statusの書き換え

変換方法については詳しくは公式ドキュメントを見るといい

docs.datadoghq.com

klogをJSONに変換

Grok Parserを利用する。 Grok Parserは様々なフォーマットのログをJSON形式に変換するために用意されている。 正規表現などを利用してなんやかんやログをマッチさせてJSONに変換することができる。 ログルールは上に記述したものから順に適用されていくため、複数のログフォーマットが混在していても問題なく構造化を行うことができる。 詳しい書き方は公式ドキュメントを見て欲しい。

docs.datadoghq.com

具体的にklogをJSONにパースするための記述はこれである。

klog_parser %{regex("[A-Z]"):klog_level}%{date("MMdd HH:mm:ss.SSSSSS"):date}\s+%{integer:thread_num}\s+%{data:file_name}\:%{integer:line}\]\s+%{data:msg}

まず、先頭の1文字をklogのログレベルとして回収する（ {I, W, E, F} に絞ってもいい）。 次に日付やスレッド番号などをフォーマットに合わせて適当にパースして最後に余ったものを全てmsgとして扱う。

ここまで処理をすると結果として

{
  "klog_level": "I",
  "date": 1586775856323,
  "thread_num": 1,
  "file_name": "main.go",
  "line": 176,
  "msg": "Communication with server successful"
}

こうなる。

正直構造化さえできてしまえばあとはこっちのものなのでイージーだ。

log_levelをDatadog Logsが理解できる形式に変更

次に{I, W, E, F} のログレベルが取れたので今度はlog statusを変更したいわけだが、そうは問屋が下さない。 log statusを変更するLog Status Remapperは下記のものを認識してログレベルを変更する。

つまり、このままだと E がInfoにマッピングされてしまう。 大文字小文字は無視するらしいので (I, W, F) はそれぞれ (info, warning, emerg) にマッピングされるのでまあ問題なさそうだがErrorがInfoになるのは困る。 正直Fatalは落ちるレベルの時しか発生しないので普段使いはWarningとErrorになってくる。

したがってklog_levelをこれに合わせて変更する必要がある。 その時に利用できるのがLookup Processorである。

変換元と出力をそれぞれ以下のように設定し、

source: klog_level
target: log_level

list of elementsを以下のようにする。

I,Info
W,Warn
E,Error
F,Fatal

ここまで処理をすると結果として

{
  "klog_level": "I",
  "klog_level": "Info",
  "date": 1586775856323,
  "thread_num": 1,
  "file_name": "main.go",
  "line": 176,
  "msg": "Communication with server successful"
}

こうなる。

log statusの書き換え

先述のLog Status Remapperを利用する。

Set status attribute: log_level

とすれば良い。

ここまでの作業を終えると晴れてInfoログとして出力が得られる。

f:id:Juju_62q:20200414230912p:plain

とりあえず満足である。

終わりに

Grok Parserを使うと概ねどんなログでも、またログ形式が混ざっていても構造化することが可能である。 ちょっとGrok Parser職人としての俗人化の香りを感じたがとりあえず満足である。

なお、stderrをstdoutに追記すると全てがInfoログになるのでそれはそれは辛く、おすすめできない。 Datadogも結構難しいよね。

  1. external-dnsはここで挙げた中では例外で、スペース区切りの ${key}:${value} という形式を利用している。↩