問題：Herokuで運用中のRailsアプリが500エラー
これまで特に問題のなかったRailsアプリがいきなり500エラーを出したり出さなかったりするようになりました。heroku logs --app app-name -tで観察していたら、prepared statementの重複が発生しているというログが出ていました。
原因：rack-timeoutが発動するとこうなる？
古い情報ですが、rack-timeoutが発動すると、こうなる場合があるらしいです。
prepared statementの名前はインクリメントされながら登録されていくのですが、新しいprepared statementが登録された後、使われる前にrack-timeoutによって殺された場合にインクリメント済みであることが周知されず、同じ数値でまた登録しようとしてしまい、エラーになるようです。
Rails本体のPRを見る
この件については、複数のPRで結構話し合われているようです。
ただ、結論としては「Rack::Timeoutによる不具合なのだからRails側で対応するつもりはない」という感じでした。Rack::Timeoutのコールバックなどを使って綺麗にすればいいという話のようです。
また、「prepared statementsを使わない設定にすればいいじゃない？大したオーバーヘッドでもないんだし」という意見もPRの議論の中にありました。デフォルトで使う設定だったのでその発想はなかった！
解決策(その1)prepared statementsを使わない設定にする
今回は、prepared statementsを使わない設定に変えてみました。
ローカル環境編
database.ymlを編集し、prepared_statements: falseを追加します。
default: &default
adapter: postgresql
encoding: unicode
pool: 5
prepared_statements: false
development:
<<: *default
database: hoge_development
host: localhost
test:
<<: *default
database: hoge_test
Heroku環境編
Herokuではアプリケーションサーバにunicornを使っているので、その設定を追加します。config['prepared_statements'] = falseです。
after_fork do |server, worker|
if defined?(ActiveRecord::Base)
config = ActiveRecord::Base.configurations[Rails.env] ||
Rails.application.config.database_configuration[Rails.env]
config['prepared_statements'] = false
ActiveRecord::Base.establish_connection(config)
end
end
注意！必ずテストすること！
これですが、設定をすれば何の問題もなくOK!というものではなく、Arelを使っているgemなどがある場合、エラーがガンガン起きたりしたので、必ず動作検証しましょう！
解決策(その2)※未検証 rack-timeout側で解決する
rack-timeout側で掃除する方法も考えついたので一応書いたのですが、動作検証する方法がわからなかったので、実は適用していません。2017-02-20追記 コメントで、いい方法を伺ったので、それを適用してみました。
rack-timeoutのバージョンは0.4.2です。
if defined?(Rack::Timeout)
Rack::Timeout.service_timeout = 20
Rack::Timeout.unregister_state_change_observer(:logger)
Rack::Timeout.register_state_change_observer(:prepared_statements_clean) do |env|
case env[Rack::Timeout::ENV_INFO_KEY].state
when :ready
env['rack-timeout-prepared-statements-clean'] = false
when :timed_out
env['rack-timeout-prepared-statements-clean'] = true
when :completed
if env['rack-timeout-prepared-statements-clean']
# 再接続することで以前のprepared statementsのキャッシュを一掃する
ActiveRecord::Base.connection.reconnect!
# 以下の方法だと、重複しているprepared statementsだけが残ってしまうので意味がなかった…
# ActiveRecord::Base.connection.instance_variable_get(:@statements).clear
end
end
end
end
prepared statementsの情報は、それぞれのコネクションの@statementsに蓄積されていくので、Rack::Timeoutの処理が完了したタイミングでclearするようにしてみています。
これでいいのか、アドバイスが聞きたいので、もしおわかりになる方がおられましたら、コメントお願いします！
まとめ
そもそもrack-timeoutが発動するような時間のかかる処理を減らしていくべきである、というのが正解だとは思います…。