前回の続き。システムの一部をCloud RunからVPS化のために、
VPS上のログをGCPのCloud Loggingに送信したい。。
とりあえず、INPUTまわりまで。
アプリのログ
アプリのログの形式はこんな感じ。
[2024-01-17T07:15:18.067+0900] INFO message info [2024-01-17T07:15:18.072+0900] ERROR messgge error test multi line 1 test multi line 2 test multi line 3 [2024-01-17T07:15:18.075+0900] DEBUG messgge debug [2024-01-17T07:15:18.079+0900] WARN messgge warn
利用するプラグイン
利用するのはこのあたり。
アプリのログファイルをtailで読み込んで、
Cloud Logging(旧Stackdriver)に送信する。
ローカルでの環境準備
とりあえず、ローカルで実装する感じ。 開発中はmacOS上で行う想定。
ディレクトリ構成はこんな感じ。
./
logs/
application.log ... テスト用のアプリログ
myapp.conf ... 開発時のconfの起点
myapp-io.conf ... 開発するINPUT/OUTPUTなど
myapp-parser.conf ... 開発するPARSER
myapp.confを渡して動作確認をしていく。
$ fluent-bit -c myapp.conf [2024/01/17 07:42:01] [ info] [sp] stream processor started [0] dummy.local: [[1705444922.491228000, {}], {"message"=>"dummy"}] [0] dummy.local: [[1705444923.491267000, {}], {"message"=>"dummy"}] [0] dummy.local: [[1705444924.492032000, {}], {"message"=>"dummy"}]
myapp.conf
初期のconfから抜粋。
parsers_fileと@INCLUDEを使って、
本体部分を分離しておく。
# myapp.conf [SERVICE] flush 1 daemon Off log_level info http_server Off http_listen 0.0.0.0 http_port 2020 storage.metrics on parsers_file myapp-parser.conf @INCLUDE myapp-io.conf
myapp-io.conf
PARSER関係以外はこっち。
# myapp-io.conf
[INPUT]
name dummy
tag dummy.local
[OUTPUT]
name stdout
match *
myapp-parser.conf
PARSER関係はこっち。
# myapp-parser.conf # とりあえず空ファイルから開始
tailを使ったログ収集
INPUTのTailプラグインを使って、
application.logを読み込む部分。
とりあえず読み込む
まずはこんな感じ。
read_from_headをつけると先頭から読んでくれる。
# myapp-io.conf [INPUT] name tail path ./logs/application.log read_from_head true [OUTPUT] name stdout match *
OUTPUTのstdoutでみると、各行が取り込まれている。
$ fluent-bit -c myapp.conf [0] tail.0: [[1705445241.946134000, {}], {"log"=>"[2024-01-17T07:20:44.448+0900] INFO message info"}] [1] tail.0: [[1705445241.946137000, {}], {"log"=>"[2024-01-17T07:20:44.451+0900] ERROR messgge error"}] [2] tail.0: [[1705445241.946138000, {}], {"log"=>" test multi line 1"}] [3] tail.0: [[1705445241.946138000, {}], {"log"=>" test multi line 2"}] [4] tail.0: [[1705445241.946139000, {}], {"log"=>" test multi line 3"}] [5] tail.0: [[1705445241.946139000, {}], {"log"=>"[2024-01-17T07:20:44.453+0900] DEBUG messgge debug"}] [6] tail.0: [[1705445241.946139000, {}], {"log"=>"[2024-01-17T07:20:44.456+0900] WARN messgge warn"}]
日付は浮動小数点の形式で分かりづらいが、
GNU dateコマンドを使えば確認できる。
# gdateのインストール $ brew install coreutils $ gdate --date='@1705445241.946139000' +'%Y-%m-%dT%H:%M:%S.%3N%z' 2024-01-17T07:47:21.946+0900
なにもしてない場合は、読み込んだ日時がログの日時になる。
毎回は面倒なので、.bashrcとかに関数を用意しておくと便利。
function gdate-num() { gdate --date="@${1}" +'%Y-%m-%dT%H:%M:%S.%3N%z' } $ gdate-num 1705445241.946139000 2024-01-17T07:47:21.946+0900
OUTPUTのstdoutプラグインでも、
JSONフォーマットにすれば、dateのフォーマットを変更できるが、
UTCでしか確認できない。。
# myapp-io.conf [OUTPUT] name stdout format json_lines json_date_format iso8601 match * $ fluent-bit -c myapp.conf {"date":"2024-01-16T23:07:19.329342Z","log":"[2024-01-17T07:20:44.448+0900] INFO message info"} {"date":"2024-01-16T23:07:19.329347Z","log":"[2024-01-17T07:20:44.451+0900] ERROR messgge error"} {"date":"2024-01-16T23:07:19.329348Z","log":" test multi line 1"} {"date":"2024-01-16T23:07:19.329348Z","log":" test multi line 2"} {"date":"2024-01-16T23:07:19.329349Z","log":" test multi line 3"} {"date":"2024-01-16T23:07:19.329349Z","log":"[2024-01-17T07:20:44.453+0900] DEBUG messgge debug"} {"date":"2024-01-16T23:07:19.329350Z","log":"[2024-01-17T07:20:44.456+0900] WARN messgge warn"}
ログから日時を取得する
ログにある日時やlevelを使いたいので、
PARSERを使って取得する。
# myapp-io.conf [INPUT] name tail path ./logs/application.log read_from_head true parser myapp-parser [OUTPUT] name stdout match * # myapp-parser.conf [PARSER] Name myapp-parser Format regex Regex ^\[(?<time>[^ ]+)\] (?<type>[a-zA-Z]+) +(?<message>.*) Time_key time Time_Format %Y-%m-%dT%H:%M:%S.%L%z
結果はこんな感じ。
$ fluent-bit -c myapp.conf [0] tail.0: [[1705443644.448000000, {}], {"type"=>"INFO", "message"=>"message info"}] [1] tail.0: [[1705443644.451000000, {}], {"type"=>"ERROR", "message"=>"messgge error"}] [2] tail.0: [[1705446865.417416000, {}], {"log"=>" test multi line 1"}] [3] tail.0: [[1705446865.417417000, {}], {"log"=>" test multi line 2"}] [4] tail.0: [[1705446865.417417000, {}], {"log"=>" test multi line 3"}] [5] tail.0: [[1705443644.453000000, {}], {"type"=>"DEBUG", "message"=>"messgge debug"}] [6] tail.0: [[1705443644.456000000, {}], {"type"=>"WARN", "message"=>"messgge warn"}] $ gdate-num 1705443644.456000000 2024-01-17T07:20:44.456+0900
[INPUT]のparser myapp-parserで、
利用するPARSERを指定している。
Regular Expressionのパーサーでは、
正規表現にマッチした行を構造化ログに変換してくれる。
Time_keyで指定したキーをログの日時として扱ってくれるようになる。
正規表現の書き方は少し拡張されていて、
(?<キー名>.*)と書くと該当のキーの値として構造化してくれる。
test multi line 1などは、ルールにマッチしなかったので、
そのままの状態になっている。
複数行を1つのログとして扱う
スタックトレースなど、複数行に渡るログがある場合、
一つのログとして扱ってほしい。
tail自体もMultiline Supportを提供しているが、
v1.8からFluent Bit側でも提供されるようになったらしい。
Old Multiline(tail側のサポート)
tail側提供のMultiline Supportはこんな感じ。
parserをparser_firstlineに変更して、
multiline onを追加すればOK
# myapp-io.conf [INPUT] name tail path ./logs/application.log read_from_head true parser_firstline myapp-parser multiline on [OUTPUT] name stdout match * # myapp-parser.conf [PARSER] Name myapp-parser Format regex Regex ^\[(?<time>[^ ]+)\] (?<type>[a-zA-Z]+) +(?<message>.*) Time_key time Time_Format %Y-%m-%dT%H:%M:%S.%L%z
実行してみると、改行を含めた1つのログに集約される。
$ fluent-bit -c myapp.conf [0] tail.0: [[1705443644.448000000, {}], {"type"=>"INFO", "message"=>" message info"}] [1] tail.0: [[1705443644.451000000, {}], {"type"=>"ERROR", "message"=>"messgge error test multi line 1 test multi line 2 test multi line 3"}] [2] tail.0: [[1705443644.453000000, {}], {"type"=>"DEBUG", "message"=>"messgge debug"}] [0] tail.0: [[1705443644.456000000, {}], {"type"=>"WARN", "message"=>" messgge warn"}]
先頭行だけPARSERを与えればよく、簡単に実装できるけど、
おそらくメンテナンスされていかないので推奨されない。
Multiline Core(Fluent Bit側のサポート)
Fluent Bit v1.8移行で推奨される方法。
ただ結構入り組んでてめんどくさい。。
設定はこんな感じ。
# myapp-io.conf [INPUT] name tail path ./logs/application.log read_from_head true multiline.parser myapp-multiline tag myapp.applog [FILTER] name parser match *.applog key_name log parser myapp-multiline-capture [OUTPUT] name stdout match * # myapp-parser.conf [MULTILINE_PARSER] name myapp-multiline type regex flush_timeout 1000 # rules | state name | regex pattern | next state # ------|---------------|-------------------------------------------- rule "start_state" "/^\[.+\] [a-zA-Z]+ .+/" "cont" rule "cont" "/^\s+.*/" "cont" [PARSER] name myapp-multiline-capture format regex regex /^\[(?<time>[^ ]+)\] (?<type>[a-zA-Z]+) +(?<message>.*)\n/m time_key time time_format %Y-%m-%dT%H:%M:%S.%L%z
$ fluent-bit -c myapp.conf [0] myapp.applog: [[1705443644.448000000, {}], {"type"=>"INFO", "message"=>"message info"}] [1] myapp.applog: [[1705443644.451000000, {}], {"type"=>"ERROR", "message"=>"messgge error test multi line 1 test multi line 2 test multi line 3"}] [2] myapp.applog: [[1705443644.453000000, {}], {"type"=>"DEBUG", "message"=>"messgge debug"}] [3] myapp.applog: [[1705443644.456000000, {}], {"type"=>"WARN", "message"=>"messgge warn"}]
[MULTILINE_PARSER]セクションで複数行に対応したパーサを記述できる。
単純な正規表現ではなく、ステートマシンで書く。
初期状態(start_state)からはじまり、
patterにマッチしたら、次の状態に遷移する。
このときに、ログの構造化は行わないため、正規表現ルールもシンプル。
Multiline parserだけで[FILTER]がないと、
こんな感じで、logにひとまとまりになるだけの状態。
$ fluent-bit -c myapp.conf [0] myapp.applog: [[1705452128.695082000, {}], {"log"=>"[2024-01-17T07:20:44.448+0900] INFO message info "}] [1] myapp.applog: [[1705452128.695089000, {}], {"log"=>"[2024-01-17T07:20:44.451+0900] ERROR messgge error test multi line 1 test multi line 2 test multi line 3 "}] [2] myapp.applog: [[1705452128.695101000, {}], {"log"=>"[2024-01-17T07:20:44.453+0900] DEBUG messgge debug "}] [3] myapp.applog: [[1705452128.695103000, {}], {"log"=>"[2024-01-17T07:20:44.456+0900] WARN messgge warn "}]
この複数行のログから日時や構造化を行うために、
[FILTER]を利用する。
基本的にはOld Multilineと似た形式の正規表現ルールだけど、
.に改行が含まれないため、/.../mの形式にする。
/.../mがないと、改行までで判定されるので、
2行目以降は無視されれてしまう。。
$ fluent-bit -c myapp.conf [0] myapp.applog: [[1705443644.448000000, {}], {"type"=>"INFO", "message"=>"message info"}] [1] myapp.applog: [[1705443644.451000000, {}], {"type"=>"ERROR", "message"=>"messgge error"}] [2] myapp.applog: [[1705443644.453000000, {}], {"type"=>"DEBUG", "message"=>"messgge debug"}] [3] myapp.applog: [[1705443644.456000000, {}], {"type"=>"WARN", "message"=>"messgge warn"}]
ただ、/.../mの形式だと末尾の改行までmessageに含まれてしまうので、
`/...\n/mという形で末尾の改行は含まれないようにしている。
すべてのログにこのFilterを利用したくはないので、
Tagをつかって対象となるログを分類している。
読み込んだ行をDBに保持する
tailプラグインは、ほんとにtail -fと同じ感じなので、
デフォルトだと読み込み位置はメモリ上。
なので、再起動したりすると、読み飛ばしたり、重複してしまう。。
読み込み位置をDBしておくオプションがあるので、
それを利用すればOK。
# myapp-io.conf [INPUT] name tail path ./logs/application.log read_from_head true db ./logs/application.tail.db
db <dbのパス>で設定すれば、sqliteで保存しておいてくれる。
.dbファイルの中身はこんな感じ。
$ echo ".tables" | sqlite3 ./logs/application.tail.db in_tail_files $ echo "select * from in_tail_files;" | sqlite3 ./logs/autoupdate.db -header -table +----+------------------------+--------+----------+------------+---------+ | id | name | offset | inode | created | rotated | +----+------------------------+--------+----------+------------+---------+ | 1 | ./logs/application.log | 262 | 62601824 | 1705443175 | 0 | +----+------------------------+--------+----------+------------+---------+ 対象ファイルのパスとオフセットなどを保持しているので、 再起動しても適切な位置から読み込みはじめてくれる。
おまけ
ログファイルに追記するスクリプトを作っておくと、
いろいろ捗る。
#!/bin/bash logs=( 'INFO message info' 'ERROR messgge error test multi line 1 test multi line 2 test multi line 3' 'DEBUG messgge debug' 'WARN messgge warn' ) for l in "${logs[@]}"; do dt=`gdate +'%Y-%m-%dT%H:%M:%S.%3N%z'` echo "[$dt] ${l}" done
あとは好きなときに実行すればOK。
$ ./add-log.sh >> logs/application.log
以上!! これでログを収集するところまではできた気がする(*´ω｀*)
