Herokuにデプロイ後、本番環境でのみログインができない。

前提・実現したいこと

RailsアプリをHerokuにデプロイし、heroku run rails db:migrate も済ませました。
その後ステージング環境で動作確認をする為、ユーザー新規登録とログインを試みました。しかし同じログイン画面にリダイレクトされるだけで、トップページへ遷移してくれません。
パスワード等の入力する情報は間違っていない為、エラーメッセージも表示されず単純にリダイレクトされると言った状況です。

この問題に関して調べた所、過去の質問やQiita記事などに行きつきました。しかし「初期データが作成されていなかった為 seed.rb を使ってデータを作成してからログインを試みる解決した」と言う情報しか得られませんでした。

私の場合 Heroku run rails c -> User.all を試したところ、該当のユーザーはきちんとデータベースに登録されている事が確認出来ました。ユーザー情報が存在しているにも関わらずログインが出来ないと言う状況です。

Heroku logs -t でログを確認してみたものの、エラーらしき記述を見つける事が出来ませんでした。以下がログインアクションを含む、ステージング環境を動かした際のログです。

2021-10-12T06:47:00.234658+00:00 heroku[web.1]: Process exited with status 143
2021-10-12T06:47:07.000000+00:00 app[api]: Build succeeded
2021-10-12T06:47:08.927921+00:00 heroku[web.1]: Starting process with command `bin/rails server -p ${PORT:-5000} -e production`
2021-10-12T06:47:13.161822+00:00 heroku[web.1]: State changed from starting to up
2021-10-12T06:47:22.072892+00:00 heroku[router]: at=info method=GET path="/" host=hoge.herokuapp.com request_id=92132780-ed51-4f7e-a38f-1ddcac5daf99 fwd="106.181.160.222" dyno=web.1 connect=0ms service=73ms status=302 bytes=969 protocol=https
2021-10-12T06:47:22.001611+00:00 app[web.1]: => Booting Puma
2021-10-12T06:47:22.001625+00:00 app[web.1]: => Rails 5.2.6 application starting in production
2021-10-12T06:47:22.001626+00:00 app[web.1]: => Run `rails server -h` for more startup options
2021-10-12T06:47:22.001626+00:00 app[web.1]: Puma starting in single mode...
2021-10-12T06:47:22.001626+00:00 app[web.1]: * Version 3.12.6 (ruby 2.6.8-p205), codename: Llamas in Pajamas
2021-10-12T06:47:22.001627+00:00 app[web.1]: * Min threads: 5, max threads: 5
2021-10-12T06:47:22.001627+00:00 app[web.1]: * Environment: production
2021-10-12T06:47:22.001627+00:00 app[web.1]: * Listening on tcp://0.0.0.0:19816
2021-10-12T06:47:22.001627+00:00 app[web.1]: Use Ctrl-C to stop
2021-10-12T06:47:22.001628+00:00 app[web.1]: I, [2021-10-12T06:47:22.001511 #4]  INFO -- : [92132780-ed51-4f7e-a38f-1ddcac5daf99] Started GET "/" for 106.181.160.222 at 2021-10-12 06:47:22 +0000
2021-10-12T06:47:22.002655+00:00 app[web.1]: I, [2021-10-12T06:47:22.002597 #4]  INFO -- : [92132780-ed51-4f7e-a38f-1ddcac5daf99] Processing by UsersController#top as HTML
2021-10-12T06:47:22.068886+00:00 app[web.1]: D, [2021-10-12T06:47:22.068807 #4] DEBUG -- : [92132780-ed51-4f7e-a38f-1ddcac5daf99]   User Load (1.3ms)  SELECT  "users".* FROM "users" WHERE "users"."id" IS NULL LIMIT $1  [["LIMIT", 1]]
2021-10-12T06:47:22.069356+00:00 app[web.1]: I, [2021-10-12T06:47:22.069304 #4]  INFO -- : [92132780-ed51-4f7e-a38f-1ddcac5daf99] Redirected to https://hoge.herokuapp.com/login
2021-10-12T06:47:22.069415+00:00 app[web.1]: I, [2021-10-12T06:47:22.069390 #4]  INFO -- : [92132780-ed51-4f7e-a38f-1ddcac5daf99] Filter chain halted as :authenticate_user rendered or redirected
2021-10-12T06:47:22.069517+00:00 app[web.1]: I, [2021-10-12T06:47:22.069493 #4]  INFO -- : [92132780-ed51-4f7e-a38f-1ddcac5daf99] Completed 302 Found in 67ms (ActiveRecord: 28.0ms)
2021-10-12T06:47:22.483502+00:00 heroku[router]: at=info method=GET path="/login" host=hoge.herokuapp.com request_id=b8471159-6064-43d7-8c4b-857a9267369e fwd="106.181.160.222" dyno=web.1 connect=0ms service=44ms status=200 bytes=5015 protocol=https
2021-10-12T06:47:22.439459+00:00 app[web.1]: I, [2021-10-12T06:47:22.439391 #4]  INFO -- : [b8471159-6064-43d7-8c4b-857a9267369e] Started GET "/login" for 106.181.160.222 at 2021-10-12 06:47:22 +0000
2021-10-12T06:47:22.440264+00:00 app[web.1]: I, [2021-10-12T06:47:22.440195 #4]  INFO -- : [b8471159-6064-43d7-8c4b-857a9267369e] Processing by UsersController#login_form as HTML
2021-10-12T06:47:22.448194+00:00 app[web.1]: D, [2021-10-12T06:47:22.447956 #4] DEBUG -- : [b8471159-6064-43d7-8c4b-857a9267369e]   User Load (3.3ms)  SELECT  "users".* FROM "users" WHERE "users"."id" IS NULL LIMIT $1  [["LIMIT", 1]]
2021-10-12T06:47:22.460549+00:00 app[web.1]: I, [2021-10-12T06:47:22.460442 #4]  INFO -- : [b8471159-6064-43d7-8c4b-857a9267369e]   Rendering users/login_form.html.erb within layouts/application
2021-10-12T06:47:22.463981+00:00 app[web.1]: I, [2021-10-12T06:47:22.463869 #4]  INFO -- : [b8471159-6064-43d7-8c4b-857a9267369e]   Rendered users/login_form.html.erb within layouts/application (3.2ms)
2021-10-12T06:47:22.476022+00:00 app[web.1]: D, [2021-10-12T06:47:22.475940 #4] DEBUG -- : [b8471159-6064-43d7-8c4b-857a9267369e]   CACHE User Load (0.0ms)  SELECT  "users".* FROM "users" WHERE "users"."id" IS NULL LIMIT $1  [["LIMIT", 1]]
2021-10-12T06:47:22.480355+00:00 app[web.1]: I, [2021-10-12T06:47:22.480293 #4]  INFO -- : [b8471159-6064-43d7-8c4b-857a9267369e] Completed 200 OK in 40ms (Views: 20.9ms | ActiveRecord: 3.3ms)
2021-10-12T06:47:24.905575+00:00 heroku[router]: at=info method=GET path="/country-select-js-master/build/css/countrySelect.css" host=hoge.herokuapp.com request_id=0150fcf9-a871-499a-9183-b4af89f791e6 fwd="106.181.160.222" dyno=web.1 connect=0ms service=6ms status=200 bytes=23223 protocol=https
2021-10-12T06:47:36.035785+00:00 heroku[router]: at=info method=POST path="/login" host=hoge.herokuapp.com request_id=25e922c2-a2d9-4c0a-82e2-4bd629c7f72a fwd="106.181.160.222" dyno=web.1 connect=0ms service=13ms status=200 bytes=5009 protocol=https
2021-10-12T06:47:36.029749+00:00 app[web.1]: I, [2021-10-12T06:47:36.029673 #4]  INFO -- : [25e922c2-a2d9-4c0a-82e2-4bd629c7f72a] Started POST "/login" for 106.181.160.222 at 2021-10-12 06:47:36 +0000
2021-10-12T06:47:36.030350+00:00 app[web.1]: I, [2021-10-12T06:47:36.030307 #4]  INFO -- : [25e922c2-a2d9-4c0a-82e2-4bd629c7f72a] Processing by UsersController#login as HTML
2021-10-12T06:47:36.030398+00:00 app[web.1]: I, [2021-10-12T06:47:36.030366 #4]  INFO -- : [25e922c2-a2d9-4c0a-82e2-4bd629c7f72a]   Parameters: {"utf8"=>"✓", "authenticity_token"=>"Beft8hxwZ0OxZeSL3M3wuzQ2rAMzfbO4268bjy+Mmon0FQE9SA+ahZ9aemMqLOehklbP/S5G1XIfmJbF6KK1qQ==", "email"=>"hoge@fuga.comm", "password"=>"[FILTERED]"}
2021-10-12T06:47:36.033840+00:00 app[web.1]: D, [2021-10-12T06:47:36.033777 #4] DEBUG -- : [25e922c2-a2d9-4c0a-82e2-4bd629c7f72a]   User Load (1.2ms)  SELECT  "users".* FROM "users" WHERE "users"."id" IS NULL LIMIT $1  [["LIMIT", 1]]
2021-10-12T06:47:36.034672+00:00 app[web.1]: I, [2021-10-12T06:47:36.034626 #4]  INFO -- : [25e922c2-a2d9-4c0a-82e2-4bd629c7f72a] Completed 200 OK in 4ms (ActiveRecord: 1.2ms)

ローカル環境では新規ユーザー登録・ログイン共に問題なく出来ますので、ログイン機能に関するコードに問題はないと思いますが、必要なコードやログがありましたら追記させて頂きます。
またローカル環境でログインを試みた際のログは以下の様になります。

Started POST "/login" for ::1 at 2021-10-12 22:05:33 +0900
Processing by UsersController#login as HTML
  Parameters: {"utf8"=>"✓", "authenticity_token"=>"tiF++rWWqbqxr7qrIDVwWM7l/maX+DmYI+Lrz99GpiIURMAkSz66n/4Dvv5vlvJa3EyPe23oVuvC6cYmLNbSjg==", "email"=>"hoge@fuga.com", "password"=>"[FILTERED]"}
  User Load (0.6ms)  SELECT  `users`.* FROM `users` WHERE `users`.`id` IS NULL LIMIT 1
  ↳ app/controllers/application_controller.rb:9
  User Load (5.1ms)  SELECT  `users`.* FROM `users` WHERE `users`.`email` = 'hoge@fuga.com' LIMIT 1
  ↳ app/controllers/users_controller.rb:255
Redirected to http://localhost:3000/
Completed 302 Found in 400ms (ActiveRecord: 23.5ms)


Started GET "/" for ::1 at 2021-10-12 22:05:33 +0900
Processing by UsersController#top as HTML
  User Load (6.9ms)  SELECT  `users`.* FROM `users` WHERE `users`.`id` = 8 LIMIT 1

以下略

何か思い当たる原因はありそうでしょうか。どなたかご助言を頂けますと有難いです。

コード

routes.rb

get "login" => "users#login_form"
post "login" => "users#login"

users_controller.rb

class UsersController < ApplicationController
  before_action :authenticate_user, {except: [:new, :create, :login_form, :login]}
  before_action :forbid_login_user, {only: [:new, :create, :login_form, :login]}

  def login
    @user = User.find_by(email: params[:email])
    if @user && @user.authenticate(params[:password])
      session[:user_id] = @user.id
      flash[:notice] = "You have successfully logged in"
      redirect_to("/")
    else
      @error_message = "Email address or password is incorrect"
      @email = params[:email]
      @password = params[:password]
      render("users/login_form")
    end
  end

  def login_form
  end
end

users/login_form.html.erb

<% if @error_message %>
  <div class="form-error">
    <%= @error_message %>
  </div>
<% end %>
  
<%= form_tag("/login") do %>
<ul>
  <li>
    <div class="col-1">Email</div>
    <div class="col-2"><input size="60" name="email" value="<%= @email %>"></div>
  </li>
  <li>
    <div class="col-1">Password</div>
    <div class="col-2"><input size="40" id="password" name="password" type="password" value="<%= @password %>"></div>
    <span toggle="#password-field" class="fa fa-fw fa-eye field_icon toggle-password"></span>
  </li>
  <li>
    <div class="save"><input class="btn-square-little-rich" id="button" type="submit" value="Log in" onclick="myfunk()"></div>
  </li>
</ul>    
<% end %>

試したこと

以前secure属性をいじった事で、ローカル環境でログイン出来なくなった事がありました。
その際は secure: true に設定してしまった為、httpsではクッキーが発行されるけれどもhttpではクッキーが発行されずログイン出来ない為リダイレクトしてしまう、と言う内容でした。

今回は逆にhttpsであるステージング環境で起きている問題ですので関係はないかと思いましたが、一応以下の様に secure: false にして試してみるも、やはり結果は変わりませんでした。

config/application.rb

config.session_store :cookie_store, expire_after: 8.hours, secure: Rails.env.production?  
↓
config.session_store :cookie_store, expire_after: 8.hours, secure: false

config/production.rb

config.force_ssl = true
↓
config.force_ssl = false
# application.rb内で記述した、secure: Rails.env.production?（本番環境のみSSL属性を付ける（SSL化する））為に必要なコード。デフォルトのfalseに直すも結果は変わらず。

補足情報（FW/ツールのバージョンなど）

ruby 2.6.4p104
RubyGems 3.0.3
Rails 5.2.3

winterboum

2021/10/11 09:06

codeが何もないのではなにも言えません。とりあえず、login部分のcodeを載せてください。

punchan36

2021/10/11 10:42

有難うございます。ログインに関するコードを追記致しました。宜しくお願い致します。

neko_daisuki

2021/10/12 05:44

ログを見ると ID が NULL のユーザーを探していますが、これは　forbid_login_user　内の処理でしょうか？ login の User.find_by(email: params[:email]) が実行されてないようなので、ここに到達する前にレスポンスを返してしまっているように見えます。

punchan36

2021/10/12 07:06

有難うございます！どうやら forbid_login_user は関係がなさそうです。forbid_login_user の行をコメントアウトし、GitHubにプッシュ → Herokuに反映しステージング環境で再度試してみましたが、結果は同じでした。また追記致しましたが、Secure属性の関係で一緒にいじった config.force_ssl = true をデフォルトの false に戻すも何も変わりませんでした。こちらも追記致しましたが、ログインアクションを行う前のログに Filter chain halted as :authenticate_user rendered or redirected がありました。Secure属性をいじった際にも表れた内容ですが、今回Secure属性周辺は全てデフォルトのコードに直したつもりです…。

neko_daisuki

2021/10/12 09:29

Filter chain halted は before_action などで render とかすると出る奴なので GET "/"　がログインしたユーザーしか閲覧できないのであれば問題ないと思います。不思議なのは 1. User.find_by(email: params[:email]) のログがない 2. ステータスが 200 なのに何も render していない 1 は config.log_level の設定が :info なのかと思いましたが、他の :debug は表示されてるので、実際に User.find_by(email: params[:email]) が実行されていないのかも。だから before_action が原因だと思ったのですが、Filter chain halted ... が表示されてないですね。 rescue_from で head :ok を返している箇所とかありませんか？

punchan36

2021/10/12 14:04

有難うございます。 config.log_level はデフォルトの :debug のまま変えておりませんので、出せるログはこれで全て、と言う事ですよね。 rescue_from、headと言うメソッドがそれぞれ存在するのですね…。初めて耳にしましたので調べて見よう見まねで以下の様に書いてみたりしましたが、使い方が間違っているようです…。 rescue_fromメソッドを使い、問題点の出所を虱潰しに探していく、と言う事なのでしょうか？ ``` rescue_from ActiveRecord::RecordNotFound, with: :record_not_found private def record_not_found render plain: "404 Not Found", status: 404 end ``` また、localhostでログインを試みた際のログも載せておきました。こちらはトップページにリダイレクトされる直前に User Load (5.1ms) SELECT `users`.* FROM `users` WHERE `users`.`email` = 'hoge@fuga.com' LIMIT 1 が読み込まれています。

neko_daisuki

2021/10/12 14:36

いえ、すでに rescue_from が存在していて、どこかで予期しないエラーが発生しているのを rescue_from が拾い、その中で空のレスポンスを返しているんじゃないかと思ったのです。そう考えるとログとの辻褄は合います。 def login が実行される前に何かが起きてる感じがしますね。 ApplicationController に before_action はありますか？

punchan36

2021/10/12 14:48

知識不足で申し訳ありません。rescue_from の記事をもう少し読んでみます。 before_action関連の記述はこちらになります。 class ApplicationController < ActionController::Base before_action :set_current_user skip_before_action :verify_authenticity_token def set_current_user @current_user = User.find_by(id: session[:user_id]) end end

neko_daisuki

2021/10/12 15:12

エラーが発生しそうな箇所はないですね・・・ github のリポジトリは公開されているものですか？差支えなければ教えてください。

punchan36

2021/10/12 15:36 編集

リポジトリは今の所Privateにしているんです。一人で作っておりまして、自分用のコメントアウト等もそのままで、公開するのが少し恥ずかしかったもので…。^^; 個人間での共有であれば是非お願いしたいのですが、teratailで個別メッセージは送れないのですね。。上記の情報だけですと、やはり原因を突き止めるのは難しそうでしょうか。もしくは、Herokuのデプロイ関連で、ちゃんとやったつもりでしたが何か問題があったのか…。初めてのデプロイでしたので、そちらでも原因が無いか探ってみます。

neko_daisuki

2021/10/12 15:42

そうですね。エラーが出ないと難しいです。ただ　Completed 200 OK in 4ms (ActiveRecord: 1.2ms)　このログは Views の情報がないという特徴があるので、head :ok か、 render body: nil のものだと思います。あと試せそうなことは config/database.yml の　development の database の値を変更して、 create migration してステージングと同じ挙動にならないか確認するとかでしょうか。

punchan36

2021/10/13 07:44

少し発展がありました。ユーザー新規登録（サインイン）も同様に上手くいかなかったのですが、以下のログが出ていました。 Errno::ECONNREFUSED (Connection refused - connect(2) for "localhost" port 25) 調べた所 development.rb で設定していた Mailer に関する記述を production.rb 内で書いていなかった為、ローカル環境では送れていたメールがステージング環境ではメールが送れていなかったのが原因でした。 Mailerに関する記述を production.rb にもコピペする事でサインインは無事出来る様になり、以下のアクションも成功しました。・サインインした後はトップページ("/")ではなくユーザー詳細ページ("/users/id")に飛ぶようにしているのですが、そのリダイレクトまで成功。・サインイン後、ログインした状態でトップページ("/")にも遷移できる。・ログアウトも出来る。しかしサインインが成功したユーザーで再度ログインページからログインを試みると、以前と変わらず失敗しました。。またログインした状態で色々な機能が動くのかも試してみましたが、データベースにアクション情報が保存はされるものの、ビューで表示されないなどのおかしな点が大量に出てきました…（データベース上ではユーザーをフォローしていると出ているのに、ビューではフォロー中のユーザーが0になるなど）。

punchan36

2021/10/13 07:49

これらの情報で原因究明が難しそうであれば、リポジトリを一時的にpublicにして neko_daisuki さまに助けて頂けますと有難いですのですが宜しいでしょうか…？

neko_daisuki

2021/10/13 08:49

分かりました。解決できるか分かりませんがやってみます。

punchan36

2021/10/13 08:56

申し訳ありません、有難うございます。リポジトリはこちらです。見苦しい点もあるかと思いますが、何卒宜しくお願い致します。 https://github.com/punchan36/langland

neko_daisuki

2021/10/13 09:00

git clone したのでプライベートにしてもらって大丈夫です

punchan36

2021/10/13 09:04

お気遣いまで頂き、本当に有難うございます。

neko_daisuki

2021/10/13 10:14

UsersController の caches_action に :create を含めているのが原因っぽいです。アクションキャッシュは before_action のみ実行され、action(def create) が実行されなくなってしまいます。なので以下の現象が起きたんですね。・develpment 環境ではキャッシュが無効になるので production 環境のみで発生する・SQL が発行されない・View を render しない

punchan36

2021/10/13 13:55

有難うございます！ caches_action の :login_form, :login を削除する事で上手くいきました。 config/environments 内にあります config.cache_classes が、ローカル環境では false、本番環境では true にデフォルトで設定されているから、と言う認識で合っておりますでしょうか。かなり前に、ページを早く読み込ませようとして書いた部分が仇になっていたようです…。今後は自分で原因に気付けるようになりたいのですが、今回エラー等を辿ってと言うよりは、経験則からおかしなコードが無いかを探されたと言う感じでしょうか？またステージング環境で発生していた他の不具合もこの caches_action が原因でした。:login_form, :login 以外にも色々なアクションを追加しておりましたので、それらを全て削除する事で正常に動くようになりました。もう一点上手く動作しない部分がありますが、恐らく原因が違う別件になるかと思いますので、もう少し考えて解決出来なければ別で質問を立てようと思います…。ベストアンサーにさせて頂きたいので、恐れ入りますがご回答頂けませんでしょうか？

neko_daisuki

2021/10/13 14:05

分かりました。メールを送ったので確認をお願いします。

punchan36

2021/10/13 14:37

確認致しました！有難うございます。