CubicLouve

Spring_MTの技術ブログ

GKE上で動いているRailsアプリでアクセスログとアプリケーションログをCloud Loggingでグルーピングする

medium.com

こちらに書いてある内容をRailsで実現するためにやったことを書きます。

StackdriverはOperation Suiteと名前が変わっており、それに伴ってStackdriver loggingも Cloud Logging と名前を変えています。

GKEで動かしているアプリケーションのログ

GKE上で動かしているアプリケーションであれば、標準出力、標準エラー出力にログを出力すれば、Cloud Loggingに送ることができます。

送るための設定方法は下記を参照ください。

cloud.google.com

Cloud Loggingで構造化ログにするためには、ログはJSONオブジェクトとして出力する必要があります。

また、上記の GAE のログに憧れて にあるように、ログのグルーピングの要件を満たすために、下記の対応を行います。

Railsアクセスログ

Railsアクセスログを出す場合は、Railsから出すのではなくrackから出したほうがよいです。

というわけで、アクセスログの出力に関してはrackのmiddlewareとして実装し、Railsに導入します。

rack middlewareの実装

rack middlewareの実装はこんな感じになっています。実際の実装とは少々異なりますが、雰囲気を掴んでいただければ。

gist.github.com

重要なポイント

"logging.googleapis.com/trace": env["action_dispatch.request_id"] || "",

アクセスログとアプリケーションログをグルーピングするために、同一のリクエストであることを示すリクエスト毎にユニークな識別子を使ってください。

上記の要件を満たせれば、action_dispatch.request_id を使う必然性はありません。

httpRequest: {
}

parentとなるアクセスログはHTTPのアクセスログである必要があります。

下記ドキュメントを参考に、httpRequest の内容を埋める必要があります。

cloud.google.com

 severity: 

グルーピングには severityの設定は必須ではないのですが、Cloud Loggingでfilterするときに役に立つので設定しておきましょう。

Railsからの呼び出し方

これをRailsのinitializerで呼び出すようにします。

アクセスログ標準エラー出力に出します。

# config/initializers/access_log.rb こんなファイルを用意して下記のようにする
Rails.configuration.middleware.insert_before(0, Rack::GkeJsonStructuredLogs, $stderr)

参照したライブラリ

github.com

これでRailsアクセスログをCloud Logging用にだすことができました。

Railのアプリケーションログ

RailsのアプリケーションログをCloud Loggingの形式に合わせるために専用のlog formatterを作っています。

gist.github.com

重要なポイント

params["logging.googleapis.com/trace"] = params[:request_id]

必ず アクセスログlogging.googleapis.com/trace と同じ内容をセットしてください。

呼び出し方

Loggerのformatterをセットします。

ログは標準出力に出します。

# config/environments/production.rb とかに書く
logger = ActiveSupport::Logger.new($stdout)
logger.formatter = Rrp::Logger::StackdriverFormatter.global_formatter                                                           
config.logger = ActiveSupport::TaggedLogging.new(logger)

request_idはリクエスト毎に変わるので、それもうまくセットできるようにします。

# app/controllers/application_controller.rbとかに書く
  prepend_before_action :set_params_for_logger
  # メモリーリークしそう。。。
  private def set_params_for_logger
    params_proc = proc do
      {
        request_id: request.env["action_dispatch.request_id"] || "-"
      }
    end
    Rrp::Logger::StackdriverFormatter.global_formatter.params_proc = params_proc
  end

これで準備が完了です。

結果どういう感じにでるのか?

検証環境での例は下記の感じです。

f:id:Spring_MT:20200708100408p:plain
CloudLoggin

検証環境ではdebugログも出しているためかなりログの量が出ていますが、アクセスログに紐付いてアプリケーションログもでています!

まとめ

グルーピングすることによって、まずはアクセスログに出ているユーザーIDやsevirityなどから絞り込んでさらにそこで何が起こったかをかなり追いやすくなりました。

これによって、調査タスクの効率が上がっていることは実感としてあります。

ぜひ試してみてください。