password_digestカラムでDeviseのinspectが落ちる理由

Deviseを使っているRailsアプリで、コンソールにユーザーを出したら An error occurred when inspecting the object が出た、あるいは user.as_json が ArgumentError で落ちる。そんなときに読む記事だ。読み終われば原因のカラムをスニペット1回で見つけられて、直すついでにAPIトークンを漏らし始めることも防げる。

先に結論。テーブルに password_digest カラムがあると、Deviseが持っている同じ名前のメソッド password_digest(password) がカラムのリーダーを隠す。Deviseの inspect は属性を1つずつ send で読むので、それを引数なしで呼んで落ちる。

本番のコンソールでだけ落ちた

仕事の案件（Rails 7.1・Devise 4.9）で、本番コンソールからユーザーを1人探しただけでこうなった。

irb(main):001> user = User.find_by(email: 'someone@example.com')
An error occurred when inspecting the object: #<ArgumentError: wrong number of arguments (given 0, expected 1)>
Result of Kernel#inspect: #<User:0x00007f528b334d40 @new_record=false, @attributes=...
irb(main):002> user.email
=> "someone@example.com"

値はちゃんとある。表示だけが死んでいる。ところがステージングで同じことをしてもエラーが出ない。

[1] pry(main)> user = User.find_by(email: 'admin@example.com')
=> #<User:0x6978>

なので最初は「本番のデータに何か変なものがあるのか」から掘り始めた。出発点が間違っていた。環境の違いではなく、REPLの違いだった。

ステージングが平気に見えたのは、pryが飲み込んでいたから

ヒントは #<User:0x6978> そのものにあった。ActiveRecordの inspect がちゃんと動けば #<User id: 17, email: ...> のように属性が出る。Rubyのデフォルトの inspect ならアドレスは16桁だ。4桁はどちらでもない。

pryの ColorPrinter#pp は inspect で出た例外を rescue し、クラス名と object.__id__.to_s(16) で作った文字列を代わりに出す。object_idは小さい連番なので短い。irbにはそういう rescue がないので「An error occurred when inspecting the object」をそのまま出す。このブログのリポジトリ（pry 0.15.2）で同じようなモデルを Pry::ColorPrinter.pp に渡してみたら、#<ReproUser:0x7544> が出るだけで例外は外に出てこなかった。

ステージングだけpryだった理由は RAILS_ENV だった。pry-rails はGemfileの group :development, :test にあり、Railsは Bundler.require(*Rails.groups) で今の環境のグループだけをrequireする。ステージングのコンテナが RAILS_ENV=development で動いていたのでpryがコンソールを乗っ取り、本番は production なのでirbだった。gemは両方のイメージに入っていた。インストールではなくrequireの違いだ。

だから「ステージングでは動くんですけど」と聞いたら、まずREPLをそろえる。再現はコンソールではなく bin/rails runner でやる。REPLが挟まらないので、ステージングでも本番とまったく同じように落ちた。

原因 — Deviseがその名前をもう使っている

runnerで取ったバックトレースのいちばん下はDeviseの inspect だった。Deviseはパスワードが例外メッセージに漏れないよう、inspect を serializable_hash ベースで定義し直している。そしてActiveModelの serializable_hash は属性名ごとに send を呼ぶ（alias :read_attribute_for_serialization :send）。

ところがDeviseの DatabaseAuthenticatable には、パスワードをハッシュするメソッドがすでにある。

# devise-4.9.4/lib/devise/models/database_authenticatable.rb:197
def password_digest(password)
  Devise::Encryptor.digest(self.class, password)
end

引数1つだ。send(:password_digest) は引数0個。だから wrong number of arguments (given 0, expected 1) になる。

カラムのリーダーがないわけではない。ARは User::GeneratedAttributeMethods に password_digest のリーダーを作っている。ただこのモジュールはクラスが作られた瞬間（inherited フック）にincludeされ、クラス本体の devise ... はその後にincludeされる。後からincludeしたモジュールが祖先チェーンの上に乗るので、名前がかぶるとカラムが負ける。User.instance_method(:password_digest).owner を出すと Devise::Models::DatabaseAuthenticatable が返ってくる。

ARが一言も警告しなかった理由も見た。カラム名が危ないかを判定する dangerous_attribute_method? は、ActiveRecord::Base 自身が定義したメソッドしか見ない。save というカラムなら即 DangerousAttributeError だが、password_digest は false だ。gemやconcernとのかぶりは黙って隠される。

そもそもなぜそのカラムがあったのか

password_digest はRails標準の has_secure_password が使う、名前の決まったカラムだ。Deviseは同じ仕事を encrypted_password でやる。パスワードハッシュのカラムが2つあったことになる。

gitを掘ると、add_column :users, :password_digest と #has_secure_password のコメントが同じ日に入っていた。最初からコメントアウトで、一度も有効にしていない。どちらを使うか迷ってDeviseに決めたが、マイグレーションはもう流れたあとで、カラムだけが残ったわけだ。本番のusers 42,212行のうち、値が入っている行は0。2年以上、空のカラムが inspect を殺していた。

落ちるのは inspect だけではない。as_json・to_json・serializable_hash も一緒に落ちる。user.email のような個別の属性やクエリは平気だ。画面でUserをJSONにする場所がなかったから持ちこたえただけで、render json: user を1行書けば500になる。

直す — ignored_columnsだけだと2か所から漏れる

最初の一手は self.ignored_columns += %w[password_digest] だった。属性一覧から消えるので send も呼ばれない。ところがセルフレビューで穴が2つ見つかった。

1つ目。 ignored_columns が効くのは、スキーマから属性を組み立てるときだけだ。select('users.*') のようにSELECTの結果にカラムが載ってくると属性が復活して、また落ちる。そういうクエリが実際にサービスのコードにあった。

2つ目。 直した瞬間、それまで見えなかったものが見え始める。Deviseがシリアライズから外してくれるのは UNSAFE_ATTRIBUTES_FOR_SERIALIZATION の一覧（encrypted_password・reset_password_token など）だけで、その案件がAPI認証に使っていた authentication_token は入っていない。このブログのリポジトリで回し直すと、inspect は filter_parameters の :token のおかげで [FILTERED] になったが、as_json・to_json は平文のトークンをそのまま返した。ActiveRecordがinitializerより先に読み込まれるアプリだと filter_attributes が空配列のままで、inspect まで平文になる。このブログのリポジトリがそうだった。

なので最終形は serializable_hash で両方外すことだ。

class User < ApplicationRecord
  self.ignored_columns += %w[password_digest]

  EXCLUDED_FROM_SERIALIZATION = %i[password_digest authentication_token].freeze

  def serializable_hash(options = nil)
    options = options.try(:dup) || {}
    options[:except] = Array(options[:except]).dup
    options[:except].concat(EXCLUDED_FROM_SERIALIZATION)
    super(options)
  end
end

except は send を呼ぶ前に名前の一覧から外す。だから select('users.*') で復活しても安全だ。Deviseの serializable_hash も super でつながるので、Devise側の隠しもそのまま生きる。Rails 8.0.4・Devise 4.9.4で再現した結果がこれだ。

直す前                  inspect・as_json・to_json  ArgumentError
ignored_columnsだけ     inspect OK、as_jsonにauthentication_tokenが平文
  + select('users.*')   inspect ArgumentError（また）
exceptまで              inspect OK、as_json keys = [id, email]

ただし only と except は elsif なので、as_json(only: [:password_digest]) のようにピンポイントで呼ぶとやはり落ちる。そんな呼び方をすることはまずないけれど。

カラムの削除は次のリリースで

同じPRに remove_column まで入れたくなるが、ローリングデプロイではそれが障害になる。旧コードがINSERTに消したカラムを入れるからだ。ignored_columns をデプロイ → 旧コンテナが全部入れ替わったのを確認 → remove_column → ignored_columns の行を削除、の順に分ける。理由は ローリングデプロイ中のremove_columnでINSERTだけ落ちる理由 に別で書いた。

自分のアプリにもあるか — まとめて洗う

カラムのリーダーが別のモジュールに隠されていて、しかもそのメソッドが引数を必ず取るカラムだけを出す。bin/rails runner で回す。

Rails.application.eager_load!

ActiveRecord::Base.descendants
  .reject { |m| m.abstract_class? || m.name.nil? || !m.table_exists? }
  .each do |klass|
    klass.define_attribute_methods rescue next
    klass.column_names.each do |c|
      m = (klass.instance_method(c) rescue next)
      next if m.owner.to_s.include?('GeneratedAttributeMethods')
      next if m.arity == 0 || m.arity == -1   # 引数なしで呼べるなら無害
      puts "#{klass.name}##{c} -> #{m.owner} (arity #{m.arity})"
    end
  end

仕事の案件（モデル80個）ではちょうど1行、User#password_digest -> Devise::Models::DatabaseAuthenticatable (arity 1) が出た。このブログのリポジトリで回すと0行だ。id はほぼすべてのモデルでARのPrimaryKeyモジュールが隠しているが、arity 0で無害なので外してある。

has_secure_passwordとDeviseで迷った跡のカラムのように、使いかけのマイグレーションは思ったより多い。使わないマイグレーションは戻しておこう。カラムは残るが、意図は残らない。今回も2年後に原因を教えてくれたのは #has_secure_password のコメント1行だけだった。

古いRailsアプリに「誰も説明できないカラム」がたまっている、あるいは認証まわりを整理しながらトークンがどこに漏れるか一緒に見てほしいなら、negabaro に気軽に聞いてほしい。