helloworld の次に書く gRPC の C++ プログラム

はじめに

gRPC はじめました。ついこの前まで Python で Falcon で RESTful API だなどと粋がっていましたが、RESTful API のブームは過ぎ去り、gRPC がマイブームです。

grpc / grpc.io
http://www.grpc.io/

gRPC とは、Google 様が作った RPC のライブラリです。主な特徴は、

• 多言語対応
  2017/4/25 現在での対応言語: C++/Java/Python/Go/Ruby/C#/Node.js/Android Java/Objective-C/PHP
• HTTP/2 通信

の 2 つだと思います。

私が今書いてるプログラムにおいて、Web API から gRPC に全面移行するまでの思考の流れは次のような感じでした。

• Web API の呼び出し側は C++ で書く必要があり、HTTP クライアントのライブラリに curlpp を選んで軽くコードを書いてみたところ、感触は良かった
• が、作りたいプログラムでは Web API 以外でも通信を行いたかったため、そもそも Falcon + curlpp だけでは足りず、一般的なソケット通信用のライブラリが必要になった
• C++ でのソケット通信と言えば、Boost.Asio だが、Boost は嫌いではないが積極的に使うのは躊躇われる
• Windows に対応する予定はないので、POSIX の API を直に使ってもいいが・・いや、そもそもどうせソケット プログラミングするなら Web API は要らないのでは・・

というわけで、一つのプロトコルで済ませられるようなソリューションを探したところ、gRPC が浮上してきました。Web API に比べてパフォーマンスも良さそうだし、後で Python と連携させることもできそうだし、HTTP/2 のストリーミングとかも将来使えそう・・ということで決めました。最初に気付けよって話ですが。

公式サイトには、対応言語それぞれについて Quick Start Guide と Basics Tutorial があり、前者では helloworld という 1:1 のクライアント/サーバー (同期と非同期は両方カバー)、後者では route_guide というサンプルでストリーミング通信のやり方が説明されています。そもそも gRPC を C++ で使おうとする人間なら、その程度の情報があれば後は適当に羽ばたいていけそうですが、ネット上に落ちているサンプルは多い方がいいと思いましたので、私が勉強のために書いたしょぼいサンプルをここで共有しておこうと思います。

Qiita に gRPC のタグはありますが、「C++ でコードを書いてみた」的な記事は見つかりませんでした。「Visual C++ でビルドしてみた」的な記事はありました。Windows だといろいろ大変なのかもしれません。

本記事における開発環境は以下の通りです。

• Ubuntu 16.04.2 LTS
• g++ 5.4.0

gRPC のビルド (/usr/local 以外にインストールする場合)

記事執筆時点では、 C++ ではソースからのビルドが必須と書かれています。

gRPC - C++ Quickstart
http://www.grpc.io/docs/quickstart/cpp.html

grpc/INSTALL.md at master - grpc/grpc
https://github.com/grpc/grpc/blob/master/INSTALL.md

前述の通り、gRPC では HTTP/2 をプロトコルとして通信を行います。HTTP/2 のペイロードは、Protocol Buffers という Google が策定した別のプロトコルを使ってデータをシリアライズすることで作られます。したがって gRPC をビルドするためには Protocol Buffers のバイナリが必要になるのですが、gRPC リポジトリのサブモジュールの一つとして組み込まれており、Protocol Buffers もビルドすることが推奨のような感じです。

ビルドの手順は、Quickstart に書かれているコマンドを順次実行するだけなので簡単ですが、これは全てのバイナリを /usr/local 下にインストールすることが前提となっています。それでも構わないのであれば特に問題はありませんが、独自のディレクトリに sudo を使わずにインストールすることが私の最近の流儀であるため、公式のコマンドに若干の変更が必要でした。

Protocol Buffers と gRPC のバイナリを以下のディレクトリにインストールする前提で進めます。

モジュール	ソース (Git リポジトリ)	インストール先
Protocol Buffers	/data/src/grpc/third_party/protobuf	/data/bin/protobuf/protobuf-dev
gRPC	/data/src/grpc	/data/bin/grpc/grpc-dev

初めに、必要なパッケージをインストールして、ソースコードをクローンします。

$ sudo apt-get install build-essential autoconf libtool curl git
$ git clone https://github.com/grpc/grpc.git
$ cd grpc
$ git submodule update --init

Protocol Buffers をビルドしてインストールします。

$ cd third_party/protobuf/
$ ./autogen.sh
$ ./configure --prefix=/data/bin/protobuf/protobuf-dev
$ make -j4
$ make install

最後に gRPC のビルドとインストールを行います。カスタム ディレクトリに入っている Protocol Buffers のバイナリを使うため、環境変数を幾つか変更します。

$ cd ../../
$ export PKG_CONFIG_PATH=/data/bin/protobuf/protobuf-dev/lib/pkgconfig:/data/bin/grpc/grpc-dev/lib/pkgconfig
$ export PATH=/data/bin/protobuf/protobuf-dev/bin:/data/bin/grpc/grpc-dev/bin:$PATH
$ export LD_LIBRARY_PATH=/data/bin/protobuf/protobuf-dev/lib:/data/bin/grpc/grpc-dev/lib
$ EXTRA_LDFLAGS=-L/data/bin/protobuf/protobuf-dev/lib make -j4
$ make prefix=/data/bin/grpc/grpc-dev install

ただし、上記方法だと gRPC のバイナリにデバッグ情報が含まれない (コンパイル/リンクの後に strip で削除される) ので、後でデバッグするときに困ります。デバッグ情報を付加するには、CONFIG=dbg を付けて make します。

$ EXTRA_LDFLAGS=-L/data/bin/protobuf/protobuf-dev/lib CONFIG=dbg make prefix=/data/bin/grpc/grpc-dev -j4
$ CONFIG=dbg make prefix=/data/bin/grpc/grpc-dev install

ライブラリのビルドが終わったら、次に試したいのは helloworld です。これはリポジトリの examples/cpp/helloworld/ に入っており、Quickstart には、make を実行するだけでビルドできるように書かれています。が、Makefile を読むと分かるように、ここでもバイナリが /usr/local がインストールされていることが前提になっているため、それ以外の場所にインストールした場合、ビルドできません。

Makefile に /usr/local がハードコードされているのは美しくないので、修正してプル リクエストを送っておきました。

Update compiler/linker options to use pkg-config in C++ examples by msmania - Pull Request #10814 - grpc/grpc
https://github.com/grpc/grpc/pull/10814

サンプル コード、しかも Makefile の修正だけという優先度が底辺のリクエストなので、マージされるかどうかは不明です。 (2017/6/14 追記) ほぼ諦めていましたが、無事マージしてくれました。よかった！

いずれにせよ、helloworld のサンプルを動かすには、Makefile 内の CPPFLAGS と LDFLAGS を変更する必要があります。また helloworld では、Makefile 内で pkg-config を使っているため、前述のビルド コマンドに書いたように環境変数 PKG_CONFIG_PATH の変更が必要です。

さらに、そのままだと helloworld のデバッグ情報も生成されないので、デバッグ情報付きでビルドするには CPPFLAGS=-g make のように別途 -g オプションをつけてコンパイルを実行する必要があります。

独自サンプル StringExchanger の作成

ようやく本題です。勉強がてら、string_exchanger というサンプルを書きました。

msmania/grpc-tutorial: Just another gRPC tutorial in C++
https://github.com/msmania/grpc-tutorial

リポジトリのルートにある helloworld というディレクトリは、gRPC の helloworld をコピーして、ビルドとデバッグが簡単にできるように幾つかの変更を加えたものです。gRPC の調査用です。

string_exchanger 内での gRPC の使い方は、ストリーミングを使わない (= Unary RPC と呼ぶらしい) 同期通信という最も単純な例です。非同期で使いたかったのですが、CompletionQueue の使い方をまだ把握できていないので、とりあえず同期通信をマルチスレッドで動かすという方針にしました。

以下、プログラムの概要とともに、gRPC を使ったアプリケーションの開発における、ソースコードの検索と gdb によるデバッグを活用した事例を紹介します。

プログラム概要

プロセス内で std::vector<std::string> を一つ持たせて、ランダムに選んだ要素を gRPC メソッドを使ってプロセス間で送受信します。Exchanger とはいうものの、実際は Push というメソッドで相手に文字列を送り付けるだけなので、StringPusher と言った方が正しいです。

図示してみました。絵心が無さ過ぎて辛い。

(2017/4/30 - 最初の図が間違っていたので、修正しました。)

図示したスレッドの概要は以下の通りです。

• UI thread: readline() でユーザー入力を受け取ってローカルの配列に文字列を追加するスレッド
• gRPC server thread: ワーカー スレッドを作って待機するスレッド
• gRPC worker thread: リクエストを受け取って gRPC メソッドを実行するスレッド (gRPC ランタイムが作成)
• gRPC client thread: gRPC メソッドのスタブを呼び出すスレッド (POSIX タイマーが作成)

main 関数の中で readline を呼んで入力を受け取ります。これが UI thread になります。同時に gRPC サーバーとしても動作させるため、pthread_create でスレッド作って grpc::ServerBuilder::Wait を呼びます。前述のようにスレッド内での待機は同期処理なので、Wait() から制御が返ってくることはありません。デバッグしてみると、gRPC メソッドの実体である string_exchanger::Push が実行される場所はサーバーの待機スレッドではなく、待機スレッドが作成したワーカー スレッドでした。このあたりの動作については、以下の記事にまとめました。gRPC の同期サーバーの内部には高機能なスレッド プールが実装されており、ワーカー スレッドの数が動的に調節されるようになっています。

helloworld で学ぶ gRPC の C++ におけるスレッド処理 - Qiita
http://qiita.com/msmania/items/123b3dd333e0c87f572d

gRPC クライアントとしての動作は、POSIX タイマーを使って定期的にメソッドを呼び出すことにしました。timer_create でタイマーを作る際に、通知の手段として SIGEV_THREAD を渡しています。したがって定期的にタイマー スレッドが作られ、スタブを同期実行してからそのスレッドは終了します。ちょっとデザイン的に微妙かもしれません。もともとは SIGEV_SIGNAL を渡してシグナル ハンドラで処理していたのですが、シグナルのブロックがなぜかうまく動かず、断念しました。Linux に関する知識不足です。勉強が足りない。情けない。

細かい部分でも改善の余地はまだまだありそうなので、気づいたところは随時直します。

pkg-config に頼らない gRPC プログラムのビルド

ビルドを簡潔にするため、Makefile 内で protobuf と grpc のインストール ディレクトリをマクロで指定できるようにしました。pkg-config も使っていません。Makefile の先頭の PROTOBUF_INSTALL_DIR と GRPC_INSTALL_DIR を環境に合わせて変更し、LD_LIBRARY_PATH を設定して make すればビルドできます。ビルドのためのコマンド例は以下の通り。

$ sudo apt-get install libreadline6-dev
$ git clone https://github.com/msmania/grpc-tutorial.git
$ cd grpc-tutorial/
$ LD_LIBRARY_PATH=/data/bin/protobuf/protobuf-dev/lib:/data/bin/grpc/grpc-dev/lib make

gRPC とは関係ありませんが、プログラムの中で readline() を使っているため libreadline6-dev パッケージが必要です。

最後のコマンドで make を実行すると、bin/t という実行可能ファイルができますが、これも LD_LIBRARY_PATH を設定しないと gRPC 及び Protocol Buffers の共有オブジェクトをロードできません。毎回指定するのは面倒なので、ldconfig でキャッシュを作っておきます。

$ echo /data/bin/protobuf/protobuf-dev/lib | sudo tee -a /etc/ld.so.conf.d/grpc.conf
/data/bin/protobuf/protobuf-dev/lib
$ echo /data/bin/grpc/grpc-dev/lib | sudo tee -a /etc/ld.so.conf.d/grpc.conf
/data/bin/grpc/grpc-dev/lib
$ cat /etc/ld.so.conf.d/grpc.conf
/data/bin/protobuf/protobuf-dev/lib
/data/bin/grpc/grpc-dev/lib
$ sudo ldconfig
$ ldconfig -p | grep 'lib\(protobuf\|grpc\)'
        libprotobuf.so.12 (libc6,x86-64) => /data/bin/protobuf/protobuf-dev/lib/libprotobuf.so.12
        libprotobuf.so.9 (libc6,x86-64) => /usr/lib/x86_64-linux-gnu/libprotobuf.so.9
        libprotobuf.so (libc6,x86-64) => /data/bin/protobuf/protobuf-dev/lib/libprotobuf.so
        libprotobuf.so (libc6,x86-64) => /usr/lib/x86_64-linux-gnu/libprotobuf.so
        libprotobuf-lite.so.12 (libc6,x86-64) => /data/bin/protobuf/protobuf-dev/lib/libprotobuf-lite.so.12
        libprotobuf-lite.so.9 (libc6,x86-64) => /usr/lib/x86_64-linux-gnu/libprotobuf-lite.so.9
        libprotobuf-lite.so (libc6,x86-64) => /data/bin/protobuf/protobuf-dev/lib/libprotobuf-lite.so
        libprotobuf-lite.so (libc6,x86-64) => /usr/lib/x86_64-linux-gnu/libprotobuf-lite.so
        libgrpc_unsecure.so.4 (libc6,x86-64) => /data/bin/grpc/grpc-dev/lib/libgrpc_unsecure.so.4
        libgrpc_unsecure.so (libc6,x86-64) => /data/bin/grpc/grpc-dev/lib/libgrpc_unsecure.so
        libgrpc_cronet.so.4 (libc6,x86-64) => /data/bin/grpc/grpc-dev/lib/libgrpc_cronet.so.4
        libgrpc_cronet.so (libc6,x86-64) => /data/bin/grpc/grpc-dev/lib/libgrpc_cronet.so
        libgrpc.so.4 (libc6,x86-64) => /data/bin/grpc/grpc-dev/lib/libgrpc.so.4
        libgrpc.so (libc6,x86-64) => /data/bin/grpc/grpc-dev/lib/libgrpc.so
        libgrpc++_unsecure.so.1 (libc6,x86-64) => /data/bin/grpc/grpc-dev/lib/libgrpc++_unsecure.so.1
        libgrpc++_unsecure.so (libc6,x86-64) => /data/bin/grpc/grpc-dev/lib/libgrpc++_unsecure.so
        libgrpc++_reflection.so.1 (libc6,x86-64) => /data/bin/grpc/grpc-dev/lib/libgrpc++_reflection.so.1
        libgrpc++_reflection.so (libc6,x86-64) => /data/bin/grpc/grpc-dev/lib/libgrpc++_reflection.so
        libgrpc++_error_details.so.1 (libc6,x86-64) => /data/bin/grpc/grpc-dev/lib/libgrpc++_error_details.so.1
        libgrpc++_error_details.so (libc6,x86-64) => /data/bin/grpc/grpc-dev/lib/libgrpc++_error_details.so
        libgrpc++_cronet.so.1 (libc6,x86-64) => /data/bin/grpc/grpc-dev/lib/libgrpc++_cronet.so.1
        libgrpc++_cronet.so (libc6,x86-64) => /data/bin/grpc/grpc-dev/lib/libgrpc++_cronet.so
        libgrpc++.so.1 (libc6,x86-64) => /data/bin/grpc/grpc-dev/lib/libgrpc++.so.1
        libgrpc++.so (libc6,x86-64) => /data/bin/grpc/grpc-dev/lib/libgrpc++.so

これで、次回以降 LD_LIBRARY_PATH の設定は不要です。

ソースコード検索事例 - メソッドのタイムアウトの設定方法を調べる

ネットワーク要因などで通信がうまくできない場合、gRPC クライアント側のスタブの呼び出しからすぐに制御が返ってきません。これでは困るので、タイムアウト値を設定したくなると思います。

helloworld でスタブを呼び出す部分を以下に抜粋しました。タイムアウト値を設定できるとすれば ClientContext が怪しいです。

    // Context for the client. It could be used to convey extra information to
    // the server and/or tweak certain RPC behaviors.
    ClientContext context;

    // The actual RPC.
    Status status = stub_->SayHello(&context, request, &reply);

gRPC のクラス リファレンスを見ます。

GRPC C++: grpc::ClientContext Class Reference
http://www.grpc.io/grpc/cpp/classgrpc_1_1_client_context.html

set_deadline というそれっぽい関数がありました。その説明が ↓。

template<typename T >
void grpc::ClientContext::set_deadline(const T & deadline)

Set the deadline for the client call.
Warning: This method should only be called before invoking the rpc.
Parameters: deadline - the deadline for the client call. Units are determined by the type used.

いや、これじゃ分からないだろ・・・特に引数の型が。というわけでソースコードを "set_deadline" というキーワードで検索します。

テストコードで何ヶ所かヒットしました。std::chrono にある型を使って時刻を渡せばよさそうだと分かりました。

// Set a 10us deadline and make sure proper error is returned.
TEST_P(ProxyEnd2endTest, RpcDeadlineExpires) {
  ResetStub();
  EchoRequest request;
  EchoResponse response;
  request.set_message("Hello");
  request.mutable_param()->set_skip_cancelled_check(true);

  ClientContext context;
  std::chrono::system_clock::time_point deadline =
      std::chrono::system_clock::now() + std::chrono::microseconds(10);
  context.set_deadline(deadline);
  Status s = stub_->Echo(&context, request, &response);
  EXPECT_EQ(StatusCode::DEADLINE_EXCEEDED, s.error_code());
}

StringExchanger では、タイマー スレッドの string_exchanger::timer_handler で set_deadline を呼んでいます。

デバッグ事例 - gRPC ログ設定

helloworld サンプルのサーバー プログラムである greeter_server を呼ぶと、次のようなログが出力されます。マルチ スレッドで動かしている場合、意図しないタイミングで標準出力に文字が出力されるのは避けたいです。これを無効にしてみます。

$ ./greeter_server
I0426 16:14:42.514940293   11457 server_builder.cc:258]      Synchronous server. Num CQs: 1, Min pollers: 1, Max Pollers: 2, CQ timeout (msec): 10000
Server listening on 0.0.0.0:50051

ログには、親切にも server_builder.cc:258 というファイル名と行番号が出力されているので、まずは場所を確認します。

  if (has_sync_methods) {
    // This is a Sync server
    gpr_log(GPR_INFO,
            "Synchronous server. Num CQs: %d, Min pollers: %d, Max Pollers: "
            "%d, CQ timeout (msec): %d",
            sync_server_settings_.num_cqs, sync_server_settings_.min_pollers,
            sync_server_settings_.max_pollers,
            sync_server_settings_.cq_timeout_msec);

gpr_log という関数が呼ばれています。ここからソースコードを辿っていくだけでもいいのですが、それでは面白くないので gdb を使ってみましょう。

$ gdb greeter_server
(gdb) b gpr_log
Function "gpr_log" not defined.
Make breakpoint pending on future shared library load? (y or [n]) y
Breakpoint 1 (gpr_log) pending.

(gdb) r
Starting program: /data/src/grpc/examples/cpp/helloworld/greeter_server
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".

Breakpoint 1, gpr_log (file=0x7ffff7b86540 "src/cpp/server/server_builder.cc", line=258,
    severity=GPR_LOG_SEVERITY_INFO,
    format=0x7ffff7b86630 "Synchronous server. Num CQs: %d, Min pollers: %d, Max Pollers: %d, CQ timeout (msec): %d") at src/core/lib/support/log_linux.c:60
60                   const char *format, ...) {
=> 0x00007ffff63f579b <gpr_log+87>:     64 48 8b 04 25 28 00 00 00      mov    %fs:0x28,%rax
   0x00007ffff63f57a4 <gpr_log+96>:     48 89 85 48 ff ff ff    mov    %rax,-0xb8(%rbp)
   0x00007ffff63f57ab <gpr_log+103>:    31 c0   xor    %eax,%eax

(gdb) bt
#0  gpr_log (file=0x7ffff7b86540 "src/cpp/server/server_builder.cc", line=258,
    severity=GPR_LOG_SEVERITY_INFO,
    format=0x7ffff7b86630 "Synchronous server. Num CQs: %d, Min pollers: %d, Max Pollers: %d, CQ timeout (msec): %d") at src/core/lib/support/log_linux.c:60
#1  0x00007ffff7b192be in grpc::ServerBuilder::BuildAndStart (this=0x7fffffffe330)
    at src/cpp/server/server_builder.cc:263
#2  0x0000000000412885 in RunServer () at greeter_server.cc:75
#3  0x00000000004129c6 in main (argc=1, argv=0x7fffffffe548) at greeter_server.cc:84

gpr_log にヒットしました。BuildAndStart() を呼んだ時点でログが出力されるようです。ステップインしてこの後の流れを追いかけます。

(gdb) s
61        char *message = NULL;
=> 0x00007ffff63f57ad <gpr_log+105>:    48 c7 85 28 ff ff ff 00 00 00 00        movq   $0x0,-0xd8(%rbp)
(gdb) n
63        va_start(args, format);
=> 0x00007ffff63f57b8 <gpr_log+116>:    c7 85 30 ff ff ff 20 00 00 00   movl   $0x20,-0xd0(%rbp)
   0x00007ffff63f57c2 <gpr_log+126>:    c7 85 34 ff ff ff 30 00 00 00   movl   $0x30,-0xcc(%rbp)
   0x00007ffff63f57cc <gpr_log+136>:    48 8d 45 10     lea    0x10(%rbp),%rax
   0x00007ffff63f57d0 <gpr_log+140>:    48 89 85 38 ff ff ff    mov    %rax,-0xc8(%rbp)
   0x00007ffff63f57d7 <gpr_log+147>:    48 8d 85 50 ff ff ff    lea    -0xb0(%rbp),%rax
   0x00007ffff63f57de <gpr_log+154>:    48 89 85 40 ff ff ff    mov    %rax,-0xc0(%rbp)
(gdb) n
64        if (vasprintf(&message, format, args) == -1) {
=> 0x00007ffff63f57e5 <gpr_log+161>:    48 8d 95 30 ff ff ff    lea    -0xd0(%rbp),%rdx
   0x00007ffff63f57ec <gpr_log+168>:    48 8b 8d 08 ff ff ff    mov    -0xf8(%rbp),%rcx
   0x00007ffff63f57f3 <gpr_log+175>:    48 8d 85 28 ff ff ff    lea    -0xd8(%rbp),%rax
   0x00007ffff63f57fa <gpr_log+182>:    48 89 ce        mov    %rcx,%rsi
   0x00007ffff63f57fd <gpr_log+185>:    48 89 c7        mov    %rax,%rdi
   0x00007ffff63f5800 <gpr_log+188>:    e8 0b 06 f6 ff  callq  0x7ffff6355e10 <vasprintf@plt>
   0x00007ffff63f5805 <gpr_log+193>:    83 f8 ff        cmp    $0xffffffff,%eax
   0x00007ffff63f5808 <gpr_log+196>:    74 33   je     0x7ffff63f583d <gpr_log+249>
(gdb) n
69        gpr_log_message(file, line, severity, message);
=> 0x00007ffff63f580a <gpr_log+198>:    48 8b 8d 28 ff ff ff    mov    -0xd8(%rbp),%rcx
   0x00007ffff63f5811 <gpr_log+205>:    8b 95 10 ff ff ff       mov    -0xf0(%rbp),%edx
   0x00007ffff63f5817 <gpr_log+211>:    8b b5 14 ff ff ff       mov    -0xec(%rbp),%esi
   0x00007ffff63f581d <gpr_log+217>:    48 8b 85 18 ff ff ff    mov    -0xe8(%rbp),%rax
   0x00007ffff63f5824 <gpr_log+224>:    48 89 c7        mov    %rax,%rdi
   0x00007ffff63f5827 <gpr_log+227>:    e8 44 3f f6 ff  callq  0x7ffff6359770 <gpr_log_message@plt>
(gdb) s
gpr_log_message (file=0x7ffff7b86540 "src/cpp/server/server_builder.cc", line=258,
    severity=GPR_LOG_SEVERITY_INFO,
    message=0x631790 "Synchronous server. Num CQs: 1, Min pollers: 1, Max Pollers: 2, CQ timeout (msec): 10000") at src/core/lib/support/log.c:62
62                           const char *message) {
=> 0x00007ffff63f55cd <gpr_log_message+22>:     64 48 8b 04 25 28 00 00 00      mov    %fs:0x28,%rax
   0x00007ffff63f55d6 <gpr_log_message+31>:     48 89 45 f8     mov    %rax,-0x8(%rbp)
   0x00007ffff63f55da <gpr_log_message+35>:     31 c0   xor    %eax,%eax
(gdb) n
63        if ((gpr_atm)severity < gpr_atm_no_barrier_load(&g_min_severity_to_print)) {
=> 0x00007ffff63f55dc <gpr_log_message+37>:     8b 45 d0        mov    -0x30(%rbp),%eax
   0x00007ffff63f55df <gpr_log_message+40>:     48 8b 15 7a e3 3b 00    mov    0x3be37a(%rip),%rdx        # 0x7ffff67b3960 <g_min_severity_to_print>
   0x00007ffff63f55e6 <gpr_log_message+47>:     48 39 d0        cmp    %rdx,%rax
   0x00007ffff63f55e9 <gpr_log_message+50>:     7c 44   jl     0x7ffff63f562f <gpr_log_message+120>
(gdb)

severity を比較しているらしき場所に辿り着きました。場所は src/core/lib/support/log.c:62 にあるので、その部分を見ます。

void gpr_log_message(const char *file, int line, gpr_log_severity severity,
                     const char *message) {
  if ((gpr_atm)severity < gpr_atm_no_barrier_load(&g_min_severity_to_print)) {
    return;
  }

  gpr_log_func_args lfargs;
  memset(&lfargs, 0, sizeof(lfargs));
  lfargs.file = file;
  lfargs.line = line;
  lfargs.severity = severity;
  lfargs.message = message;
  g_log_func(&lfargs);
}

ログ レベルは g_min_severity_to_print、ロガーは g_log_func、というグローバル変数に設定されていました。これらを外部から変更できそうな関数を探すと、同じファイル内で見つかります。ともに grpc/support/log.h で宣言されており、外部から使える API ですが、リファレンスには載っていませんでした。

void gpr_set_log_verbosity(gpr_log_severity min_severity_to_print) {
  gpr_atm_no_barrier_store(&g_min_severity_to_print,
                           (gpr_atm)min_severity_to_print);
}

void gpr_set_log_function(gpr_log_func f) {
  g_log_func = f ? f : gpr_default_log;
}

例えば gpr_set_log_verbosity(GPR_LOG_SEVERITY_ERROR) を実行すると、出力されるログはエラーログのみになります。しかし、エラー ログもコンソールに出したくない場合に gpr_set_log_verbosity(GPR_LOG_SEVERITY_ERROR + 1) のようないい加減な値を渡すのはどうも筋が悪いです。StringExchanger では、gpr_set_log_function([](gpr_log_func_args*) {}); を main 関数で実行して、空の関数をロガーとしてセットすることで全てのログを無効にしました。

おまけ: gRPC による HTTP/2 パケット

今まで HTTP/2 のパケットを一度も見たことがなく、いい機会なので gRPC の通信内容を tcpdump でキャプチャーして見てみました。

2 つのマシン上でそれぞれ StringExchanger を実行し、そのうちの一台で tcpdump を実行します。実行したコマンドは以下の通りです。

サーバーとしての待機ポートは 50000/tcp で、お互いがの相手のポートに対して gRPC メソッドを実行します。最初に適当な文字列を手で入力 ("+Hello!" など) することで、後は勝手に文字列の投げ合いが始まります。IPv6 を使っていることに特に意味はありません。もちろん IPv4 でも動きます。

tcpdump の実行 on host1:

$ sudo tcpdump -i enp3s0 -w capture-ipv6.cap tcp port 50000
tcpdump: listening on enp3s0, link-type EN10MB (Ethernet), capture size 262144 bytes

bin/t の 実行 on host1:

$ ifconfig | grep net
enp3s0    Link encap:Ethernet  HWaddr f8:ca:b8:29:b7:6d
          inet addr:10.124.252.133  Bcast:10.124.255.255  Mask:255.255.252.0
          inet6 addr: 2001:4898:200:13:9020:89b8:1a9e:b98/64 Scope:Global
          inet6 addr: fe80::ad89:69fe:5810:a38c/64 Scope:Link
          inet6 addr: 2001:4898:200:13:a8:4cd2:8418:3ffc/64 Scope:Global
          inet addr:127.0.0.1  Mask:255.0.0.0
          inet6 addr: ::1/128 Scope:Host
$ bin/t [::]:50000 [fe80::8738:bc19:6be6:f376%enp3s0]:50000
>> +Hello!
>> +Good morning!

bin/t の 実行 on host2:

$ ifconfig | grep net
eth0      Link encap:Ethernet  HWaddr 00:15:5d:fe:7a:35
          inet addr:10.124.252.98  Bcast:10.124.255.255  Mask:255.255.252.0
          inet6 addr: 2001:4898:200:13:2abc:5bb:708e:8976/64 Scope:Global
          inet6 addr: 2001:4898:200:13:cd90:6e43:b4e3:a5d3/64 Scope:Global
          inet6 addr: fe80::8738:bc19:6be6:f376/64 Scope:Link
          inet addr:127.0.0.1  Mask:255.0.0.0
          inet6 addr: ::1/128 Scope:Host
$ bin/t [::]:50000 [fe80::ad89:69fe:5810:a38c%eth0]:50000
>> +ohayou-gozaimasu
>> +sayonara

20 秒ぐらい待ってから Ctrl+D を押してプログラムを終了します。

キャプチャーしたファイルを Wireshark で開きます。

パケットは取れていますが、HTTP/2 として認識されません。パーサーを動かすには、適当なパケットを右クリックして、コンテキスト メニューの [Decode As...] をクリックし、ダイアログで HTTP2 を選びます。今回は、待機ポートである 50000/tcp のパケットを HTTP2 としてパースします。

無事、HTTP/2 として解釈されました。

HTTP/2 のスペックは RFC7540 です。

Hypertext Transfer Protocol Version 2 (HTTP/2)
http://httpwg.org/specs/rfc7540.html

少し内容を読んでみましょう。例えば、ヘッダーの内容は次のようになっています。メソッドを定義した .proto ファイルと照らし合わせると、"/<パッケージ名>.<サービス名>/<メソッド名>" のパスに HTTP/2 の POST メソッドを投げているようです。Web API っぽいですね。

Header: :scheme: http
Header: :method: POST
Header: :path: /grpc_tutorial.StringExchanger/Push
Header: :authority: [fe80::8738:bc19:6be6:f376%enp3s0]:50000
Header: te: trailers
Header: content-type: application/grpc
Header: user-agent: grpc-c++/1.4.0-dev grpc-c/4.0.0-dev (linux; chttp2; gentle)
Header: grpc-accept-encoding: identity,deflate,gzip
Header: grpc-timeout: 500m

対する応答のヘッダーは次の通り。これは正常な応答の例で、HTTP/1.x と同じステータス 200 が返っています。

Header: :status: 200
Header: content-type: application/grpc
Header: grpc-accept-encoding: identity,deflate,gzip
Header: grpc-timeout: 500m

送られているペイロードは DATA ストリームに入っています。Protocol Buffers のシリアライズの仕組みは分かりませんが、今回のような小さいデータでは、先頭に何バイトかの制御データが埋め込まれるものの、文字列自体はそのまま見えます。

おわりに

gRPC を使ったマルチスレッドの同期型クライアント/サーバー プログラムを C++ で開発する初歩の部分を紹介しました。とりあえず想定通りに動きましたが、NG なことをやっているかどうかが知識不足なので分かりません。本格的に gRPC を使い倒すには、非同期通信や CompletionQueue の仕組みなど、まだまだ覚えないといけないことがたくさんあります。

それと、今の HTTP/1.1 の理解レベル程度には HTTP/2 を覚えたい。