豪鬼メモ

一瞬千撃

DBサービスを作ろう その1 ログとデーモン化

前回に引き続き、DBサービスの設計について検討していく。サービスと言えば、ログを記録せねばならない。また、起動プロセスと分離してデーモン化する必要がある。gRPCベースのサービスでそれらを行うにはどうすべきか考える。


まず、C++のロガーを選定する。結論から言えば、自分で拵えることにした。既存の実装としてBoostLogとかApache log4cxxとかspdlogとかがあるらしいが。パッケージの依存関係が増えるのがちょっと面倒くさい。日付とログレベルが属性として付いた任意の文字列をストリームに出力するという基本的な機能だけあれば良いので、自分で作るのも難しくはない。というか、Kyoto Tycoonの実装を改変すればすぐできそうだ。

ログ機能の実装でまず面倒くさいのは、タイムスタンプを読みやすい日付の文字列に変換することである。一般に広く使われている書式として、"2021/08/31 12:34:56" のようなYYYY/MM/DD hh:mm:ss形式をまずは実装する。また、W3CDTFとRFC 1123も実装する。

それらを実装する前に、まず時間と暦法の差異について確認しよう。UNIXにおいては、時間は、西暦の世界標準時の1970年1月1日0時0分0秒を起点とする経過秒数(から閏秒を引いたもの)である「UNIX時間」として管理される。UNIX時間は暦法とは独立である。UNIX時間は、タイムゾーン毎に変化せず、閏年閏日)の影響も受けない。しかし、UNIX時間は直感的に理解しづらいので、後処理前提のバイナリログに記録する分にはよいが、人間が読むテキストベースのログに記録するには向いていない。そこで、一般には西暦(グレゴリオ暦)に変換する。人によっては和暦やイスラム暦に変換するかもしれない。プログラマの視点で見れば、暦法とは、UNIX時間を日付の文字列にシリアライズする変換関数のユーティリティとも言える。

日付に変換するところで、タイムゾーンと時差の話が出てくる。西暦を採用するとして、単に "1978/02/11 18:35:05" と書くと、どのタイムゾーンにおいての日付なのかがわからなくなり、一意のUNIX時間に戻せない。よって、日付と一緒にそのタイムゾーンの時差を記録するとよい。W3CDTFやRFC1123といった標準規格のフォーマットは、時差の書式も定義されている。W3CDTFだと "1978-02-11T18:30:05+09:00" となるし、RFC 1123だと "Sat, 11 Feb 1978 18:30:05 +0900" となる。曜日の情報は不要だし、月を英語の名前で表記するのも冗長なので、RFC 1123形式は個人的にはあんまり好きじゃない。なのでW3CDTF一択で良いとは思っているが、所詮は好みの問題だ。一意なUNIX時間に逆変換できさえすれば、何でもいい。秒単位よりも細かい粒度で時間を記録したい場合には、W3CDTFの小数表現を使うのがよい。"1978-02-11T18:30:05.123456+09:00" のようになる。地域標準時間だけしか扱わないと割り切るなら、YYYY/MM/DD hh:mm:ss形式を使ってもよい。

ここまで述べた日付変換関数とその逆変換関数を、Tkrzwのユーティリティ tkrzw_time_util.h として実装しておいた。

// 現在のUNIX時間を得る
double GetWallTime();

// YYYY/MM/DD hh:mm:ss形式に変換
size_t FormatDateSimple(char* result, int64_t wtime, int32_t td);
size_t FormatDateSimpleWithFrac(char* result, double wtime, int32_t td, int32_t frac_cols);

// W3CDTF形式に変換
size_t FormatDateW3CDTF(char* result, int64_t wtime, int32_t td);
size_t FormatDateW3CDTFWithFrac(char* result, double wtime, int32_t td, int32_t frac_cols);

// RFC 1123形式に変換
size_t FormatDateRFC1123(char* result, int64_t wtime, int32_t td);

// UNIX時間の10進数表記、16進数表記、および上述の3形式に対応したUNIX時間への逆変換
double ParseDateStr(std::string_view str);

上記さえあれば、ロガーの実装は簡単だ。Tkrzwのユーティリティ tkrzw_logger.h として実装しておいた。データベース関連のアプリケーションはログを書くことも多いだろうから、おまけでログ機能が付いてくるのは嬉しいだろう。当然、スレッドセーフである。以下のような使い方になる。

// 標準出力ストリームを出力先にしたロガーを作る。
// ログレベルや区切り文字や日付の書式と時差も同時に指定できる
// 時差をINT32MINにするとシステムのタイムゾーン情報から設定する
StreamLogger logger(&std::cout, Logger::INFO, " ",
  tkrzw::BaseLogger::DATE_W3CDTF_MICRO, INT32MIN);

// 任意の文字列を記録する
logger.Log(Logger::INFO, "I am a boy.");

// printf互換フォーマット文字列でログを記録する
logger.LogF(Logger::ERROR, "I have %d books.", 2);

// 任意の型のデータを文字列として連結してログを記録する
logger.LogCat(Logger::FATAL, "x", 2, "-", 3.5);

// 別のストリームに動的に切り替えも可能
logger.SetStream(&anoter_stream);

以下のような文字列が出力される。

2021-08-31T12:30:22.323922+09:00 [INFO] I am a boy.
2021-08-31T12:30:22.324078+09:00 [ERROR] I have 2 books.
2021-08-31T12:30:22.324152+09:00 [FATAL] x2-3.5

StreamLoggerはストリームを与えるとそれにログを記録するという機能だけを提供することで、ログの記録とログファイルの管理の責任を分離する。これのラッパーとしてログローテーション機能を持つロガーを実装しても良いが、今のところは必要ない。

ロガーを使う上で、非常に重要な点がある。ログメッセージの構築をなるべく自前で行わないことだ。例えば、文字列を連結するStrCat関数を呼んで自前でメッセージを構築するとしよう。その場合、ログレベルのフィルタによって実際には出力されない場合にも、ログメッセージを構築するための負荷がかかってしまう。

logger.Log(Logger::DEBUG, StrCat("My name is ", name, ", Living in ", country, "."));

その代わりに、ロガーに組み込まれたLogCatやLogFを使うべきだ。それらは先にログレベルを調べて、必要なければ文字列の生成を省略してくれる。これはリクエスト毎などの非常に頻繁な頻度でトレース情報やデバッグ情報を出力する際には特に重要になる。

logger.Log(Logger::DEBUG, "My name is ", name, ", Living in ", country, ".");

自前でログメッセージを構築する場合で、それがそれなりの負荷をかける場合には、先にログレベルを調べる処理を自分で呼ぶべきだ。ダサいようだが、仕方がない。出力しないログがボトルネックになるのは笑えない話なので。

if (logger.CheckLevel(Logger::DEBUG)) {
  const std::string message = StrCat("proto=", proto.Utf8DebugString());
  logger.Log(Logger::DEBUG, message);
}


Tkrzw-RPCのサービスにログを組み込もう。デフォルトでは、ログは標準出力に吐き出すようにする。そして、コマンド引数でログの出力先を任意のファイルに変更できるようにする。ログレベルも設定できるようにする。

$ tkrzw_server --log_file tkrzw_server.log --log_level debug

ログファイルの管理は、サービスとは独立した別のプログラムの責任にした方がよい。結局は、ログの出力先を変えるログローテート以上のことをしないといけないからだ。世代管理とか圧縮とか他のサーバへの転送とかだ。それをロガー自体にやらせると実装が際限なく肥大化してしまう。適当なシェルスクリプトで管理できるようにした方が柔軟だ。

サーバプログラムは、起動時に指定されたファイルにログを書き続ける。そんな中でログローテーションをどうやるかと言うと、そのファイルをリネームしてしまえばよい。UNIXにおいては、ファイル名とinodeは別のレイヤーである。ファイルをリネームしてもinodeは変わらない。あるファイルを開いたプロセスがいる状態でそのファイルをリネームしても、そのプロセスはリネームしたファイルの読み書きを何ら問題なく続けてくれる。プロセスが知っているのはファイルディスクリプタだけで、それはあくまでinodeと関連付けられているからだ。

UNIX文化においては、サービスのプロセスにSIGHUPを送ると、プロセスを再起動するか、起動したままログファイルや設定ファイルを開き直すということになっている。本来、SIGHUPは端末がハングアップしたから死ねという意味なのだが、デーモン化したプロセスは端末と繋がっていないということで、別目的に転用できるということらしい。それを踏襲して、tkrzw_serverもSIGHUPを受信したらログファイルを開き直す。この操作によって、ログの出力先が引数で指定された元のファイルに戻る。これによってログローテーションが成立するというわけだ。

// グローバル変数
StreamLogger* g_logger = nullptr;
std::string_view g_log_file;
std::string_view g_log_level;
std::string_view g_log_date;
std::ofstream* g_log_stream = nullptr;
std::atomic<grpc::Server*> g_server(nullptr);

// SIGHUPのコールバック関数
Status ConfigLogger() {
  if (g_log_stream->is_open()) {
    g_log_stream->close();
    if (!g_log_stream->good()) {
      return Status(Status::SYSTEM_ERROR, "log close failed");
    }
  }
  if (g_log_file.empty()) {
    g_logger->SetStream(nullptr);
    g_logger->SetMinLevel(Logger::NONE);
  } else {
    g_log_stream->open(std::string(g_log_file), std::ios::app);
    if (!g_log_stream->good()) {
      return Status(Status::SYSTEM_ERROR, "log open failed");
    }
    g_logger->SetStream(g_log_stream);
    g_logger->SetMinLevel(Logger::ParseLevelStr(g_log_level));
    g_logger->SetDateFormat(BaseLogger::ParseDateFormatStr(g_log_date));
  }
  return Status(Status::SUCCESS);
}

// メイン関数
void Process() {
  ...
  // ロガーの寿命はメイン関数に合わせて、そのポインタをグローバルにする
  StreamLogger logger;
  g_logger = &logger;
  // ログファイルのパスなどもグローバル変数として参照できるようにする
  g_log_file = std::string_view(log_file);
  g_log_level = std::string_view(log_level);
  g_log_date = std::string_view(log_date);
  std::ofstream log_stream;
  g_log_stream = &log_stream;
  // ロガーを初期化する
  ConfigLogger();
  // シグナルを受け取ったらロガーを再初期化する
  std::signal(SIGHUP, ReconfigServer);
  ...
}

サーバ側の各RPCコールの冒頭にて、クライアントの情報とリクエストの内容をデバッグログとして出力する関数を用意しよう。デバッグ時にのみだけ負荷が発生するように、CheckLevelで保護している。

class DBMServiceImpl : public DBMService::Service {
public:
  void LogRequest(grpc::ServerContext* context, const char* name,
                  const google::protobuf::Message* proto) {
    if (!logger_->CheckLevel(Logger::DEBUG)) {
      return;
    }
    static std::regex regex_linehead("\\n\\s*");
    std::string proto_text =  std::regex_replace(proto->Utf8DebugString(), regex_linehead, " ");
    while (!proto_text.empty() && proto_text.back() == ' ') {
      proto_text.resize(proto_text.size() - 1);
    }
    std::string message = StrCat(context->peer(), " [", name, "]");
    if (proto_text.empty()) {
      message += " ";
      message += proto_text;
    }
    logger_->Log(Logger::DEBUG, message);
  }

  grpc::Status Echo(
      grpc::ServerContext* context, const EchoRequest* request,
      EchoResponse* response) override {
    LogRequest(context, "Echo", request);
    response->set_echo(request->message());
    return grpc::Status::OK;
  }
};

こうしておくと、以下のようなメッセージが出力されるようになる。

2021-08-26T19:00:16+09:00 [INFO] ==== Starting the process as a command ====
2021-08-26T19:00:16+09:00 [INFO] Opening a database: #dbm=tiny
2021-08-26T19:00:16+09:00 [INFO] address=0.0.0.0:1978, pid=243069
2021-08-26T19:00:27+09:00 [DEBUG] ipv4:127.0.0.1:56026 [GetVersion] message: "hello"
2021-08-26T19:00:30+09:00 [DEBUG] ipv4:127.0.0.1:56028 [Inspect]
2021-08-26T19:00:33+09:00 [DEBUG] ipv4:127.0.0.1:56030 [Set] key: "tako" value: "ika" overwrite: true
2021-08-26T19:00:37+09:00 [DEBUG] ipv4:127.0.0.1:56032 [Get] key: "tako"
2021-08-26T19:00:41+09:00 [DEBUG] ipv4:127.0.0.1:56034 [Remove] key: "tako"
2021-08-26T19:00:55+09:00 [INFO] Shutting down by signal: 15
2021-08-26T19:00:55+09:00 [INFO] The server finished
2021-08-26T19:00:55+09:00 [INFO] Closing a database
2021-08-26T19:00:55+09:00 [INFO] ==== Ending the process in success ====


サービスはデーモン化するべきである。demon(悪魔)ではなくdaemon(守護神)と綴るらしいが、不死身にするというのが元々の意味だ。要は起動端末から殺せなくなるとともに、親プロセスに起因する制約から解放されているというのがデーモンプロセスの要件だ。そのため、デーモン化には以下の手順が必要となる。

  • 標準出力と標準エラー出力の内容をフラッシュする
  • プロセスをforkした直後に親は死に、子だけになる
    • この瞬間に孤児になり、里親がinitになる。
    • 親が死ぬ際にはexitでなく_exitで死に、on_exitのコールバックを無視する
  • setsidで新規端末セッションを開始し、自身がセッションリーダーかつプロセスグループリーダーになる
  • signalでSIGHUPとSIGCHLDを無視して、親類の死亡を無視する
  • さらにプロセスをforkした直後に親は死に、子だけになる。
    • これによってリーダーがいないセッショングループに自分だけが所属する
  • umaskでファイルモードの制約を外す
  • chdirでルートディレクトリに移動する
  • 標準入力、標準出力、標準エラー出力を閉じる
  • /dev/null を新たな標準入力、標準出力、標準エラー出力に設定する

以上のことを実装すると、こんなようなコードになる。

Status DaemonizeProcess() {
  std::cout << std::flush;
  std::cerr << std::flush;
  switch (fork()) {
    case -1: {
      return GetErrnoStatus("fork", errno);
    }
    case 0: {
      break;
    }
    default: {
      _exit(0);
    }
  }
  if (setsid() == -1) {
    return GetErrnoStatus("setsid", errno);
  }
  signal(SIGHUP, SIG_IGN);
  signal(SIGCHLD, SIG_IGN);
  switch (fork()) {
    case -1: {
      return GetErrnoStatus("fork", errno);
    }
    case 0: {
      break;
    }
    default: {
      _exit(0);
    }
  }
  umask(0);
  if (chdir("/") == -1) {
    return GetErrnoStatus("chdir", errno);
  }
  close(0);
  close(1);
  close(2);
  const int32_t fd = open("/dev/null", O_RDWR, 0);
  if (fd != -1) {
    dup2(fd, 0);
    dup2(fd, 1);
    dup2(fd, 2);
    if (fd > 2) {
      close(fd);
    }
  }
  return Status(Status::SUCCESS);
}

tkrzw_serverを起動する際にデーモン化できるようにオプションをつける。また、デーモン化すると端末から殺せなくなるので、停止するにはプロセスIDを指定してシグナルを送る必要がある。よって、起動時にプロセスIDをファイルに記録しておくと便利だ。実運用ではデーモンはOSの起動スクリプトで起動することが多いだろうが、テスト時に端末から起動するには以下のようにする。デーモンになると全てのファイルは絶対パスで指定することになる。

$ tkrzw_server --daemon --pid_file $HOME/tkrzw_server.pid \
  --log_file $HOME/tkrzw_server.log --log_level debug

デーモンを殺すには、プロセスIDのファイルを読み込んで、以下のようにすればよい。殺すといっても、TERMシグナルを送るだけだ。サーバ側は、リクエストの受信を停止し、データベースファイルを閉じた上で、gracefullyに自死するように実装する。実運用ではこのようにTERMシグナルを送る処理もOSの終了スクリプトとして登録することになるだろう。

$ kill -TERM $(cat $HOME/tkrzw_server.pid)

ログローテーションは以下のように実行することになる。この処理を行うスクリプトはcronで定期的に起動することになるだろう。

$ mv $HOME/tkrzw_server.log $HOME/tkrzw_server.log.$(date "+%Y%m%d%H%M%S")
$ kill -HUP $(cat $HOME/tkrzw_server.pid)

デーモンプロセスの作法をきちんと理解するのは簡単ではない。gRPCのおかげでRPC層の可搬性は格段に向上したが、デーモン化などの部分はまだまだOS依存の処理を書かねばならない。とはいえ、一回覚えればどんなサービスでも共通なので、覚えておいて損はない。


まとめ。これからサーバプロセスを実装していくにあたり、まずはログとデーモン化の機能を実装した。特にログ機能はいかなるサービスでも必要になるし、コードの広い範囲で横断的に利用されるので、かなり初期の段階で実装した方が、結果的に作業が効率化する。次回はいよいよデータベースサービスの具体的なAPIを設計していく。