見出し画像
Photo by sho_kondo_tm

GAE/Rails で Stackdriver Logging を綺麗にするためにログの仕組みを学んだ

Yoshioka Kiyoaki

GAE は好きです。Stackdriver Logging も好きです。Rails も... (好きだといいたい...)。最近 GAE/Rails で Logging に凄く苦労し、いろいろ勉強できたので note を書きます。

結論からいうと GAE / Rails の場合は

gem 'stackdriver'
# config/environments/*.rb
Rails.application.configure do
  config.google_cloud.use_logging = true
end

これだけでかなり綺麗に Log を表示することができます。

そしてこれ以上に綺麗に出力するのはとても大変です。(リクエストログの Serverity の部分など)

ここに至るまでにものすごい苦労がありました。

1. 初期段階

まずスタートは何も設定しない状態から始まります。初期設定のログの場合はこのように表示されます。nginx のアクセスログと Rails のアプリケーションログの2つを表示しています。

nginx のアクセスのログの方はさほど気になりませんが、アプリケーションログの方は Severity、Time、Request ID などが Parse できておらず Stackdriver Logging の良さを活かせていません。

2. GAE Flexible Environment での Log の仕組み

とりあえず最初は仕組みを理解することから始まるだろうと考えます。

GAE Flexible Environment では、GoogleCloudPlatform/ruby-docker にあるDockerfile で Image が作成され、Docker Container として VM 上で立ち上がります。この VM 上では Rails App のほか、nginx や google_fluentd (log collector) などの Container も立ち上がっています。

Dockerfile で RAILS_LOG_TO_STDOUT=true になっているので通常の設定ならば STDOUT に Rails のログが吐き出されます。
STDOUT に吐き出されたログはどうなるかというと、docker container のログとして拾われ、sidecar として動いている google_fluentd によって拾われ、Parse され Stackdriver へ送信されていきます。

概ね GKE Rails の人たちも似たような構成になっているとは思います。この辺の仕組みは実際に SSH して確認することもできます。

$ gcloud beta app instances --project $PROJECT_ID ssh $INSTANCE_NAME --service $SERVICE --version $VERSION

$ sudo docker ps

$ sudo docker exec -it google-fluentd bash

fluentd によって改修されたログは、最終的に fluentd plugin である GoogleCloudOutput で処理されます。fluentd の設定を見ると少しわかるかもしれません。

ここで重要なのが Rails の標準のテキストログは単なる textPayload として処理されてしまっています。

GoogleCloudOutput では、ログがテキストであっても JSON String なら Parse し、Stackdriver Logging の Log Entry の情報として取り出されます。これは構造化ログレコード (Structured Payloads) と呼ばれています。

つまりこの時点で綺麗なログを出すための方法として、Rails のログを JSON にして Structured Payloads を追加することを考えました。これが大変さの始まりでした。

3. Log Format を JSON にして綺麗に表示させる

調べてみると似たような形で頑張っている記事を見つけました。

これらの挙動も実際に docker container 上で試すことができます。

$ sudo docker exec -it gaeapp bash
$ echo '{
    "timestamp": "2018-12-09T23:34:29.383529238Z",
    "severity": "INFO",
    "message": "Test Logging",
    "httpRequest": {
        "requestMethod": "GET",
        "requestUrl": "/foo/bar",
        "requestSize": "12",
        "status": 200,
        "responseSize": "12",
        "userAgent": "UserAgent",
        "remoteIp": "0.0.0.0",
        "referer": "",
        "latency": "0.05s",
        "cacheHit": false,
        "cacheValidatedWithOriginServer": false
    }
}' | jq -c '.' >> /var/log/app_engine/custom_logs/test.log.json

こんな感じで Rails が動いている Container 上で /var/log/app_engine/custom_logs に書き出すことで Structured Payloads が効いていることが確認できます。

これらの構造に合わせて Rails の Logger::Formatter をいろいろ頑張って Logger::Formatter::Stackdriver 的なものをつくってました。

結果がこんな感じです。

textPayload ではなく jsonPayload として認識されているおかげで、INFO / DEBUG などの severity がカラーリングされ、おまけに例えば

severity >= "ERROR" # ERROR 以上のログを表示
jsonPayload.dbLatency >= "0.1s" # db の処理にかかった時間が 0.1 秒以上のログを表示
jsonPayload.requestId = "abcde" # requestId が一致するログを表示

みたいな Stackdriver Logging の Filter が使えるようになります。User IDとか追加してても良さそうですね。最高。Big Query への Export Sink を設定していたら便利そうです。やった。嬉しい。

これでだいぶ綺麗になったと満足したいところだったんですが、アクセスログとアプリケーションログがバラバラになっていて、GAE SE で書き出しているような使いやすさがまだ足りてません。

あとから知ることができたんですが、アクセスログとアプリケーションログをまとめるための条件があるみたいです。先にこれを知りたかった感...。

というか本当は Logger Formatter を自前で用意するのが若干 (ほんの少し) 嫌で、Structured Payload を気にしないといけないし、Rails 側で用意されているログ (ActiveRecord::LogSubscriber の SQL ログなど) が相性悪い気がしていました。

それらのログは複数行で1セットになっていることも多く、空行やインデント用の空スペースなどもあり、1行単位で表示するのが難しいからです。

4. 初心に立ち返って stackdriver gem を試す

ちょっと疲れたのでこの Logger Gem の詳細は省きますが、端的にいうとこの Logger でロギングすると STDOUT / STDERR や Log File ではなく、gRPC で Stackdriver に直接 Structured Payload として送信されていきます。

...されていくはずなんですが、全然有効になっている感じがなくずっと悩んでいました。

Google Cloud Document の方では GAE Rails なら gem をいれるだけで有効化されると書いてあるものの、実は use_logging = true が必要な場合がありました。

stackdriver gem のほうにも Document があり、こちらを参照すると use_logging が production のみ true になっています。

実際にコードを読むとわかりますが、use_logging が false だと Stackdriver 用の logger が設定されません。

自分の環境だと staging を用意してたので、明示的な use_logging = true を追加する必要がありました。気づかなかった...。気づいた時の衝撃が大きかった...。切なかった...。

これにより綺麗な1つのアクセスログに紐づいて、様々なアプリケーションログをまとめて閲覧することができます。一方で nginx.request のほうの severity が設定できていないので微妙さが残りますが、自前であれこれするよりはとりあえず安心感があります。

nginx.request の方では severity が拾われないので、気になる人は Lograge などで Rails App 側でリクエストログを出力するのも良さそうです。

5. Stackdriver Debugger, Error Reporting, Trace を有効にする

Stackdriver Debugger は便利そうなので使えるなら使いたいですよね。知らない方はこちらの動画を。

Web Console 上からぽちぽちするだけで、変数の値をみたりログを追加したりすることができます。

GAE FE は deploy が超絶遅く、「デバッグログを増やして、デプロイして、確認して、またデプロイして」ってサイクルが辛いので。

これも Document には gem をいれるだけで良さそうな雰囲気が漂ってますが、production 以外では config で有効化する必要があります。

最終的にこれら Stackdriver Services を使うためにはこのような設定をいれることで利用することができます。

# config/environments/*.rb
Rails.application.configure do
  ...

  config.google_cloud.use_logging = true
  config.google_cloud.use_debugger = true
  config.google_cloud.use_error_reporting = true
  config.google_cloud.use_trace = true
end

さいごに

結構遠回りして use_logging にたどり着きました。なんで書いててくれなかったんだろう (gem の方には確かに書いているけれども)。

無事 Logging がそこそこ綺麗になりました。labels も設定できるので User IDとか追加しておくと、より扱いやすくなるかもしれないです。

途中の google-fluentd 周りは勉強だったと思って...。

この記事が気に入ったらサポートをしてみませんか？