謎のPG::UndefinedTableエラー
とあるプロジェクトでbundle exec rake testを実行したところ「ActiveRecord::StatementInvalid: PG::UndefinedTable: ERROR: relation "..." does not exist」というエラーが発生した。ところが、同じ環境でbin/rake testならばエラーにならない。さらに言えば同じくbundle execであってもbundle exec rails sならばやはり問題なく動いてしまう。
$ bundle exec rake test
Started
E
================================================================================================================================================================
/Users/akira/.../test/models/user_test.rb:8:in `block in <class:UserTest>'
/Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/querying.rb:13:in `count'
/Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/relation/calculations.rb:48:in `count'
/Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/relation/calculations.rb:133:in `calculate'
/Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/relation/calculations.rb:227:in `perform_calculation'
/Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/relation/calculations.rb:258:in `execute_simple_calculation'
/Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/relation/calculations.rb:232:in `aggregate_column'
/Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/model_schema.rb:260:in `column_names'
/Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/attributes.rb:93:in `columns'
/Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/schema_cache.rb:43:in `columns'
/Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/postgresql/schema_statements.rb:197:in `columns'
/Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/postgresql_adapter.rb:733:in `column_definitions'
/Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/postgresql/database_statements.rb:160:in `exec_query'
/Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/postgresql_adapter.rb:584:in `execute_and_clear'
/Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/postgresql_adapter.rb:592:in `exec_no_cache'
/Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/abstract_adapter.rb:478:in `log'
/Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activesupport-4.2.10/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
/Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/abstract_adapter.rb:484:in `block in log'
/Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/postgresql_adapter.rb:592:in `block in exec_no_cache'
/Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/postgresql_adapter.rb:592:in `async_exec'
Error: test: ok(UserTest):
ActiveRecord::StatementInvalid: PG::UndefinedTable: ERROR: relation "bars" does not exist
LINE 5: WHERE a.attrelid = '"bars...
^
: SELECT a.attname, format_type(a.atttypid, a.atttypmod),
pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod
FROM pg_attribute a LEFT JOIN pg_attrdef d
ON a.attrelid = d.adrelid AND a.attnum = d.adnum
WHERE a.attrelid = '"bars"'::regclass
AND a.attnum > 0 AND NOT a.attisdropped
ORDER BY a.attnum
まずは検索してみたのだが、これだというものはひっかからなかった。ちょっと検索語に困る場面でもある。bundle exec rakeで検索してもね。
ただ、実のところ、エラーメッセージ中のSQL文の内容について、最初からひっかかっていた点があった。それはrelationの名前について。上では"bars"となっている部分。
アプリケーションのコードの上では、これにあたりそうのはFoo::Barというモデルくらいしか見当たらない。だから、これがテーブル名なりなんなりを指しているのだとするとbarsでなはなくfoo_barsとなるべきなのではないか、という予想を立てることができそうだ。(ここでは名前を置き換えているが、実際にはもう少し特徴的なモデル名である。)
この予想をもとにできるだけ小さい再現コードを作ることを試みた。といってもごくシンプルにFoo::Bar.countと書いてみたところで現象を起こすことができた。
次に何が起きているのか軽く追いかけてみた。これもシンプルにbyebugといれてコードを実行し、いかにもそれっぽいところにブレークポイントを置いて実行してみればよい。この場合、バックトレースのならびからするとactive_record/connection_adapters/postgresql/schema_statements.rb:197あたりがとっかかりになりそうだ。
$ bundle exec rake test test/models/user_test.rb
Loaded suite /Users/akira/.rbenv/versions/2.4.4/bin/rake
Started
[2, 11] in /Users/akira/.../test/models/user_test.rb
2:
3: class UserTest < ActiveSupport::TestCase
4: # test "the truth" do
5: # assert true
6: # end
7: test 'ok?' do
8: byebug
=> 9: Foo::Bar.count
10: end
11: end
(byebug) b /Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/postgresql/schema_statements.rb:197
Created breakpoint 1 at /Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/postgresql/schema_statements.rb:197
(byebug) c
Stopped by breakpoint 1 at /Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/postgresql/schema_statements.rb:197
[192, 201] in /Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/postgresql/schema_statements.rb
192: end
193:
194: # Returns the list of all column definitions for a table.
195: def columns(table_name)
196: # Limit, precision, and scale are all handled by the superclass.
=> 197: column_definitions(table_name).map do |column_name, type, default, notnull, oid, fmod|
198: oid = get_oid_type(oid.to_i, fmod.to_i, column_name, type)
199: default_value = extract_value_from_default(oid, default)
200: default_function = extract_default_function(default_value, default)
201: new_column(column_name, default_value, oid, type, notnull == 'f', default_function)
(byebug) table_name
"bars"
ではbin/rake testならどうなるかを確認してみると、予想通りの結果となった。
Stopped by breakpoint 1 at /Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/postgresql/schema_statements.rb:197
[192, 201] in /Users/akira/.rbenv/versions/2.4.4/lib/ruby/gems/2.4.0/gems/activerecord-4.2.10/lib/active_record/connection_adapters/postgresql/schema_statements.rb
192: end
193:
194: # Returns the list of all column definitions for a table.
195: def columns(table_name)
196: # Limit, precision, and scale are all handled by the superclass.
=> 197: column_definitions(table_name).map do |column_name, type, default, notnull, oid, fmod|
198: oid = get_oid_type(oid.to_i, fmod.to_i, column_name, type)
199: default_value = extract_value_from_default(oid, default)
200: default_function = extract_default_function(default_value, default)
201: new_column(column_name, default_value, oid, type, notnull == 'f', default_function)
(byebug) table_name
"foo_bars"
さて、この辺であやしくなってくるのはファイルのロード順だろう。あたまにfoo_がくっつかないところを見ると、app/models/foo.rbがロードされる前に、別の何かがロードされたのではないかという予想ができる。
その確認にはconfig/initializersあたりでrequire 'foo'とでもしてみればよさそう……してみた結果、当たっていた。ではどこで何を読み込んでいるのだろう?
実はこのプロジェクト、いくつか事情があって、全体的にプレフィックスを置くようにしている。モデルやコントローラなど、ことごとくFoo::を付けてまわっているのだが、そうなってくるとapp/models/foo.rbではない何かが先にロードされていると見てよさそう。そう考えて、デバッグプリントを入れて動きを追ってみたところ、なんと、test_helper.rbの中でrequire 'foo/baz'しているのが原因であった。より正確にはlib/foo/baz.rbの存在が原因だということが分かった。こんなのあったの忘れてたよ。
つまり、本来であればFoo::Barという参照により、規約的におそらく唯一になるはずのapp/models/fooが最初にロードされる。このファイルの中身はおなじみのこういうものである。
module Foo
def self.table_name_prefix
'foo_'
end
end
ところがtest_helper.rbでrequire 'foo/baz'しており、それによりロードされるlib/foo/baz.rbの中ではモジュールFooが定義されている。当然ながらそこにはtable_name_prefixの定義はないのだが、このロードによりFoo::Barの参照でFooが未定義になることはなく、その結果としてapp/models/foo.rbがロードされず、素知らぬふりをして動き続きけた挙げ句に「relation "bars" does not exist」をくらったわけである。
そういうわけで、今回の場合はシンプルにlib/fooという置き方を変更することにする。
根本的には、自動ロードするものと、明示的にロードするものとでプレフィックスを重ねないようにしたほうがよいということになるだろうか。