[Ruby on Rails Tutorial]Herokuにデプロイ後Application error[H10 (App crashed)]が発生した時の対処法

7297 ワード
Heroku Rails RailsTutorial Ruby cloud9 Ruby テキストリンク

環境

Cloud9(テンプレートはRails Tutorialを選択)
Ruby 2.3
Rails 5.0.0.1

現象

Ruby on Rails チュートリアルにそって学習を進めている途中、
第5章を終えたあたりから、Herokuへのデプロイ後にサイトを開こうとすると下記エラー画面が出るようになった。
(開発環境では問題なく動いている状態。)

その際の対処法メモ。

エラーメッセージ

Application error
An error occurred in the application and your page could not be served. If you are the application owner, check your logs for details.

※直接的な原因は様々あると思うので唯一の方法ではありませんが、調査の過程については参考になる部分があるかもしれません。

まずはログを見る

ログを見てみろというので、$ heroku logs | grep errorしてみる。

出力結果

2017-01-12T00:27:38.982656+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=GET path="/" host=rails-sample.herokuapp.com request_id=0f78723d-3f66-4981-a0ee-37cdfaf15ae7 fwd="219.101.173.94" dyno= connect= service= status=503 bytes=
2017-01-12T00:27:39.654230+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=GET path="/favicon.ico" host=rails-sample.herokuapp.com request_id=8691ff81-a219-4ad1-bbff-fe6558d49a7c fwd="219.101.173.94" dyno= connect= service= status=503 bytes=
・・・
2017-01-12T04:38:24.738755+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=GET path="/favicon.ico" host=rails-sample.herokuapp.com request_id=b3d112b2-0f22-45ef-a396-165e5857acb2 fwd="219.101.173.94" dyno= connect= service= status=503 bytes=

desc="App crashed"と出ている。
アプリ自体が壊れてしまった？

もうちょっと詳しく見てみる

これだけではよくわからないので、今度は$ grep errorしないで細かく追ってみることにした。

heroku logs 詳細

2017-01-26T06:53:49.671886+00:00 heroku[web.1]: Process exited with status 1
2017-01-26T06:53:49.689491+00:00 heroku[web.1]: State changed from starting to crashed
2017-01-26T06:53:49.690754+00:00 heroku[web.1]: State changed from crashed to starting
2017-01-26T06:53:52.311557+00:00 heroku[web.1]: Starting process with command `bundle exec puma -C config/puma.rb`
2017-01-26T06:53:54.862499+00:00 app[web.1]: Puma starting in single mode...
2017-01-26T06:53:54.862561+00:00 app[web.1]: * Version 3.4.0 (ruby 2.2.6-p396), codename: Owl Bowl Brawl
2017-01-26T06:53:54.862565+00:00 app[web.1]: * Min threads: 5, max threads: 5
2017-01-26T06:53:54.862586+00:00 app[web.1]: * Environment: production
2017-01-26T06:53:56.445348+00:00 app[web.1]: ! Unable to load application: LoadError: No such file to load -- test_helper
・・・
2017-01-26T06:54:55.533586+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=GET path="/" host=calm-garden-72176.herokuapp.com request_id=9c05bdaa-3019-4ad9-9afd-41d490c4e340 fwd="219.101.173.94" dyno= connect= service= status=503 bytes=
2017-01-26T06:54:56.293246+00:00 heroku[router]: at=error code=H10 desc="App crashed" method=GET path="/favicon.ico" host=calm-garden-72176.herokuapp.com request_id=cb47c74e-37b0-4936-9070-0c8d29c8d715 fwd="219.101.173.94" dyno= connect= service= status=503 bytes=

以下の記述に着目。
test_helperが見つからない？

! Unable to load application: LoadError: No such file to load --
test_helper

ちなみに、test_helper.rb自体には特に問題は見当たらない。
ちょっとまだよくわからない。

ENV['RAILS_ENV'] ||= 'test'
require File.expand_path('../../config/environment', __FILE__)
require 'rails/test_help'
require "minitest/reporters"
Minitest::Reporters.use!

class ActiveSupport::TestCase
  fixtures :all
  include ApplicationHelper
end

rails consoleしてみる

どこかの記事で、こんな時にはコンソール開いてみるといいよ、とあった。
ということで$ heroku run rails consoleして、エラーメッセージをみる。

結果

/app/vendor/bundle/ruby/2.2.0/gems/activesupport-5.0.0.1/lib/active_support/dependencies.rb:293:in `require': No such file to load -- test_helper (LoadError)
from /app/vendor/bundle/ruby/2.2.0/gems/activesupport-5.0.0.1/lib/active_support/dependencies.rb:293:in `block in require'
from /app/vendor/bundle/ruby/2.2.0/gems/activesupport-5.0.0.1/lib/active_support/dependencies.rb:259:in `load_dependency'
from /app/vendor/bundle/ruby/2.2.0/gems/activesupport-5.0.0.1/lib/active_support/dependencies.rb:293:in `require'
from /app/app/helpers/application_helper_test.rb:1:in `<top (required)>'

from /app/app/helpers/application_helper_test.rb:1:in `'

application_helper_test.rbの1行目にrequire 'test_helper'している部分がある。
ここら辺が怪しいかな？

原因と解決方法

Stackoverflowのこちらの記事を参考に、ようやく解決にたどり着きました。

You have a test, quarterly_export_statement_test.rb, in your app/controllers directory.

In production, Rails loads all classes eagerly, so it attempts to load your test. Your test does require 'test_helper'. The test directory, which contains test_helper, isn't in the load path in the production environment (good!), so that require fails.

To fix the problem, move the test to the test directory where it belongs, which appears to be /home/nyros/Documents/Projects/DFL/Working/DFL/test.

本番環境では、Railsはすべてのクラスを熱心に読み込むため、テストをロードしようとするとのこと。

原因
application_helper_test.rbが何かのはずみでapp/helpers配下に移動していたため、1行目のrequire 'test_helper'でtest_helperがうまく呼び出せず、LoadErrorとなっていた。

解決方法
application_helper_test.rbを正しい位置test/helpers配下に移動させてやることで本番環境で動作することが確認できた。

原因が判ってみるとなんてことないが、どハマりしてしまい解決まで数週間を要してしまいました。。