1.production環境でユーザー登録を試してみましょう。ユーザー登録時に入力したメールアドレスにメールは届きましたか?
まずは「Sign up」画面から、ユーザー登録に必要な情報を入力し、「Create my account」ボタンをクリックします。
上記の画面が出て、入力したメールアドレスが有効ならば、実際にメールが到着しているはずです。確認してみましょう。
確かにメールが到着していました。
2. メールを受信できたら、実際にメールをクリックしてアカウントを有効化してみましょう。また、Heroku上のログを調べてみて、有効化に関するログがどうなっているのか調べてみてください。
ヒント: ターミナルからheroku logsコマンドを実行してみましょう。
まずは、受信したメールの「Activate」リンクをクリックします。
無事ユーザーが有効化されました。
ユーザー有効化処理時のサーバーログ
まずはUsersコントローラーのnewアクションに関するログです。新規ユーザー登録情報の入力画面が表示されるところまでです。
2019-12-17T03:38:26.701082+00:00 heroku[router]: at=info method=GET path="/signup" host=warm-woodland-62915.herokuapp.com request_id=9ef43fd8-9976-4b6c-9793-fde8257190ab fwd="103.5.140.188" dyno=web.1 connect=1ms service=28ms status=200 bytes=3428 protocol=https
2019-12-17T03:38:26.675341+00:00 app[web.1]: I, [2019-12-17T03:38:26.675221 #4] INFO -- : [9ef43fd8-9976-4b6c-9793-fde8257190ab] Started GET "/signup" for 103.5.140.188 at 2019-12-17 03:38:26 +0000
2019-12-17T03:38:26.676239+00:00 app[web.1]: I, [2019-12-17T03:38:26.676157 #4] INFO -- : [9ef43fd8-9976-4b6c-9793-fde8257190ab] Processing by UsersController#new as HTML
2019-12-17T03:38:26.677651+00:00 app[web.1]: I, [2019-12-17T03:38:26.677545 #4] INFO -- : [9ef43fd8-9976-4b6c-9793-fde8257190ab] Rendering users/new.html.erb within layouts/application
2019-12-17T03:38:26.678404+00:00 app[web.1]: I, [2019-12-17T03:38:26.678315 #4] INFO -- : [9ef43fd8-9976-4b6c-9793-fde8257190ab] Rendered shared/_error_messages.html.erb (0.1ms)
2019-12-17T03:38:26.686611+00:00 app[web.1]: I, [2019-12-17T03:38:26.686532 #4] INFO -- : [9ef43fd8-9976-4b6c-9793-fde8257190ab] Rendered users/_form.html.erb (8.5ms)
2019-12-17T03:38:26.686868+00:00 app[web.1]: I, [2019-12-17T03:38:26.686762 #4] INFO -- : [9ef43fd8-9976-4b6c-9793-fde8257190ab] Rendered users/new.html.erb within layouts/application (9.1ms)
2019-12-17T03:38:26.688192+00:00 app[web.1]: I, [2019-12-17T03:38:26.688122 #4] INFO -- : [9ef43fd8-9976-4b6c-9793-fde8257190ab] Rendered layouts/_rails_default.erb (0.9ms)
2019-12-17T03:38:26.688627+00:00 app[web.1]: I, [2019-12-17T03:38:26.688523 #4] INFO -- : [9ef43fd8-9976-4b6c-9793-fde8257190ab] Rendered layouts/_shim.html.erb (0.1ms)
2019-12-17T03:38:26.689527+00:00 app[web.1]: I, [2019-12-17T03:38:26.689418 #4] INFO -- : [9ef43fd8-9976-4b6c-9793-fde8257190ab] Rendered layouts/_header.html.erb (0.6ms)
2019-12-17T03:38:26.690255+00:00 app[web.1]: I, [2019-12-17T03:38:26.690186 #4] INFO -- : [9ef43fd8-9976-4b6c-9793-fde8257190ab] Rendered layouts/_footer.html.erb (0.3ms)
2019-12-17T03:38:26.690776+00:00 app[web.1]: I, [2019-12-17T03:38:26.690656 #4] INFO -- : [9ef43fd8-9976-4b6c-9793-fde8257190ab] Completed 200 OK in 14ms (Views: 13.3ms | ActiveRecord: 0.0ms)
続いて、Usersコントローラーのcreateアクションが開始されました。ユーザーの操作としては、「新規ユーザー登録情報の入力画面で、「Submit」ボタンがクリックされたところ」です。
2019-12-17T03:39:00.628200+00:00 app[web.1]: I, [2019-12-17T03:39:00.628068 #4] INFO -- : [b0361e09-bbea-4688-bdcd-1f9d317e14fa] Started POST "/signup" for 103.5.140.188 at 2019-12-17 03:39:00 +0000
2019-12-17T03:39:00.629006+00:00 app[web.1]: I, [2019-12-17T03:39:00.628922 #4] INFO -- : [b0361e09-bbea-4688-bdcd-1f9d317e14fa] Processing by UsersController#create as HTML
2019-12-17T03:39:00.629110+00:00 app[web.1]: I, [2019-12-17T03:39:00.629041 #4] INFO -- : [b0361e09-bbea-4688-bdcd-1f9d317e14fa] Parameters: {"utf8"=>"✓", "authenticity_token"=>"kPI+VonM8nuUu11tRyJNCgkw++6CAdlBZgdH7pgF3GwQjj4/Ah6f7x8yXoXNG4AwTYpDgE+jwtNJ13XXCZMh8w==", "user"=>{"name"=>"Hoge Hoge", "email"=>"[有効なメールアドレス]", "password"=>"[FILTERED]", "password_confirmation"=>"[FILTERED]"}, "commit"=>"Create my account"}
2019-12-17T03:39:00.714970+00:00 app[web.1]: D, [2019-12-17T03:39:00.714832 #4] DEBUG -- : [b0361e09-bbea-4688-bdcd-1f9d317e14fa] (1.7ms) BEGIN
2019-12-17T03:39:00.718390+00:00 app[web.1]: D, [2019-12-17T03:39:00.718293 #4] DEBUG -- : [b0361e09-bbea-4688-bdcd-1f9d317e14fa] User Exists (2.1ms) SELECT 1 AS one FROM "users" WHERE LOWER("users"."email") = LOWER($1) LIMIT $2 [["email", "[有効なメールアドレス]"], ["LIMIT", 1]]
2019-12-17T03:39:00.807361+00:00 app[web.1]: D, [2019-12-17T03:39:00.807224 #4] DEBUG -- : [b0361e09-bbea-4688-bdcd-1f9d317e14fa] SQL (10.7ms) INSERT INTO "users" ("name", "email", "created_at", "updated_at", "password_digest", "activation_digest") VALUES ($1, $2, $3, $4, $5, $6) RETURNING "id" [["name", "Hoge Hoge"], ["email", "[有効なメールアドレス]"], ["created_at", "2019-12-17 03:39:00.718914"], ["updated_at", "2019-12-17 03:39:00.718914"], ["password_digest", "$2a$10$tLq83mKKaJN4XGBafxp0BOMpmTDw6iKYj729bNu9dE6jrGYu7w/o6"], ["activation_digest", "$2a$10$CKnDgcIkfShDxkQLli6OU.6vszmQ3rrXdSMa7khjybONYxxNWxNf2"]]
2019-12-17T03:39:00.811145+00:00 app[web.1]: D, [2019-12-17T03:39:00.811013 #4] DEBUG -- : [b0361e09-bbea-4688-bdcd-1f9d317e14fa] (3.0ms) COMMIT
有効化トークンに対応するダイジェストは以下の文字列ですね。
$2a$10$CKnDgcIkfShDxkQLli6OU.6vszmQ3rrXdSMa7khjybONYxxNWxNf2
続いて、メイラーに関するログが返されています。
2019-12-17T03:39:00.817822+00:00 app[web.1]: I, [2019-12-17T03:39:00.817728 #4] INFO -- : [b0361e09-bbea-4688-bdcd-1f9d317e14fa] Rendering user_mailer/account_activation.html.erb within layouts/mailer
2019-12-17T03:39:00.818892+00:00 app[web.1]: I, [2019-12-17T03:39:00.818826 #4] INFO -- : [b0361e09-bbea-4688-bdcd-1f9d317e14fa] Rendered user_mailer/account_activation.html.erb within layouts/mailer (0.9ms)
2019-12-17T03:39:00.819846+00:00 app[web.1]: I, [2019-12-17T03:39:00.819782 #4] INFO -- : [b0361e09-bbea-4688-bdcd-1f9d317e14fa] Rendering user_mailer/account_activation.text.erb within layouts/mailer
2019-12-17T03:39:00.820407+00:00 app[web.1]: I, [2019-12-17T03:39:00.820338 #4] INFO -- : [b0361e09-bbea-4688-bdcd-1f9d317e14fa] Rendered user_mailer/account_activation.text.erb within layouts/mailer (0.4ms)
2019-12-17T03:39:01.140739+00:00 app[web.1]: D, [2019-12-17T03:39:01.140608 #4] DEBUG -- : [b0361e09-bbea-4688-bdcd-1f9d317e14fa] UserMailer#account_activation: processed outbound mail in 328.5ms
2019-12-17T03:39:01.383306+00:00 app[web.1]: I, [2019-12-17T03:39:01.383191 #4] INFO -- : [b0361e09-bbea-4688-bdcd-1f9d317e14fa] Sent mail to [有効なメールアドレス] (242.3ms)
2019-12-17T03:39:01.383340+00:00 app[web.1]: D, [2019-12-17T03:39:01.383285 #4] DEBUG -- : [b0361e09-bbea-4688-bdcd-1f9d317e14fa] Date: Tue, 17 Dec 2019 03:39:01 +0000
続いて、ユーザー有効化URL通知用メールのヘッダーが返されます。
2019-12-17T03:39:01.383343+00:00 app[web.1]: From: noreply@example.com
2019-12-17T03:39:01.383345+00:00 app[web.1]: To: [有効なメールアドレス]
2019-12-17T03:39:01.383347+00:00 app[web.1]: Message-ID: <5df84dd5239a7_42b04df0df05c5129@b042e83a-3492-4249-911e-6b41b5e09cd5.mail>
2019-12-17T03:39:01.383349+00:00 app[web.1]: Subject: Account activation
2019-12-17T03:39:01.383351+00:00 app[web.1]: Mime-Version: 1.0
2019-12-17T03:39:01.383353+00:00 app[web.1]: Content-Type: multipart/alternative;
2019-12-17T03:39:01.383355+00:00 app[web.1]: boundary="--==_mimepart_5df84dd521d3b_42b04df0df05c50d3";
2019-12-17T03:39:01.383358+00:00 app[web.1]: charset=UTF-8
2019-12-17T03:39:01.383360+00:00 app[web.1]: Content-Transfer-Encoding: 7bit
2019-12-17T03:39:01.383362+00:00 app[web.1]:
2019-12-17T03:39:01.383364+00:00 app[web.1]:
2019-12-17T03:39:01.383366+00:00 app[web.1]: ----==_mimepart_5df84dd521d3b_42b04df0df05c50d3
以下のログには、テキストメールの本文が返されています。
2019-12-17T03:39:01.383368+00:00 app[web.1]: Content-Type: text/plain;
2019-12-17T03:39:01.383370+00:00 app[web.1]: charset=UTF-8
2019-12-17T03:39:01.383372+00:00 app[web.1]: Content-Transfer-Encoding: 7bit
2019-12-17T03:39:01.383374+00:00 app[web.1]:
2019-12-17T03:39:01.383376+00:00 app[web.1]: Hi Hoge Hoge,
2019-12-17T03:39:01.383377+00:00 app[web.1]:
2019-12-17T03:39:01.383380+00:00 app[web.1]: Welcome to the Sample App! Click on the link below to activate your account:
2019-12-17T03:39:01.383382+00:00 app[web.1]:
2019-12-17T03:39:01.383384+00:00 app[web.1]: https://warm-woodland-62915.herokuapp.com/account_activations/iNFYhM1X7rDUmVORFrGMbA/edit?email=[有効なメールアドレス]
2019-12-17T03:39:01.383386+00:00 app[web.1]:
2019-12-17T03:39:01.383387+00:00 app[web.1]:
2019-12-17T03:39:01.383390+00:00 app[web.1]: ----==_mimepart_5df84dd521d3b_42b04df0df05c50d3
以下のログには、HTMLメールの本文が返されています。
2019-12-17T03:39:01.383392+00:00 app[web.1]: Content-Type: text/html;
2019-12-17T03:39:01.383393+00:00 app[web.1]: charset=UTF-8
2019-12-17T03:39:01.383395+00:00 app[web.1]: Content-Transfer-Encoding: 7bit
2019-12-17T03:39:01.383397+00:00 app[web.1]:
2019-12-17T03:39:01.383402+00:00 app[web.1]: <!DOCTYPE html>
2019-12-17T03:39:01.383404+00:00 app[web.1]: <html>
2019-12-17T03:39:01.383406+00:00 app[web.1]: <head>
2019-12-17T03:39:01.383409+00:00 app[web.1]: <meta http-equiv="Content-Type" content="text/html; charset=utf-8" />
2019-12-17T03:39:01.383410+00:00 app[web.1]: <style>
2019-12-17T03:39:01.383412+00:00 app[web.1]: /* Email styles need to be inline */
2019-12-17T03:39:01.383414+00:00 app[web.1]: </style>
2019-12-17T03:39:01.383416+00:00 app[web.1]: </head>
2019-12-17T03:39:01.383418+00:00 app[web.1]:
2019-12-17T03:39:01.383420+00:00 app[web.1]: <body>
2019-12-17T03:39:01.383422+00:00 app[web.1]: <h1>Sample App</h1>
2019-12-17T03:39:01.383424+00:00 app[web.1]:
2019-12-17T03:39:01.383426+00:00 app[web.1]: <p>Hi Hoge Hoge,</p>
2019-12-17T03:39:01.383428+00:00 app[web.1]:
2019-12-17T03:39:01.383430+00:00 app[web.1]: <p>
2019-12-17T03:39:01.383432+00:00 app[web.1]: Welcome to the Sample App! Click on the link below to activate your account:
2019-12-17T03:39:01.383434+00:00 app[web.1]: </p>
2019-12-17T03:39:01.383435+00:00 app[web.1]:
2019-12-17T03:39:01.383438+00:00 app[web.1]: <a href="https://warm-woodland-62915.herokuapp.com/account_activations/iNFYhM1X7rDUmVORFrGMbA/edit?email=[有効なメールアドレス]">Activate</a>
2019-12-17T03:39:01.383440+00:00 app[web.1]:
2019-12-17T03:39:01.383441+00:00 app[web.1]: </body>
2019-12-17T03:39:01.383443+00:00 app[web.1]: </html>
2019-12-17T03:39:01.383445+00:00 app[web.1]:
2019-12-17T03:39:01.383447+00:00 app[web.1]: ----==_mimepart_5df84dd521d3b_42b04df0df05c50d3--
メール本文から、有効化トークンは以下の文字列であることがわかります。
iNFYhM1X7rDUmVORFrGMbA
続いてのログにより、Usersコントローラーのcreateアクションの最後は / へのリダイレクトで完了したことがわかります。
2019-12-17T03:39:01.383918+00:00 app[web.1]: I, [2019-12-17T03:39:01.383828 #4] INFO -- : [b0361e09-bbea-4688-bdcd-1f9d317e14fa] Redirected to https://warm-woodland-62915.herokuapp.com/
2019-12-17T03:39:01.384190+00:00 app[web.1]: I, [2019-12-17T03:39:01.384101 #4] INFO -- : [b0361e09-bbea-4688-bdcd-1f9d317e14fa] Completed 302 Found in 752ms (ActiveRecord: 17.6ms)
今度は、AccountActivationsコントローラーに対するeditが開始されたところからのログです。「メール本文中に記載されたURLにアクセスがあった」というタイミングですね。
2019-12-17T03:48:03.998174+00:00 app[web.1]: I, [2019-12-17T03:48:03.998081 #4] INFO -- : [f2ca36e3-b2d1-4746-ba15-c67b852fbee5] Started GET "/account_activations/iNFYhM1X7rDUmVORFrGMbA/edit?email=[有効なメールアドレス]" for 103.5.140.188 at 2019-12-17 03:48:03 +0000
2019-12-17T03:48:03.999604+00:00 app[web.1]: I, [2019-12-17T03:48:03.999504 #4] INFO -- : [f2ca36e3-b2d1-4746-ba15-c67b852fbee5] Processing by AccountActivationsController#edit as HTML
2019-12-17T03:48:03.999666+00:00 app[web.1]: I, [2019-12-17T03:48:03.999597 #4] INFO -- : [f2ca36e3-b2d1-4746-ba15-c67b852fbee5] Parameters: {"email"=>"[有効なメールアドレス]", "id"=>"iNFYhM1X7rDUmVORFrGMbA"}
2019-12-17T03:48:04.013441+00:00 app[web.1]: D, [2019-12-17T03:48:04.013350 #4] DEBUG -- : [f2ca36e3-b2d1-4746-ba15-c67b852fbee5] User Load (4.0ms) SELECT "users".* FROM "users" WHERE "users"."email" = $1 LIMIT $2 [["email", "[有効なメールアドレス]"], ["LIMIT", 1]]
2019-12-17T03:48:04.101912+00:00 app[web.1]: D, [2019-12-17T03:48:04.101770 #4] DEBUG -- : [f2ca36e3-b2d1-4746-ba15-c67b852fbee5] SQL (12.9ms) UPDATE "users" SET "activated" = 't', "activated_at" = '2019-12-17 03:48:04.087544' WHERE "users"."id" = $1 [["id", 104]]
2019-12-17T03:48:04.102898+00:00 app[web.1]: I, [2019-12-17T03:48:04.102788 #4] INFO -- : [f2ca36e3-b2d1-4746-ba15-c67b852fbee5] Redirected to https://warm-woodland-62915.herokuapp.com/users/104
2019-12-17T03:48:04.103242+00:00 app[web.1]: I, [2019-12-17T03:48:04.103156 #4] INFO -- : [f2ca36e3-b2d1-4746-ba15-c67b852fbee5] Completed 302 Found in 103ms (ActiveRecord: 18.7ms)
（再掲）以下のログのSQL文を見るに、ユーザーの有効化処理は正常に完了したようです。
2019-12-17T03:48:04.101912+00:00 app[web.1]: D, [2019-12-17T03:48:04.101770 #4] DEBUG -- : [f2ca36e3-b2d1-4746-ba15-c67b852fbee5] SQL (12.9ms) UPDATE "users" SET "activated" = 't', "activated_at" = '2019-12-17 03:48:04.087544' WHERE "users"."id" = $1 [["id", 104]]
3. アカウントを有効化できたら、今度はパスワードの再設定を試してみましょう。正しくパスワードの再設定ができたでしょうか?
まず、ログインフォームから「forgot password」のリンクをクリックします。
パスワード再設定の対象となるユーザーのメールアドレスを入力します。
メールが送られてきます。ハイライトした部分は再設定用トークンです。
リンクをクリックして、パスワード再設定フォームへ進みます。
新しいパスワードを入力します。
パスワードの再設定が完了し、パスワードを再設定したユーザーのプロフィールページが表示されます。
パスワード再設定に関するサーバーログ
まずはPasswordResetsコントローラーのnewアクションに関するログです。
2019-12-17T09:27:37.630786+00:00 app[web.1]: I, [2019-12-17T09:27:37.630687 #4] INFO -- : [4904fcd9-d965-4f6a-93d7-0fa95587d243] Started GET "/password_resets/new" for 175.177.6.7 at 2019-12-17 09:27:37 +0000
2019-12-17T09:27:37.632157+00:00 app[web.1]: I, [2019-12-17T09:27:37.632064 #4] INFO -- : [4904fcd9-d965-4f6a-93d7-0fa95587d243] Processing by PasswordResetsController#new as HTML
2019-12-17T09:27:37.634071+00:00 app[web.1]: I, [2019-12-17T09:27:37.633999 #4] INFO -- : [4904fcd9-d965-4f6a-93d7-0fa95587d243] Rendering password_resets/new.html.erb within layouts/application
2019-12-17T09:27:37.635383+00:00 app[web.1]: I, [2019-12-17T09:27:37.635314 #4] INFO -- : [4904fcd9-d965-4f6a-93d7-0fa95587d243] Rendered password_resets/new.html.erb within layouts/application (1.2ms)
2019-12-17T09:27:37.635971+00:00 app[web.1]: I, [2019-12-17T09:27:37.635907 #4] INFO -- : [4904fcd9-d965-4f6a-93d7-0fa95587d243] Rendered layouts/_rails_default.erb (0.4ms)
2019-12-17T09:27:37.636126+00:00 app[web.1]: I, [2019-12-17T09:27:37.636073 #4] INFO -- : [4904fcd9-d965-4f6a-93d7-0fa95587d243] Rendered layouts/_shim.html.erb (0.0ms)
2019-12-17T09:27:37.636548+00:00 app[web.1]: I, [2019-12-17T09:27:37.636470 #4] INFO -- : [4904fcd9-d965-4f6a-93d7-0fa95587d243] Rendered layouts/_header.html.erb (0.2ms)
2019-12-17T09:27:37.636862+00:00 app[web.1]: I, [2019-12-17T09:27:37.636799 #4] INFO -- : [4904fcd9-d965-4f6a-93d7-0fa95587d243] Rendered layouts/_footer.html.erb (0.1ms)
2019-12-17T09:27:37.637075+00:00 app[web.1]: I, [2019-12-17T09:27:37.637018 #4] INFO -- : [4904fcd9-d965-4f6a-93d7-0fa95587d243] Completed 200 OK in 5ms (Views: 3.7ms | ActiveRecord: 0.0ms)
ここまでのログは、「forgot password」リンクのクリックから、パスワード再設定対象のメールアドレスの入力画面がWebブラウザに表示されるところまでに対応しています。
続いて、PasswordResetsコントローラーのcreateアクションが開始されました。ユーザーの操作としては、「パスワード再設定対象のメールアドレスの入力画面で、「Submit」ボタンがクリックされたところ」です。
2019-12-17T09:28:10.677268+00:00 app[web.1]: I, [2019-12-17T09:28:10.677144 #4] INFO -- : [3885b893-52a2-4eed-bc9d-d14c153f57e1] Started POST "/password_resets" for 175.177.6.7 at 2019-12-17 09:28:10 +0000
2019-12-17T09:28:10.678356+00:00 app[web.1]: I, [2019-12-17T09:28:10.678278 #4] INFO -- : [3885b893-52a2-4eed-bc9d-d14c153f57e1] Processing by PasswordResetsController#create as HTML
2019-12-17T09:28:10.678449+00:00 app[web.1]: I, [2019-12-17T09:28:10.678378 #4] INFO -- : [3885b893-52a2-4eed-bc9d-d14c153f57e1] Parameters: {"utf8"=>"✓", "authenticity_token"=>"s6/JcwQzuM6JAiREt9u1PDuPaKc5we/TAWuJbaIJyxcyV3rusF2/H0ksby8hky03XDCj8W0j/jxFcmxVT61haQ==", "password_reset"=>"[FILTERED]", "commit"=>"Submit"}
2019-12-17T09:28:10.686514+00:00 app[web.1]: D, [2019-12-17T09:28:10.686418 #4] DEBUG -- : [3885b893-52a2-4eed-bc9d-d14c153f57e1] User Load (2.8ms) SELECT "users".* FROM "users" WHERE "users"."email" = $1 LIMIT $2 [["email", "[有効なメールアドレス]"], ["LIMIT", 1]]
2019-12-17T09:28:10.766666+00:00 app[web.1]: D, [2019-12-17T09:28:10.766571 #4] DEBUG -- : [3885b893-52a2-4eed-bc9d-d14c153f57e1] SQL (3.7ms) UPDATE "users" SET "reset_digest" = '$2a$10$uOXG8lKmc/1ytMzVC5QHAOiY0S/GjmMYHYMb7lVd.dNK8vIsQFYtG', "reset_sent_at" = '2019-12-17 09:28:10.762063' WHERE "users"."id" = $1 [["id", 104]]
（再掲）パスワード再設定トークンに対応するダイジェストをRDBに保存する処理には、以下のログが対応しています。
2019-12-17T09:28:10.766666+00:00 app[web.1]: D, [2019-12-17T09:28:10.766571 #4] DEBUG -- : [3885b893-52a2-4eed-bc9d-d14c153f57e1] SQL (3.7ms) UPDATE "users" SET "reset_digest" = '$2a$10$uOXG8lKmc/1ytMzVC5QHAOiY0S/GjmMYHYMb7lVd.dNK8vIsQFYtG', "reset_sent_at" = '2019-12-17 09:28:10.762063' WHERE "users"."id" = $1 [["id", 104]]
ダイジェストは以下の文字列ですね。
$2a$10$uOXG8lKmc/1ytMzVC5QHAOiY0S/GjmMYHYMb7lVd.dNK8vIsQFYtG
続いて、メイラーに関するログが返されています。
2019-12-17T09:28:10.771901+00:00 app[web.1]: I, [2019-12-17T09:28:10.771829 #4] INFO -- : [3885b893-52a2-4eed-bc9d-d14c153f57e1] Rendering user_mailer/password_reset.html.erb within layouts/mailer
2019-12-17T09:28:10.772669+00:00 app[web.1]: I, [2019-12-17T09:28:10.772606 #4] INFO -- : [3885b893-52a2-4eed-bc9d-d14c153f57e1] Rendered user_mailer/password_reset.html.erb within layouts/mailer (0.7ms)
2019-12-17T09:28:10.773513+00:00 app[web.1]: I, [2019-12-17T09:28:10.773447 #4] INFO -- : [3885b893-52a2-4eed-bc9d-d14c153f57e1] Rendering user_mailer/password_reset.text.erb within layouts/mailer
2019-12-17T09:28:10.773958+00:00 app[web.1]: I, [2019-12-17T09:28:10.773897 #4] INFO -- : [3885b893-52a2-4eed-bc9d-d14c153f57e1] Rendered user_mailer/password_reset.text.erb within layouts/mailer (0.4ms)
2019-12-17T09:28:10.987227+00:00 app[web.1]: D, [2019-12-17T09:28:10.987125 #4] DEBUG -- : [3885b893-52a2-4eed-bc9d-d14c153f57e1] UserMailer#password_reset: processed outbound mail in 219.8ms
2019-12-17T09:28:11.369313+00:00 heroku[router]: at=info method=POST path="/password_resets" host=warm-woodland-62915.herokuapp.com request_id=3885b893-52a2-4eed-bc9d-d14c153f57e1 fwd="175.177.6.7" dyno=web.1 connect=1ms service=692ms status=302 bytes=1049 protocol=https
2019-12-17T09:28:11.363917+00:00 app[web.1]: I, [2019-12-17T09:28:11.363795 #4] INFO -- : [3885b893-52a2-4eed-bc9d-d14c153f57e1] Sent mail to [有効なメールアドレス] (376.4ms)
2019-12-17T09:28:11.364042+00:00 app[web.1]: D, [2019-12-17T09:28:11.363974 #4] DEBUG -- : [3885b893-52a2-4eed-bc9d-d14c153f57e1] Date: Tue, 17 Dec 2019 09:28:10 +0000
続いて、パスワード再設定URL通知用メールのヘッダーが返されます。
2019-12-17T09:28:11.364046+00:00 app[web.1]: From: noreply@example.com
2019-12-17T09:28:11.364048+00:00 app[web.1]: To: [有効なメールアドレス]
2019-12-17T09:28:11.364051+00:00 app[web.1]: Message-ID: <5df89faaf1d68_42b033a8e4c6c36478@0a287fc0-3c85-4948-82ec-158df909485c.mail>
2019-12-17T09:28:11.364053+00:00 app[web.1]: Subject: Password reset
2019-12-17T09:28:11.364055+00:00 app[web.1]: Mime-Version: 1.0
2019-12-17T09:28:11.364057+00:00 app[web.1]: Content-Type: multipart/alternative;
2019-12-17T09:28:11.364059+00:00 app[web.1]: boundary="--==_mimepart_5df89faaf0b60_42b033a8e4c6c36371";
2019-12-17T09:28:11.364062+00:00 app[web.1]: charset=UTF-8
2019-12-17T09:28:11.364064+00:00 app[web.1]: Content-Transfer-Encoding: 7bit
以下のログには、テキストメールの本文が返されています。
2019-12-17T09:28:11.364070+00:00 app[web.1]: ----==_mimepart_5df89faaf0b60_42b033a8e4c6c36371
2019-12-17T09:28:11.364072+00:00 app[web.1]: Content-Type: text/plain;
2019-12-17T09:28:11.364074+00:00 app[web.1]: charset=UTF-8
2019-12-17T09:28:11.364077+00:00 app[web.1]: Content-Transfer-Encoding: 7bit
2019-12-17T09:28:11.364078+00:00 app[web.1]:
2019-12-17T09:28:11.364081+00:00 app[web.1]: To reset your password click the link below:
2019-12-17T09:28:11.364082+00:00 app[web.1]:
2019-12-17T09:28:11.364085+00:00 app[web.1]: https://warm-woodland-62915.herokuapp.com/password_resets/itlJPL32OY-XMHORblVHpQ/edit?email=[有効なメールアドレス]
2019-12-17T09:28:11.364087+00:00 app[web.1]:
2019-12-17T09:28:11.364089+00:00 app[web.1]: This will expire in two hours.
2019-12-17T09:28:11.364091+00:00 app[web.1]:
2019-12-17T09:28:11.364093+00:00 app[web.1]: If you did not request your password to be reset, please ignore this email and
2019-12-17T09:28:11.364095+00:00 app[web.1]: your password stay as it is.
2019-12-17T09:28:11.364097+00:00 app[web.1]:
2019-12-17T09:28:11.364099+00:00 app[web.1]:
2019-12-17T09:28:11.364101+00:00 app[web.1]: ----==_mimepart_5df89faaf0b60_42b033a8e4c6c36371
以下のログには、HTMLメールの本文が返されています。
2019-12-17T09:28:11.364103+00:00 app[web.1]: Content-Type: text/html;
2019-12-17T09:28:11.364105+00:00 app[web.1]: charset=UTF-8
2019-12-17T09:28:11.364107+00:00 app[web.1]: Content-Transfer-Encoding: 7bit
2019-12-17T09:28:11.364109+00:00 app[web.1]:
2019-12-17T09:28:11.364110+00:00 app[web.1]: <!DOCTYPE html>
2019-12-17T09:28:11.364112+00:00 app[web.1]: <html>
2019-12-17T09:28:11.364115+00:00 app[web.1]: <head>
2019-12-17T09:28:11.364117+00:00 app[web.1]: <meta http-equiv="Content-Type" content="text/html; charset=utf-8" />
2019-12-17T09:28:11.364119+00:00 app[web.1]: <style>
2019-12-17T09:28:11.364121+00:00 app[web.1]: /* Email styles need to be inline */
2019-12-17T09:28:11.364123+00:00 app[web.1]: </style>
2019-12-17T09:28:11.364125+00:00 app[web.1]: </head>
2019-12-17T09:28:11.364128+00:00 app[web.1]:
2019-12-17T09:28:11.364130+00:00 app[web.1]: <body>
2019-12-17T09:28:11.364132+00:00 app[web.1]: <h1>Password reset</h1>
2019-12-17T09:28:11.364133+00:00 app[web.1]:
2019-12-17T09:28:11.364135+00:00 app[web.1]: <p>To reset your password click the link below:</p>
2019-12-17T09:28:11.364137+00:00 app[web.1]:
2019-12-17T09:28:11.364140+00:00 app[web.1]: https://warm-woodland-62915.herokuapp.com/password_resets/itlJPL32OY-XMHORblVHpQ/edit?email=[有効なメールアドレス]
2019-12-17T09:28:11.364141+00:00 app[web.1]:
2019-12-17T09:28:11.364143+00:00 app[web.1]: <p>This will expire in two hours.</p>
2019-12-17T09:28:11.364145+00:00 app[web.1]:
2019-12-17T09:28:11.364147+00:00 app[web.1]: <p>
2019-12-17T09:28:11.364150+00:00 app[web.1]: If you did not request your password to be reset, please ignore this email and
2019-12-17T09:28:11.364152+00:00 app[web.1]: your password stay as it is.
2019-12-17T09:28:11.364153+00:00 app[web.1]: </p>
2019-12-17T09:28:11.364155+00:00 app[web.1]:
2019-12-17T09:28:11.364157+00:00 app[web.1]: </body>
2019-12-17T09:28:11.364159+00:00 app[web.1]: </html>
2019-12-17T09:28:11.364161+00:00 app[web.1]:
2019-12-17T09:28:11.364164+00:00 app[web.1]: ----==_mimepart_5df89faaf0b60_42b033a8e4c6c36371--
メール本文から、パスワード再設定トークンは以下の文字列であることがわかります。
itlJPL32OY-XMHORblVHpQ
続いてのログにより、PasswordResetsコントローラーのcreateアクションの最後は / へのリダイレクトで完了したことがわかります。
2019-12-17T09:28:11.364629+00:00 app[web.1]: I, [2019-12-17T09:28:11.364565 #4] INFO -- : [3885b893-52a2-4eed-bc9d-d14c153f57e1] Redirected to https://warm-woodland-62915.herokuapp.com/
2019-12-17T09:28:11.364841+00:00 app[web.1]: I, [2019-12-17T09:28:11.364781 #4] INFO -- : [3885b893-52a2-4eed-bc9d-d14c153f57e1] Completed 302 Found in 686ms (ActiveRecord: 6.5ms)
今度は、PasswordResetsコントローラーに対するeditが開始されたところからのログです。「メール本文中に記載されたURLにアクセスがあった」というタイミングですね。
2019-12-17T09:28:40.413354+00:00 heroku[router]: at=info method=GET path="/password_resets/itlJPL32OY-XMHORblVHpQ/edit?email=[有効なメールアドレス]" host=warm-woodland-62915.herokuapp.com request_id=ed1e4c85-a8ad-4e30-90a9-2d581a582d69 fwd="175.177.6.7" dyno=web.1 connect=1ms service=98ms status=200 bytes=3413 protocol=https
2019-12-17T09:28:40.314045+00:00 app[web.1]: I, [2019-12-17T09:28:40.313937 #4] INFO -- : [ed1e4c85-a8ad-4e30-90a9-2d581a582d69] Started GET "/password_resets/itlJPL32OY-XMHORblVHpQ/edit?email=[有効なメールアドレス]" for 175.177.6.7 at 2019-12-17 09:28:40 +0000
2019-12-17T09:28:40.314979+00:00 app[web.1]: I, [2019-12-17T09:28:40.314889 #4] INFO -- : [ed1e4c85-a8ad-4e30-90a9-2d581a582d69] Processing by PasswordResetsController#edit as HTML
2019-12-17T09:28:40.315025+00:00 app[web.1]: I, [2019-12-17T09:28:40.314972 #4] INFO -- : [ed1e4c85-a8ad-4e30-90a9-2d581a582d69] Parameters: {"email"=>"[有効なメールアドレス]", "id"=>"itlJPL32OY-XMHORblVHpQ"}
2019-12-17T09:28:40.319097+00:00 app[web.1]: D, [2019-12-17T09:28:40.319022 #4] DEBUG -- : [ed1e4c85-a8ad-4e30-90a9-2d581a582d69] User Load (1.7ms) SELECT "users".* FROM "users" WHERE "users"."email" = $1 LIMIT $2 [["email", "[有効なメールアドレス]"], ["LIMIT", 1]]
2019-12-17T09:28:40.398272+00:00 app[web.1]: I, [2019-12-17T09:28:40.398149 #4] INFO -- : [ed1e4c85-a8ad-4e30-90a9-2d581a582d69] Rendering password_resets/edit.html.erb within layouts/application
2019-12-17T09:28:40.403019+00:00 app[web.1]: I, [2019-12-17T09:28:40.402925 #4] INFO -- : [ed1e4c85-a8ad-4e30-90a9-2d581a582d69] Rendered shared/_error_messages.html.erb (0.7ms)
2019-12-17T09:28:40.405414+00:00 app[web.1]: I, [2019-12-17T09:28:40.405331 #4] INFO -- : [ed1e4c85-a8ad-4e30-90a9-2d581a582d69] Rendered password_resets/edit.html.erb within layouts/application (7.0ms)
2019-12-17T09:28:40.406458+00:00 app[web.1]: I, [2019-12-17T09:28:40.406378 #4] INFO -- : [ed1e4c85-a8ad-4e30-90a9-2d581a582d69] Rendered layouts/_rails_default.erb (0.7ms)
2019-12-17T09:28:40.406920+00:00 app[web.1]: I, [2019-12-17T09:28:40.406841 #4] INFO -- : [ed1e4c85-a8ad-4e30-90a9-2d581a582d69] Rendered layouts/_shim.html.erb (0.0ms)
2019-12-17T09:28:40.407613+00:00 app[web.1]: I, [2019-12-17T09:28:40.407535 #4] INFO -- : [ed1e4c85-a8ad-4e30-90a9-2d581a582d69] Rendered layouts/_header.html.erb (0.4ms)
2019-12-17T09:28:40.408136+00:00 app[web.1]: I, [2019-12-17T09:28:40.408058 #4] INFO -- : [ed1e4c85-a8ad-4e30-90a9-2d581a582d69] Rendered layouts/_footer.html.erb (0.2ms)
2019-12-17T09:28:40.408613+00:00 app[web.1]: I, [2019-12-17T09:28:40.408534 #4] INFO -- : [ed1e4c85-a8ad-4e30-90a9-2d581a582d69] Completed 200 OK in 93ms (Views: 10.7ms | ActiveRecord: 1.7ms)
ここまでのログは、パスワード再設定画面がWebブラウザに表示されるところまでに対応しています。
続いて、PasswordResetsコントローラーのupdateアクションが開始されました。ユーザーの操作としては、「パスワード再設定画面で、「Submit」ボタンがクリックされたところ」です。
2019-12-17T09:29:12.595676+00:00 app[web.1]: I, [2019-12-17T09:29:12.595538 #4] INFO -- : [8848c122-5082-4846-86ce-2ceb8b852cbe] Started PATCH "/password_resets/itlJPL32OY-XMHORblVHpQ" for 175.177.6.7 at 2019-12-17 09:29:12 +0000
2019-12-17T09:29:12.596922+00:00 app[web.1]: I, [2019-12-17T09:29:12.596829 #4] INFO -- : [8848c122-5082-4846-86ce-2ceb8b852cbe] Processing by PasswordResetsController#update as HTML
2019-12-17T09:29:12.597042+00:00 app[web.1]: I, [2019-12-17T09:29:12.596951 #4] INFO -- : [8848c122-5082-4846-86ce-2ceb8b852cbe] Parameters: {"utf8"=>"✓", "authenticity_token"=>"dg4e+oRJwi5xsE/Jz4Pmq+2UoA2OiDh5+ocmuTpFoVb2ch6TD5uvuvo5TCFFuiuRqS4YY0MqI+vVVxSAq9NcyQ==", "email"=>"[有効なメールアドレス]]", "user"=>{"password"=>"[FILTERED]", "password_confirmation"=>"[FILTERED]"}, "commit"=>"Update password", "id"=>"itlJPL32OY-XMHORblVHpQ"}
2019-12-17T09:29:12.601036+00:00 app[web.1]: D, [2019-12-17T09:29:12.600952 #4] DEBUG -- : [8848c122-5082-4846-86ce-2ceb8b852cbe] User Load (1.6ms) SELECT "users".* FROM "users" WHERE "users"."email" = $1 LIMIT $2 [["email", "[有効なメールアドレス]"], ["LIMIT", 1]]
2019-12-17T09:29:12.677061+00:00 app[web.1]: D, [2019-12-17T09:29:12.676951 #4] DEBUG -- : [8848c122-5082-4846-86ce-2ceb8b852cbe] (1.4ms) BEGIN
2019-12-17T09:29:12.756980+00:00 app[web.1]: D, [2019-12-17T09:29:12.756856 #4] DEBUG -- : [8848c122-5082-4846-86ce-2ceb8b852cbe] User Exists (1.6ms) SELECT 1 AS one FROM "users" WHERE LOWER("users"."email") = LOWER($1) AND ("users"."id" != $2) LIMIT $3 [["email", "[有効なメールアドレス]"], ["id", 104], ["LIMIT", 1]]
2019-12-17T09:29:12.759699+00:00 app[web.1]: D, [2019-12-17T09:29:12.759627 #4] DEBUG -- : [8848c122-5082-4846-86ce-2ceb8b852cbe] SQL (1.4ms) UPDATE "users" SET "password_digest" = $1, "updated_at" = $2 WHERE "users"."id" = $3 [["password_digest", "$2a$10$H0x3ghcOyu0l4DHat9NqLOsJ0.xRYZ.DDKTXvoaO18Ot7E5p/omzq"], ["updated_at", "2019-12-17 09:29:12.757425"], ["id", 104]]
2019-12-17T09:29:12.762463+00:00 app[web.1]: D, [2019-12-17T09:29:12.762374 #4] DEBUG -- : [8848c122-5082-4846-86ce-2ceb8b852cbe] (2.4ms) COMMIT
2019-12-17T09:29:12.763828+00:00 app[web.1]: D, [2019-12-17T09:29:12.763760 #4] DEBUG -- : [8848c122-5082-4846-86ce-2ceb8b852cbe] (1.1ms) BEGIN
2019-12-17T09:29:12.765871+00:00 app[web.1]: D, [2019-12-17T09:29:12.765779 #4] DEBUG -- : [8848c122-5082-4846-86ce-2ceb8b852cbe] SQL (1.3ms) UPDATE "users" SET "reset_digest" = $1, "updated_at" = $2 WHERE "users"."id" = $3 [["reset_digest", nil], ["updated_at", "2019-12-17 09:29:12.763908"], ["id", 104]]
2019-12-17T09:29:12.768224+00:00 app[web.1]: D, [2019-12-17T09:29:12.768124 #4] DEBUG -- : [8848c122-5082-4846-86ce-2ceb8b852cbe] (2.1ms) COMMIT
2019-12-17T09:29:12.768664+00:00 app[web.1]: I, [2019-12-17T09:29:12.768603 #4] INFO -- : [8848c122-5082-4846-86ce-2ceb8b852cbe] Redirected to https://warm-woodland-62915.herokuapp.com/users/104
2019-12-17T09:29:12.768800+00:00 app[web.1]: I, [2019-12-17T09:29:12.768749 #4] INFO -- : [8848c122-5082-4846-86ce-2ceb8b852cbe] Completed 302 Found in 172ms (ActiveRecord: 15.9ms)
パスワードの再設定が正常に完了していますね。最後は当該ユーザーのプロフィールページにリダイレクトされています。