こんにちは！インフラユニットの小林です。
今回はログ監視ツール『Loki』の導入事例を紹介をします。
課題
これまでもログ可視化集約ツールを使っていたのですが、メモリ使用量の多さや気が付いたら落ちていたりして、VMのランニングコストや運用負荷が課題とされていました。
またUIが非常にリッチなツールだったんですが、我々のやる事と言えば『ApacheやNginxのログからステータスコードやリクエストタイムを可視化』したり、『アプリケーションでエラーが起きた場合にログを確認』といったくらいで、若干オーバースペック気味なのも課題でした。
なので、軽量でシンプルにログを可視化集約できるツールを探し、Lokiに白羽の矢が立ちました。
Lokiとはなにか？
- Prometheusからヒントを得た、水平展開、高可用性、マルチテナントが可能なログ集約システムです
- OSSで、開発の主体はGrafana Lab社です
- コストパフォーマンスや運用のしやすさを目的に開発されています
- 集約時にログを解析してIndexを作成せずに、ラベルを付けたテキストストリーム的なものとしてログを保存しています
ログ転送の仕組み
ログの転送エージェントにはPromtailを使っています。他にはFluentdやFluent Bitが使えるようです。 EC2インスタンスにバイナリ、またはコンテナ形式で導入しています。
ログ可視化の仕組み
LokiとPromtailを使った場合、可視化の方法は2種類あります。
- Lokiサーバにログを送信し、保存したログをGrafanaで見る
- Promtailで指定したログの値を集計し、それをPrometheusでメトリクスとして取得しGrafanaで見る
1の方はKibana+Elasticsearchみたいな感じでイメージしやすいかと思いますが、2の方はちょっと理解に時間がかるかも知れません（僕はかかりました）。
後程お見せしますが、Promtailは『ログ送信エージェント』と『メトリクスを公開するサーバ』の、2通りの振る舞いができます。
使ってみてわかってきたこと
検証、そして導入後に分かってきたことを紹介します。
Grafanaでログをササっとみられるのは楽
以下の図は、実際にGrafanaを使ってLokiサーバに保存されているログを抽出している画面です。
Log labels というところにログのラベルと抽出条件を入力します。
{service="hoge",environment="staging"} というのがログストリームについているラベルです。
|~ "\"status\": \"404\"" というのがログを抽出する条件です。"status": "404"を含むログを抽出してという意味です。この文法はLogQLという独自のクエリです。
PrometheusのPromQLと構造は似ていて、正規表現に慣れればそんなに難しくありません。
そしてGrafanaでログを確認できるので、サーバにログインせずに素早くログを確認できます。
ログの履歴を保存する機能やダッシュボード化も出来るので、よく使うクエリを毎回打つ必要もありません。
『indexを作らない』の意味
Lokiはデバッグを得意としています。『サーバにsshログインして、ログをコマンドでgrepして…awk？…sort？』といった手間を軽やかに省略できるのがウリです。
ただ一方で、長期保存されたログからの傾向分析。例えば『n週間分のnginxアクセスログからhttp_methodの分布をみる』といった処理は時間がかかります。
以下は『1週間分のnginxアクセスログからhttp_methodの分布をみる』操作のキャプチャです。
時間のレンジを直近2日から7日に広げると集計に時間がかかることが分かります。
もちろんマシンスペックやログの量に依存する話ですが、ログ保存時に解析をしてindexを作成しないので、先ほどの図のように多角的な集計はチョット苦手なのが現状です。
しかし可視化できると集計したくなるのが人の常です。なので集計方法としてPromtailでログを集計してメトリクスとして公開する方法があります。
ログから作成するメトリクスと統計情報
ログ送信エージェントPromtailのメトリクスを公開する機能についてお話します。上の図の緑色で囲った部分です。
まず、以下のようにapacheのアクセスログをjsonで定義します。もちろんjson以外でも大丈夫ですけど、その場合は正規表現を使ってKeyとValueを定義する必要があります。
LogFormat " { \"timestamp\":\"%{'%Y'-%m-%dT%H:%M:%S}t\", \"remote_ip\":\"%{X-Forwarded-For}i\", \"port\":%{local}p, \"local_ip\":\"%A\", \"httpHost\":\"%v\", \"reqStatus\":%>s, \"protocol\":\"%H\", \"bytes_sent\":%O, \"bytes_received\":%I, \"reqTime\":%D, \"file_path\":\"%f\", \"query\":\"%q\", \"method\":\"%m\", \"reqURL\":\"%U\", \"request\":\"%r\", \"ua\":\"%{User-Agent}i\", \"referrer\":\"%{Referer}i\" } " json
実際のログは以下のように出力されます。（見やすいように改行を入れてます）
{ "timestamp":"2020-06-15T14:26:52", "remote_ip":"<hoge>", "port":80, "local_ip":"<hoge>", "httpHost":"127.0.0.1", "reqStatus":200, "protocol":"HTTP/1.1", "bytes_sent":3934, "bytes_received":1578, "reqTime":17750, "file_path":"/var/www/html/current/public/index.php", "query":"", "method":"GET", "reqURL":"/login", "request":"GET /login HTTP/1.1", "ua":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.138 Safari/537.36", "referrer":"<hoge>" }
そして、Promtailに以下のような設定をします。
pipeline_stages: # jsonステージという - json: expressions: # Keyの宣言 request_time: reqTime # metricsステージという - metrics: # metricsの名前を定義 web_request_time: # Histogram（統計）を取得すると宣言 type: Histogram description: "http duration time" source: request_time config: buckets: [0,1000000,1500000,2000000]
まずはjsonステージで、 request_time というKeyを宣言しています。Valueはログにある、reqTimeの値が入ります。（ちなみにreqTimeはマイクロ秒です）
実際のログに "reqTime":17750 と出てたら、jsonステージで宣言したKeyのValueは以下のようになります。
| Key | Value |
|---|---|
| request_time | 17750 |
次にmetricsステージでは、jsonステージで作成したKeyを集計できます。
まず、 web_request_time というメトリクスを宣言しています。 Histogramという統計情報を取得するタイプを選択し、先ほど作成したrequest_timeをデータソースとし、0,1000000,1500000,2000000 という4つのbucketを作っています。
各bucketはValueの値に対応していて、以下のように分けられます。
| bucket名 | 該当するValue |
|---|---|
| 0 | 0から999999（1秒未満） |
| 1000000 | 1000000から1499999（1~1.5秒未満） |
| 1500000 | 1500000から1999999（1.5秒から2秒未満） |
| 2000000 | 2000000から∞（2秒以上） |
なので例だと17750なので0のbucketに該当し、0のbucketの値が+1されます。
実際のメトリクスを見てみましょう。Prometheusのメトリクスと同じように取得できます。 デフォルトだとサーバとしてのPromtailは80/tcpでlistenしているので、localhost:80/metrics にアクセスすると取得できます。
# TYPE promtail_custom_tact_ap_request_time histogram promtail_custom_web_request_time_bucket{service="hoge,"le="0"} 0 promtail_custom_web_request_time_bucket{service="hoge,le="1e+06"} 620565 promtail_custom_web_request_time_bucket{service="hoge,le="1.5e+06"} 621554 promtail_custom_web_request_time_bucket{service="hoge,le="2e+06"} 621925 promtail_custom_web_request_time_bucket{service="hoge,le="+Inf"} 623086 promtail_custom_web_request_time_sum{service="hoge} 1.9314177764e+10 promtail_custom_web_request_time_count{service="hoge} 623086
表にしてみましょう。
| メトリクスとラベル | 意味 | 値 |
|---|---|---|
| promtail_custom_web_request_time_bucket{service="hoge,"le="0"} | request_timeが0秒以下のログの数 | 0 |
| promtail_custom_web_request_time_bucket{service="hoge,le="1e+06"} | request_timeが1秒以下のログの数 | 620565 |
| promtail_custom_web_request_time_bucket{service="hoge,le="1.5e+06"} | request_timeが1.5秒以下のログの数 | 621554 |
| promtail_custom_web_request_time_bucket{service="hoge,le="2e+06"} | request_timeが2.0秒以下のログの数 | 621925 |
| promtail_custom_web_request_time_bucket{service="hoge,le="+Inf"} | request_timeが2.0秒より大きいのログの数 | 623086 |
| promtail_custom_web_request_time_sum{service="hoge} | 全てのrequest_timeの合計値 | 1.9314177764e+10 |
| promtail_custom_web_request_time_count{service="hoge} | 全てのrequest_timeの数（≒ログの数） | 623086 |
request_timeが2.0秒より大きいのログの数がやたらと多く、全てのrequest_timeの数（≒ログの数）と同じ事に違和感を感じた方も多いのではないでしょうか。これは累積ヒストグラムというものです。
Promtailが扱うヒストグラムは累積ヒストグラムと言って、手前のすべての区間の度数を足し合わせた累計値をその区間の度数とし、可視化すると下図の右のグラフのように右肩上がりになります。Prometheusが扱う統計情報も同じです。
どういうメリットがあるかというと、例えば割合が出しやすいです。
例えば『全リクエスト中で1秒未満のアクセスの割合』は、promtail_custom_web_request_time_bucket{service="hoge,le="1e+06"} / promtail_custom_web_request_time_count{service="hoge}で算出できます。全リクエストを出すために各bucketを足す必要がありません。累積ヒストグラムのメリットについての詳細は以下の記事をご覧ください。
また、左のグラフのような各値それぞれの統計を出したい場合はcounterというタイプのメトリクスを作成しましょう。
現在Promtailにはhistgram、counter、gaugeの3タイプのメトリクスがあります。詳しくはloki/metrics.md at master · grafana/loki · GitHub をご覧ください。
nginx-module-vts
統計情報を出したいだけなら、nginxの場合はnginx-module-vts（Nginx virtual host traffic status module）という追加モジュールがあります。
このモジュールを使うと、特定URLにアクセスするだけで以下の図のような様々な情報を取得できます。
Prometheusのexporterもあるので、Prometheusにメトリクスを保存することが可能です。
Lokiをログのデバッグツールと割り切って、Webサーバの統計情報はnginx-module-vtsから取得するといった使い分けも可能です。
GrafanaのSlackが温かい
Lokiは2019年11月にGAになった若いOSSです。ゆえに（英語でも）情報があまりなく、導入に関して非常に苦労しました。
そんな私の相談相手になってくれたのはGrafanaのslackです。そこにはGrafanaを愛する世界中のユーザだけではなく、Grafana Lab社の社員もいて技術的な相談にも乗ってくれたりします。
こちらから登録できます。 Lokiの話題専用の#lokiチャンネルがあります。
特に私がお世話になったのはCyril Tovenaさんという方で、私の機械翻訳バリバリの拙い英語の質問でも真摯に応えてくれました。以下は実際のslackでのやり取りです。（ご本人の了承を頂いてます）
ご本人から「Sure make me popular in Japan（意訳：（会社のブログに掲載していいかという問いに）もちろんだよ。日本で俺のことを有名にしてくれよ！」とのことなのでご紹介します。
LokiのmaintainerであるCyril Tovenaさんです。Blue Eyed Samurai.
https://grafana.com/blog/2019/08/16/meet-the-grafana-labs-team-cyril-tovena/
現在のLoki環境
現在はOracle CloudにVMを作成し、コンテナでLokiを動かしています。 VMのスペックや構成は以下の通りです
VMの情報
- CentOS 7.7
- CPU : 4core
- MEM: 16GB
- SSD: 500GB
コンテナの構成
httpsと認証のためにNginxとCertbotコンテナを置いて、その後ろにLokiコンテナを置いてます。 docker-composeでまとめて、設定等はbitbucketでバージョン管理をしています。
負荷状況
現在10台程度のサーバからログが送られています。
以下は直近1週間のサーバの状態をGrafanaで見たものです。
/opt にログを貯めていて、1GB/day程度の増加量のわりにはCPUやメモリへの負荷は低いかなと感じています。
以前はメモリ消費量が大きくて悩みの種だったんですが、lokiのコンフィグのchunk_retain_periodという、メモリからファイルにフラッシュした後のメモリ上のデータ保持期間を168hからデフォルトの15分に戻したら下のグラフのようにメモリ消費量がガクッと減りました。なぜ168hになってたのかは謎ですが、お気を付けください。
そして以下が実際のLokiに保存されているNginxのログと、nginx-module-vtsから得たメトリクスを使って作成したダッシュボードです。
各ステータスコード/Methodの増分、エラーの比率、リクエストの処理にかかっている時間などが確認できます。
今後
まだ一部のサービスでしかLoki/Promtailを導入していないので、なるべく広く展開していきたいと考えています。
Loki自体の負荷が高くなってきたらマイクロサービス化するのも面白いかもしれません。
最後までお読みいただき有難うございました。
