Promtailのtimestampとmultiline設定について

2024年8月27日 09:37

はじめに

こんにちは。株式会社SHIFT ITソリューション部の松本です。
現在は、主にお客さまの新規導入ソリューションのPOCなどを実施しています。

今回は、無料で比較的導入が簡単ではあるけれど、チューニング設定の情報入手が難しい、Promtailの2つの機能の効果と設定方法を紹介します。

ログ収集

OSのログやミドルウェア、アプリケーションのログを運用で確認や調査をする事があると思います。
サーバにログインして確認するには、本番環境では申請や手順書作成などが発生し、対象のサーバにログインするまでに時間がかかります。
また、UNIXサーバの場合、サーバ上でログファイルの確認には、コマンド知識が必要です。
そこで登場するのが、ログの収集、検索をGUIで可視化できるログ収集/管理の仕組です。

今回は、無料で且つ、比較的簡単に導入できるGrafana、Grafana Loki、Promtailの構成で、ログ収集/管理システムを構築したときに、知っておいた方が便利なPromtailの2つの機能について紹介します。

Promtailとは

Grafana　＋　Grafana Loki　でログ収集を構築する場合、ログを送信する仕組みが必要になります。そのログを送信する役割を担うのが、Promtailです。

公式HPの説明
Promtail agent | Grafana Loki documentation

各機能は下記のようになります。

timestamp機能

timestamp機能とは

OSやミドルウェア、アプリケーションから出力されるログの内容には、殆どが各行（イベント発生時）に時刻が記載されています。

Promtailのデフォルト設定では、ログ内容をPromtailがGrafana Lokiに送った場合、Grafana Lokiにはログを取り込んだ時刻が記録され、Grafanaに表示されます。
リアルタイムでログ収集している場合はログ取り込み時刻とログ内のイベント発生時刻はあまりずれることはないのでそれ程問題にはなりません。

問題になるのは、下記のような場合です。

一時的にPromtailが停止していて、再開した場合
リアルタイムのログ収集ではなく、定期的に各サーバから送られてくるログをPromtailでGrafana Lokiに送信する場合

この場合、ログ取り込み時刻とログ内のイベント時刻がずれてしまいます。
こうなってしまうと、イベント発生時刻でGrafanaから絞り込みを行った場合、ログ取り込み時刻を利用してしまうため、実際のイベント発生時刻で絞り込みができなくなってしまいます。

Promtailがログを収集し、Grafana Lokiに取り込まれるときに、ログ内の各イベント発生時の時刻とログを取り込んだ時刻を合わせる機能が、timestamp機能になります。

multiline機能

multiline機能とは

Promtailから送られログデータを、Grafana Lokiが取り込む場合、１行ずつ取り込みます。ログ内のイベント発生は、１行1イベントのみの場合は問題ありません。

しかし、エラー発生時の場合など、複数行にわたって続けてログ出力される場合があります。 Javaの例外エラーなどがそれにあたります。

1イベント複数行のログを1行として取り込む機能が、multiline機能です。

timestamp/multiline設定

では、timestamp/multiline機能を設定した場合、どのような状態でGrafana上で表示されるか確認してみます。

今回は比較するために

test_job1 :timestamp/multiline 未設定の定義
test_job2 :timestamp/multiline 設定済みの定義

の2つを用意し、同じ内容のログを処理する設定にしています。

収集するログファイルの内容

2024-07-21 08:12:19.123 Server01 [INFO] タイムスタンプ検証01
2024-07-21 08:23:19.456 Server01 [INFO] タイムスタンプ検証02
2024-07-21 08:34:19.789 Server01 [INFO] タイムスタンプ検証03
2024-07-21 09:45:19.321 Server01 [ERROR] マルチライン検証01
 エラー1
 エラー2
 エラー3
2024-07-21 09:55:20.543 Server01 [ERROR] マルチライン検証02
 エラー4
 エラー5
 エラー6
2024-07-21 09:56:19.123 Server01 [INFO] タイムスタンプ検証01
2024-07-21 10:10:19.456 Server01 [INFO] タイムスタンプ検証02

設定ファイル

Pomtailの設定ファイルに下記のように記載します。　　　

server:
  http_listen_port: 9080
  grpc_listen_port: 0
  log_level: debug

positions:
  filename: /tmp/positions.yaml

clients:
  - url: http://localhost:3100/loki/api/v1/push

scrape_configs:
- job_name: test_job1
  static_configs:
  - targets:
      - localhost
    labels:
      job: test_job1
      __path__: /data/log/test_job1.log

  pipeline_stages:
  - match:
     selector: '{job="test_job1"}'
     stages:
      - regex:
         expression: '^(?P<time>\d{4}-\d{2}-\d{2}\s\d{2}:\d{2}:\d{2}.\d{3})\s(?P<srv>........)\s.*$'
      - labels:
         time:
         srv:

- job_name: test_job2
  static_configs:
  - targets:
      - localhost
    labels:
      job: test_job2
      __path__: /data/log/test_job2.log

  pipeline_stages:
  - match:
     selector: '{job="test_job2"}'
     stages:
      - regex:
         expression: '^(?P<time>\d{4}-\d{2}-\d{2}\s\d{2}:\d{2}:\d{2}.\d{3})\s(?P<srv>........)\s.*$'
      - timestamp:
         source: time
         format: "2006-01-02 15:04:05.999"
         location: "Asia/Tokyo"
      - multiline:
         firstline: '^\d{4}-\d{2}-\d{2}\s\d{2}:\d{2}:\d{2}.\d{3}'
         max_wait_time: 3s
      - labels:
         time:
         srv:

設定の説明（timestamp）

      - regex:
         expression: '^(?P<time>\d{4}-\d{2}-\d{2}\s\d{2}:\d{2}:\d{2}.\d{3})\s(?P<srv>..........)\s.*$'

ログのパース設定を行います。
ここにtimestamp対象になる文字列の指定を正規表現で記載しパースします。　　

      - timestamp:
         source: time
         format: "2006-01-02 15:04:05.999"
         location: "Asia/Tokyo"

source:
どこをtimestampの対象にするか指定します。
ここにはexpressionでパース設定した　"time" 　を指定します。

format:
これは固定指定されていますので、そのままの記載で問題ありません。

location:
ロケーションの指定です。

      - labels:
         time:
         srv:

labels:
PromtailがGrafana Lokiに送信するときに付けるラベル名になります。
今回は、expressionでパースした　"time"　と　"srv"　としています。

設定の説明（multiline）

      - multiline:
         firstline: '^\d{4}-\d{2}-\d{2}\s\d{2}:\d{2}:\d{2}.\d{3}'
         max_wait_time: 3s

firstline:
1行の始まり部分を指定します。
ここの条件に一致した行を1行として認識させます。

max_wait_time:
firstlineのパターンを待つ時間を指定します。

では、timestamp/multiline機能が未設定の場合と、設定した場合で Grafana上でどのように表示されるか比較してみます。

比較

timestamp/multiline機能　未設定

実際のログ内に記載がされているタイムスタンプ（青枠）と、Grafana Lokiが取り込んだ時刻（赤枠）の時間が不一致になってます。
時刻の記載がない行についても、一行一行にGrafana Lokiが取り込んだ時刻が表示されています。

timestamp/multiline機能　設定済み

実際のログ内に記載がされているタイムスタンプ（青枠）と、Grafana Lokiが取り込んだ時刻（赤枠）の時間がが一致しています。
時刻の記載がない行には、Grafana Lokiが取り込んだ時刻が表示されておらず、メッセージが表示された最初の行にGrafana Lokiが取り込んだタイムスタンプが表示されています。　

では、この状態で、Grafana上で絞り込みを実施してみます。

時間の絞り込み

今回は、2024/7/21 08:00:00 ～ 2024/7/21 09:59:59 の間で発生したイベントを絞り込みます。

timestamp/multiline機能　未設定

条件にマッチしないため、ヒットしません。
これは、Grafanaの時間での絞り込みは、Grafana Lokiが取り込んだ時刻で絞り込まれる為です。
実際のログ内のイベント発生時刻と、Grafana Lokiのログ取り込み時刻がミスマッチになっているため、このような事が起こります。

timestamp/multiline機能　設定済み

条件にマッチしたログ内のイベントが表示されます。

このように、Grafanaの時刻絞り込みでログ内の発生イベント時刻を絞り込みたい場合に、タイムスタンプを有効にしておく必要があります。
※正確には、Promtailでパースした時刻部分をGrafanaの検索部分を追加する事で絞り込む事は可能です。

つぎに、キーワードで検索してみます。

キーワード絞り込み

timestamp/multiline機能　未設定

キーワードにヒットした1行だけ表示されます。
これでは、発生時刻や、前後の情報がこの状態ではわかりません。

timestamp/multiline機能　設定済み

キーワードにヒットした行に含まれる以外も表示されます。
これは、Promtailで設定したmultiline設定で1行と判断された行が表示される為です。
multiline設定をする事で、キーワード検索したときに、発生イベントとしては1行として扱いたい情報を表示する事が可能です。

補足

同時設定する場合
この機能は同時に利用する事が多いと思います。
同時に設定ファイルに記載する場合は、timestamp、multilineの順番に記載します。
※逆に記載するとtimestampが機能しません。
2時間以上前に発生したログを取り込む場合
timestamp機能を有効にする場合、過去のイベント発生時刻とGrafana Lokiが取り込む時刻が同じになります。
デフォルトで、Grafana Lokiは2時間前までの過去ログ時刻を取り込む事ができます。
通常、デフォルト設定で困る事はないと思いますが、2時間より過去の発生イベントをGrafana Lokiに取り込みたい場合は、Grafana Lokiのconfig.ymlで下記の設定で調整します。

　ingester:
  　max_chunk_age: 24h

上記設定では、24時間前までの発生イベント時刻のログをLokiが取り込む事ができるようになります。
※multiline設定が無効な場合は、Grafana Lokiが実際取り込んだ時刻になるので設定する必要はありません。

３. デバッグしたい場合
Promtailはログパースを指定して色々設定しますが、うまく動かない場面が結構あると思います。
その場合は、Promtailの設定でログレベルをデバッグモードしてみると、調査に役立ちます。

server:
  http_listen_port: 9080
  grpc_listen_port: 0
  log_level: debug　←　これ

例えば、設定した正規表現がマッチしない場合は、下記のようなログが出力されます。

Jul 15 15:31:51 hostname promtail[11339]: level=debug ts=2024-07-15T06:31:51.832866941Z caller=regex.go:121 component=file_pipeline component=stage type=regex msg="regex did not match" input="2024-07-15 15:25:25.868 テスト1" regex=^(?P<time>\d{4}-\d{2}-\d{2}\s\d{2}:\d{2}:\d{2}.\d{3})\s(?P<srv>..........)\s.*$
Jul 15 15:31:51 hostname promtail[11339]: level=debug ts=2024-07-15T06:31:51.832887241Z caller=timestamp.go:176 component=file_pipeline msg="extracted data did not contain a timestamp"

デバッグモードでは、大量にログ出力されるので、確認ができ次第停止する事を忘れないようにしましょう。

最後に

Grafana＋Grafana Loki＋Promtailは導入も簡単で無料で利用できるので、小・中規模のログ収集やリソース監視には導入しやすいと思います。

この2つの機能は、実際のログ管理での利用方法（エラー発生時刻を絞りたい、発生したキーワードで検索したい）に必要になりますので、利用してみてください。

執筆者プロフィール：松本悟
主にインフラ設計/構築/運用を担当しています。
趣味：アクアリウム、筋トレ、ゲーム

お問合せはお気軽に
https://service.shiftinc.jp/contact/

SHIFTについて（コーポレートサイト）
https://www.shiftinc.jp/

SHIFTのサービスについて（サービスサイト）
https://service.shiftinc.jp/

SHIFTの導入事例
https://service.shiftinc.jp/case/

お役立ち資料はこちら
https://service.shiftinc.jp/resources/

SHIFTの採用情報はこちら
https://recruit.shiftinc.jp/career/

PHOTO：UnsplashのArtem Sapegin

最後まで読んでくださり、ありがとうございます！

御社サービスのご相談はお気軽に。

ソフトウェア品質のプロがお伺いします。