LoginSignup
4
4

More than 3 years have passed since last update.

@notozeki(notozeki)inフィフス・フロア株式会社

【Rails】ログにDeviseのユーザーIDを出力する

Posted at

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

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

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

  • 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 に↓のように書くと1、

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!!:thumbsup:

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

"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]のように配列になっているのか気になったが、今回はそこまで深入りしない（ご存知の方がいれば教えてください:pray:）。

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

ユーザー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 がラクで良い:relaxed:

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

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

LGTM:ok_woman:

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

おまけ

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

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

参考文献

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

4
4
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
4
4