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


[昨日](https://qiita.com/notozeki/items/b974f3db166a21f18e22)に引き続き 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](https://github.com/heartcombo/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`](https://api.rubyonrails.org/classes/ActionDispatch/Request.html) オブジェクトを引数としてその `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!!:+1:

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

```
"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] [Better Rails Logs: Current User Request Context &middot; Simon Taranto](http://blog.simontaranto.com/post/2018-05-18-better-rails-logs-current-user-request-context.html/)


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