password_digest 가 Devise inspect 를 깨는 이유

Devise 를 쓰는 Rails 앱에서 콘솔에 유저를 찍었더니 An error occurred when inspecting the object 가 나오거나, user.as_json 이 ArgumentError 로 죽는다면 이 글이다. 다 읽으면 원인 컬럼을 스니펫 한 번으로 찾고, 고치면서 API 토큰을 새로 흘리지 않게 막을 수 있다.

결론부터. 테이블에 password_digest 컬럼이 있으면 Devise 가 가진 같은 이름의 메서드 password_digest(password) 가 컬럼 리더를 가린다. Devise 의 inspect 는 속성을 하나씩 send 로 읽는데, 그걸 인자 없이 부르니 죽는다.

본번 콘솔에서만 터졌다

회사 프로젝트(Rails 7.1 · Devise 4.9)에서 본번 콘솔로 유저 하나를 찾았을 뿐인데 이렇게 나왔다.

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 로 한다. 비밀번호 해시 컬럼이 두 개였던 셈이다.

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 한 줄이면 500 이다.

고치기 — ignored_columns 만으로는 두 군데가 샌다

첫 수는 self.ignored_columns += %w[password_digest] 였다. 속성 목록에서 빠지니 send 도 안 부른다. 그런데 셀프 리뷰에서 구멍이 두 개 나왔다.

하나. ignored_columns 는 스키마로 속성을 만들 때만 듣는다. select('users.*') 처럼 SELECT 결과에 컬럼이 실려 오면 속성이 되살아나 다시 터진다. 그런 쿼리가 실제로 서비스 코드에 있었다.

둘. 고친 순간 안 보이던 게 보이기 시작한다. 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개)에서는 딱 한 줄, User#password_digest -> Devise::Models::DatabaseAuthenticatable (arity 1) 이 나왔다. 이 블로그 저장소에 돌리면 0줄이다. id 는 거의 모든 모델에서 AR 의 PrimaryKey 모듈이 가리지만 arity 0 이라 무해해서 걸렀다.

has_secure_password 와 Devise 를 재다가 남은 컬럼처럼, 쓰다 만 마이그레이션은 생각보다 흔하다. 안 쓸 마이그레이션은 되돌려 두자. 컬럼은 남고 의도는 안 남는다. 이번에 2년 뒤 원인을 알려 준 것도 #has_secure_password 주석 한 줄뿐이었다.

오래된 Rails 앱에 이런 「아무도 모르는 컬럼」 이 쌓여 있거나, 인증 쪽을 정리하면서 토큰이 어디로 새는지 같이 봐 줄 사람이 필요하면 negabaro 에 물어봐도 된다.