[Article] Tsurugiのログ設定について

[akirakw]

[Article] Tsurugiのログ設定について

はじめに

この記事は Tsurugi Advent Calendar 2023 の11日目の記事です。

Tsurugiサーバが出力するログとその設定方法、ログの見方などについて解説していきます。

この記事は Tsurugi 1.0.0-BETA2 を元に書いています。これ以外のバージョンでは本記事とは異なる動作をすることがあります。
また、現時点ではログに対する仕様は検討中の部分が多々あるため、将来的この記事の内容から変更される可能性があることをご承知おきください。

概要

本記事では、以下のような内容について解説しています。

• Tsurugiのログ機構は Google Logging (以下「glog」) を利用して提供されている。
  • Tsurugiのログを理解する上で、glogを理解することはとても重要である。
• Tsurugiのログ設定方法は2つの方法がある。
  • 構成定義ファイル: $TSURUGI_HOME/var/etc/tsurugi.ini の glog セクションで設定する
  • GLOG_ 環境変数: glogが受け付ける GLOG_ から始まる各種環境変数で設定する。構成ファイルの定義は環境変数の設定で上書きされる。
• Tsurugiのログはポリシーが異なる2種類のログを定義している。
  • 運用ログ : Tsurugiのサーバプロセスの情報を提供するログ。
  • イベントログ : クライアントからのリクエストに対応する処理の情報を提供するログ。
  • 運用ログはglogの LOG() マクロにより出力、イベントログはglogの VLOG() マクロ(Verbose Logging:詳細ログ)により出力される。
• Tsurugiのログはコンポーネントやスコープ、関数を特定する「ロケーションプレフィックス」というフォーマットを採用している。

Tsurugiのログを扱う上で、glogを理解しておくことは重要です。
以降の説明では適宜 glog 自体の説明も行っていきますが、以下のglogユーザガイドの関連箇所を合わせて読むと理解が進むと思います。

• https://github.com/google/glog#user-guide

デフォルトの動作を確認

とりあえずTsurugiをインストールして起動してみます。

$ $TSURUGI_HOME/bin/tgctl start
successfully launched tsurugidb

ログらしきものは画面には出ないようです。デフォルトではログはどこに出力されるのでしょうか。

Tsurugiでは基本的に、ログのデフォルト設定は glog のデフォルト設定に従うようになっています。
そしてglogは、デフォルトでログはファイルとして出力されるようになっており、そのディレクトリは /tmp , ファイル名は <program name>.<hostname>.<user name>.log.<severity level>.<date>-<time>.<pid> というファイル名（長いですね...）と定義されています。

/tmp にあるんだな、ってことで見てみます。サーバプロセス名は tsurugidb なのでそれでフィルタします。

$ ls -l /tmp/tsurugidb.*
lrwxrwxrwx 1 akirakw akirakw   62 Dec  8 14:16 /tmp/tsurugidb.INFO -> tsurugidb.kawaguchi-desk.akirakw.log.INFO.20231208-141617.9248
lrwxrwxrwx 1 akirakw akirakw   65 Dec  8 14:16 /tmp/tsurugidb.WARNING -> tsurugidb.kawaguchi-desk.akirakw.log.WARNING.20231208-141617.9248
-rw-r--r-- 1 akirakw akirakw 4342 Dec  8 14:16 /tmp/tsurugidb.kawaguchi-desk.akirakw.log.INFO.20231208-141617.9248
-rw-r--r-- 1 akirakw akirakw  270 Dec  8 14:16 /tmp/tsurugidb.kawaguchi-desk.akirakw.log.WARNING.20231208-141617.9248

長いファイル名のログファイル、ありましたね。
ついでにショートカット用のシンボリックリンク tsurugidb.INFO などを作ってくれるようなので、これ経由で中身を見てみます。

$ less /tmp/tsurugidb.INFO

Log file created at: 2023/12/08 14:16:17
Running on machine: kawaguchi-desk
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
I1208 14:16:17.950067  9248 backend.cpp:154] /:glog:config: logtostderr: false, logtostderr for glog.
I1208 14:16:17.950199  9248 backend.cpp:158] /:glog:config: stderrthreshold: 2, stderrthreshold for glog.
...

ログ、出てましたね。

エラーログを確認

ではエラーログも見てみましょう。
Tsurugiの起動をわざと失敗させるため、Tsurugiが管理するトランザクションログファイル用のメタデータファイルをrenameしてしまいます（重要な環境では絶対にまねしないでください）。その後Tsurugiを起動してみます。

$ $TSURUGI_HOME/bin/tgctl shutdown
.
successfully shutdown tsurugidb

# わざと起動失敗させるためにトランザクションログファイル用のメタデータファイルをrename
mv var/data/log/limestone-manifest.json var/data/log/limestone-manifest.json.bak

$ $TSURUGI_HOME/bin/tgctl start
E1208 14:55:30.937510 13654 datastore_format.cpp:97] /:limestone unsupported dbdir persistent format version: see https://github.com/project-tsurugi/tsurugidb/blob/master/docs/upgrade-guide.md (version mismatch: version 0, server supports version 1)
E1208 14:55:30.937686 13654 transactional_kvs_resource.cpp:81] opening database failed
E1208 14:55:30.937716 13654 server.cpp:80] Server application framework setup phase failed.
E1208 14:55:30.937731 13654 backend.cpp:258] Starting server failed due to errors in setting up server application framework.
could not launch tsurugidb, as tsurugidb exited due to some error.

起動失敗を示すようなログが、なぜか画面に出ています。ログはファイルに出されるのではなかったでしたっけ？

とりあえずログファイルが出ているかを確認します。シンボリックリンク tsurugidb.ERROR から覗いてみます。

$ less /tmp/tsurugidb.ERROR

Log file created at: 2023/12/08 14:55:30
Running on machine: kawaguchi-desk
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
E1208 14:55:30.937510 13654 datastore_format.cpp:97] /:limestone unsupported dbdir persistent format version: see https://github.com/project-tsurugi/tsurugidb/blob/master/docs/upgrade-guide.md (version mismatch: version 0, server supports version 1)
E1208 14:55:30.937686 13654 transactional_kvs_resource.cpp:81] opening database failed
E1208 14:55:30.937716 13654 server.cpp:80] Server application framework setup phase failed.
E1208 14:55:30.937731 13654 backend.cpp:258] Starting server failed due to errors in setting up server application framework.

エラーログ、出ていましたね。それに画面に出たのと同じ内容のようです。

glogではいくつかのログの動作を設定するためのフラグ(Setting Flags)がありますが、その中で「あるログ重要度以上のログは標準エラー出力にも出力する」というフラグ stderrthreshold があり、デフォルトでこれが 2 ( ERROR 相当) に設定されています。このためにエラーログは標準エラー出力にも出力されるようになっています。
なにかしらの原因でTsurugiサーバの起動に失敗した場合、標準エラー出力にもそのエラー内容が表示されるので便利ですね。

ログの設定

では次に、ログの設定とこれを変更する方法を見ていきます。

構成定義ファイル

Tsurugiのログ設定は、基本的にはTsurugiの構成ファイル $TSURUGI_HOME/var/etc/tsurugi.ini の glog セクションで設定するようになっています。

• https://github.com/project-tsurugi/tateyama/blob/master/docs/config_parameters.md

[glog]
    #logtostderr=false
    #stderrthreshold=2
    #minloglevel=0
    #log_dir=
    #max_log_size=
    #v=0

デフォルトではすべての項目がコメントアウトされており、各項目はデフォルトで規定されている設定で動作します。設定ファイル上に書かれている値がデフォルト値です。

glogセクションの設定項目

各設定項目を見ていきます。

logtostderr

logtostderr を true に設定すると、ログはファイルではなく標準エラー出力に出力されるようになります。
開発時や遊ぶとき(?)にはこちらのほうが便利なこともあるかもしれませんね。
標準エラー出力を扱う外部ツールベースでログを管理するといった場合にもよいかもしれません。

stderrthreshold

stderrthreshold は「ここで設定したログ重要度以上のログは標準エラー出力にも出力する」というフラグです。

「ログ重要度」という言葉がさらっと出てきました。これはglogのドキュメントで「Severity Levels」として説明されているもので、いわゆるログレベルのようなものですが対応する数値と合わせて閾値の制御をしているので正確に理解しておくべきものです。

glogのログ重要度は以下のように定義されています。

Severity Level	Value
INFO	0
WARNING	1
ERROR	2
FATAL	3

そして、 stderrthreshold はこの数値と同じ、およびそれより大きい値のログを標準エラー出力にも出力する、というように機能します。
例えば stderrthreshold=0 と設定したらINFO以上の重要度のログ（つまり全てですね）が標準エラー出力にも出力されるようになります。

minloglevel

minloglevel は「ここで設定したログ重要度以上のログを出力する」というフラグです。

ログ重要度については stderrthreshold の箇所で説明しました。
デフォルトでは minloglevel=0 となっているのでINFO以上の重要度のログ（つまり全てですね）がログ出力されることになります。
例えば minloglevel=2 と設定すると ERROR, FATAL のログのみ出力され、 INFO , WARNING のログは出力されないようになります。

log_dir

ログをファイルに出力する設定している場合（つまり logtostderr=false の場合）にログが出力されるディレクトリです。未指定の場合glogのデフォルト設定（=上述で説明した /tmp ) が適用されます。

絶対パス、相対パスのどちらでも設定することが可能です。相対パスを指定した場合、環境変数 $TSURUGI_HOME で設定されているディレクトリパスからの相対パスとなります。

max_log_size

max_log_size を超えるログファイルサイズとなった場合に、glogはログファイルをローテーションします。単位はMBです。未指定の場合、glogのデフォルト設定である 1800 が適用されます。

Note

1.0.0-BETA2 では max_log_size はインストーラーに含まれるデフォルトの構成ファイルには値が明記されていませんが、デフォルト値は 1800 で動作します。1.0.0-BETA3 からデフォルトの構成ファイルにデフォルト値が明記される予定です。

v

v は出力する詳細ログ(glogのVerbose Logging)の閾値です。
Tsurugiで規定されている詳細ログのうち、ここで指定された値 以下 の詳細ログが出力されるようになります（つまりminloglevelとは逆のようなルールで設定されることに注意してください）。

Tsurugiでは、詳細ログを単発のリクエストの処理に関するメッセージやepoch毎の定期的なイベントなどを出力するためのログ（イベントログ）として利用しています。
詳細ログのレベルとしては、おおよそ以下のようなポリシーで利用しています。

• 10: error
  • 単発のイベントやリクエストに対する問題の報告
  • イベントやリクエスト処理における異常系の処理の報告
  • 通常、原因となったリクエストやイベントを成功させるために何らかのアクションが求められる
• 20: warning
  • 単発のイベントやリクエストに対する警告
• 30: info
  • 情報提供を目的としたメッセージ
• 35: debug_timing_event
  • 開発者向けデバッグ情報で、ログを出力した際の性能への影響が限定的なもののみを出力する
• 40: debug
  • より詳細な開発者向けデバッグ情報の提供を目的としたメッセージ
• 50: trace
  • さらに詳細な情報の提供を目的としたメッセージ

例えば v=40 と設定すれば error, warning, info, debug_timing_event, debug のログがそれぞれ出力されるようになります。

また重要な点として、glogのVerbose Loggingは LOG重要度(Severity Level)が INFO のログとして扱われます。そのため、minloglevel などのログ重要度を扱う設定で ログ重要度が INFO のログが出力される設定になっていないと詳細ログが出力されないことに注意してください（ややこしいですね...）。

logbuflevel

logbuflevel は「ここで設定したログ重要度以下のログをバッファリングする」というフラグです。

Note

1.0.0-BETA2 では logbuflevel はインストーラーに含まれるデフォルトの構成ファイルには含まれませんが、構成ファイルで設定可能な項目です。1.0.0-BETA3 からデフォルトの構成ファイルに含まれる予定です。

ログがバッファリングされることで、ログ出力の性能が最適化される一方、瞬時にファイルなどにその内容が反映されないというトレードオフがあります。

デフォルト設定では logbuflevel は 0 、すなわち重要度 INFO のログがバッファリング対象で、 WARN , ERROR はバッファ
リングの対象外です（この設定項目は設定値 以下 の項目を対象とするのがまたややこしいですね...）

また注意点として、 v の項目で説明したとおり、詳細ログは INFO のログとして扱われるため、デフォルトでは詳細ログもバッファリングの対象となっています。特に開発時などでは詳細ログがバッファリングされることで参照したいログが出ていないということで困る方がいると思う（筆者含む）ので注意してください。

logbuflevel に -1 を指定することで、 INFO を含むすべてのログをバッファリング対象外とすることができます。
開発時や遊ぶとき(?)にはこちらのほうが適していることもあるかもしれませんね。

GLOG_ 環境変数

glogでは環境変数 GLOG_フラグ名 という環境変数を指定することで、環境変数経由で設定フラグを指定することができます。
例えば以下のような環境変数を利用できます。

• GLOG_logtostderr=true
• GLOG_v=40

一時的にログ設定を変更したいような場合に便利ですね。

また、この方法はTsurugiのDockerイメージを利用する場合には特に便利です。
コンテナ上の設定ファイルを指定するのはちょっと面倒ですが、この方法であればDockerのコンテナ起動オプションに GLOG_ 環境変数を積むことでログレベルを変更できます。

$ docker container run -d -p 12345:12345 --name tsurugi -e GLOG_v=30 ghcr.io/project-tsurugi/tsurugidb

その他、 GLOG_ 環境変数を使うことで、Tsurugiの構成ファイルに定義されていない設定フラグを指定することもできます。
これらのフラグのほとんどはglogのドキュメントにも記載がなく、利用可能なフラグはglogのソースコードから把握するしかありませんが、興味がある方はglogの以下のソースコードなどを覗いてみるとよいと思います。

• https://github.com/google/glog/blob/master/src/logging.cc

運用ログとイベントログ

Tsurugiでは、サーバのログを大きくポリシーの異なる2種類のログに分けて管理しています。

• 運用ログ: DBMSのサーバープロセスの状態やその継続的な稼働にインパクトのある事象に関するメッセージはLOG()マクロを使用する。
• イベントログ: 単発のリクエストの処理に関するメッセージやepoch毎の定期的なイベントなどはVLOG()マクロを使用して詳細ログとして表示する

先述の設定項目でも説明した通り、LOG()マクロのログはログの重要度(Severity Levels: ERROR, WARINING, INFO)によって制御されます。一方、VLOG()のほうは詳細ログのレベル (0 ～ 50) によって制御されます。

開発時や遊ぶとき(?)には、クライアントツールやAPIに対応するサーバの動作をログとして確認したいことが多々あるかと思います。そのような時に確認したいログのほとんどはイベントログとして出力されますので、このログの違いを意識して適切なログ設定を行うことがTsurugiの挙動を把握する上で重要となります。

• see also:
  • https://github.com/project-tsurugi/jogasaki/blob/master/docs/logging_policy.md

ロケーションプレフィックス

Tsurugiでは、ソースコードにおけるログメッセージの出力位置を表すプレフィックスを下記フォーマットで定義しています。

/:<component>:<member_locator>

• <component> はコンポーネント名(jogasaki, sharksfin, tateyamaなど)
• <member_locator> はコンポーネント内でログの出力位置を特定可能な文字列
  • 末尾にコロン区切りで関数名・スコープ名などを追加してもよい
  • 例: /:jogasaki:api:impl:database

glogには他のロガーAPIでは提供されることもある、ログの種類ごとに出力先を分ける、異なるログレベルを定義する、といったような精緻なログ定義を行うことが難しくなっています。

このため、Tsurugiではこのロケーロケーションプレフィックスに基づいて grep などを使って自分が確認したいログを簡単に抽出できるようにしています。
とてもシンプルな仕組みではありますが、自分が見たいログをフィルターするためには効果的なので、ログを確認する際にはぜひこのロケーションプレフィックスを手掛かりにログを見てみてください。

• see also:
  • https://github.com/project-tsurugi/tateyama/blob/master/docs/timing_events.md

終わりに

いかがでしたでしょうか。

データベースのログはだいたいは見てもよくわからないものかもしれませんが、ログを把握することでTsurugiの挙動を理解し、もっとTsurugiに興味が湧いてくるかもしれません...。この記事がTsurugiを使う上での一助となれば幸いです。

Enjoy Tsurugi!!