昨日に引き続き Devise ネタ。Rails で、ログに Devise のユーザーIDを出力する方法をまとめる。

なるべくシンプルに、素の Rails の機能だけを使って実現する。追加ライブラリ、カスタム logger や Rack ミドルウェアは不要

以下のバージョンで動作を確認している。

Rails 6.0.2.1
Devise 4.7.1

TL;DR

以下のようなコードで、

config/environments/development.rb

  config.log_tags = [
    ->(req) {
      session_key = (Rails.application.config.session_options || {})[:key]
      session_data = req.cookie_jar.encrypted[session_key] || {}

      users = []
      %w(user admin).each do |scope| # user, admin はスコープの一例
        user_id = session_data.dig("warden.user.#{scope}.key", 0, 0)
        users << "#{scope}:#{user_id}" if user_id
      end

      users.join(',')
    }
  ]

以下のように、ログに Devise のログインユーザーのIDを記録できるようになる（先頭の [] の中）。

[user:1,admin:2] Completed 200 OK in 147ms (Views: 99.7ms | ActiveRecord: 8.3ms | Allocations: 15413)

背景

素の Rails には、ユーザー認証の仕組みは入っていないので、Devise などのライブラリを使って対応することが多い。

今回も、Devise を用いてユーザー認証を実装する機会があった。加えて、ログに「誰が操作したのか（ユーザーID）」を記録したいという要件があった。よくありそうなユースケースのわりに、あまり参考になる情報がなかったので、まとめておくことにした。

ログに`log_tags`で「タグ」をつける

Rails のログ設定の一つに log_tags というものがある。

config.log_tags: 次のリストを引数に取ります（requestオブジェクトが応答するメソッド、requestオブジェクトを受け取るProc、またはto_sに応答できるオブジェクト）。これは、ログの行にデバッグ情報をタグ付けする場合に便利です。たとえばサブドメインやリクエストidを指定することができ、これらはマルチユーザーのproductionアプリケーションをデバッグするのに便利です。
-- https://railsguides.jp/configuring.html#rails全般の設定

つまり、これを設定すると、ログの各行の頭に何かしらの出力（タグ）を追加できる。

よくあるのは、同一リクエストに対するログであることを識別するための「リクエストID」を出力する例である。たとえば、development.rb に↓のように書くと¹、

config/environments/development.rb

  config.log_tags = [ :request_id ]

↓のようなログ出力になる。

[424aabe4-63c2-4732-b566-fe04b97191ec] Started GET "/" for ::1 at 2020-01-31 11:35:26 +0900
[424aabe4-63c2-4732-b566-fe04b97191ec] Processing by StaticPagesController#index as HTML
[424aabe4-63c2-4732-b566-fe04b97191ec]   Rendering static_pages/index.html.erb within layouts/application
[424aabe4-63c2-4732-b566-fe04b97191ec]   Rendered static_pages/index.html.erb within layouts/application (Duration: 1.2ms | Allocations: 201)
[424aabe4-63c2-4732-b566-fe04b97191ec] [Webpacker] Everything's up-to-date. Nothing to do
[424aabe4-63c2-4732-b566-fe04b97191ec] Completed 200 OK in 76ms (Views: 67.3ms | ActiveRecord: 0.0ms | Allocations: 7674)

各行の先頭に付いている [424aabe4-63c2-4732-b566-fe04b97191ec] が、このリクエストのリクエストIDである。このように、ログの頭に [] で囲まれてタグが出るようになるのが log_tags の設定である。

`Request`オブジェクトからセッション情報を取り出す

log_tags に Proc オブジェクトを入れると、ActionDispatch::Request オブジェクトを引数としてその Proc を呼び出した結果が、タグとしてログに挿入される。

たとえば、以下のようにすると、

config/environments/development.rb

  config.log_tags = [ ->(req) { req.env['HTTP_USER_AGENT'] } ]

以下のようなログが出てくる。

[Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/79.0.3945.130 Safari/537.36] Completed 200 OK in 57ms (Views: 49.8ms | ActiveRecord: 0.0ms | Allocations: 7428)

さて、この Request オブジェクトから Devise の認証情報が取れれば、それをタグに使うことができる。参考文献[1]によると、以下の方法でセッションデータが取れるらしい。

config/environments/development.rb

  config.log_tags = [
    ->(req) {
      session_key = (Rails.application.config.session_options || {})[:key]
      session_data = req.cookie_jar.encrypted[session_key] || {}
      session_data
    }
  ]

見てみる（一部省略）。

[{"session_id"=>"e4...", "warden.user.user.key"=>[[1], "$2a$11$fBAgejWzT9na6eZoIlYuP."], "warden.user.admin.key"=>[[2], "$2a$11$AXPU8A9xEASFrtZuFkwuVu"], "_csrf_token"=>"gc..."}] Completed 200 OK in 242ms (Views: 73.4ms | ActiveRecord: 77.8ms | Allocations: 11038)

works fine!!

セッションの中身がすべて出力されているので少し長いが、以下のあたりにユーザー情報がありそうだ。

"warden.user.user.key"=>[[1], "$2a$11$fBAgejWzT9na6eZoIlYuP."], "warden.user.admin.key"=>[[2], "$2a$11$AXPU8A9xEASFrtZuFkwuVu"]

セッション情報からユーザーIDを特定

キーの"warden.user.xxxx.key"のxxxxにあたるところが、Devise のスコープを表しているようだった。

値の方はなにやら不思議な形をしている。

[[1], "$2a$11$fBAgejWzT9na6eZoIlYuP."]

多分 1 がユーザーIDに対応するのかなと思ったが、やはりそのようだった。

参考: https://stackoverflow.com/questions/23597718/what-is-the-warden-data-in-a-rails-devise-session-composed-of

ただ、公式の情報はパッと調べた中では見つからなかった。なぜ[1]のように配列になっているのか気になったが、今回はそこまで深入りしない（ご存知の方がいれば教えてください）。

ともあれ、これで必要な情報は揃った。

ユーザーIDをログに出力する

フォーマットの検討

一般に Devise では複数の「スコープ」が扱える。たとえば User と Admin を別々にログインできるようにする、というときにスコープを分けて対応する。

そのため、ログに記録すべきユーザーIDも User のものと Admin のものの2つ、というふうに複数になりえる。その前提で、ログのフォーマットを決める。

複数のユーザーIDを出力したときに、どのスコープのユーザーIDであるかを区別できるように、以下のようにスコープとIDを:で繋ぐことにして、

user:1

さらに、複数のスコープでログインしているときは、それらを,で繋ぐことにした。

user:1,admin:3

コード例

上記のフォーマットに従ってタグを整形するコードは以下のようになった。%w(user admin) のようなところは、そのプロジェクトで使っている Devise のスコープ名（単数形）に変える。

config/environments/development.rb

  config.log_tags = [
    ->(req) {
      session_key = (Rails.application.config.session_options || {})[:key]
      session_data = req.cookie_jar.encrypted[session_key] || {}

      users = []
      %w(user admin).each do |scope|
        user_id = session_data.dig("warden.user.#{scope}.key", 0, 0)
        users << "#{scope}:#{user_id}" if user_id
      end

      users.join(',')
    }
  ]

Hash#dig がラクで良い

この設定でログを出力すると、以下のようになった。

[user:1,admin:2] Completed 200 OK in 147ms (Views: 99.7ms | ActiveRecord: 8.3ms | Allocations: 15413)

LGTM

本番環境でも使いたいときは config/environments/production.rb にも転記するのを忘れずに。

おまけ

ちなみに、Proc の戻り値が空文字列、つまりどのスコープでもログインしていないときは、タグ自体が出力されないようだった。空の [] が出力されるかと思ったが、ちゃんと空かどうか見ているようだ。

Completed 200 OK in 74ms (Views: 71.9ms | ActiveRecord: 0.0ms | Allocations: 4425)

参考文献

[1] Better Rails Logs: Current User Request Context · Simon Taranto

ちなみに、production.rb ではデフォルトでこの設定になっている。 ↩