デプロイしたのにアプリがブラウザに表示されない原因はunicorn.rbの設定にあった

やりたいこと

本番環境のブラウザでポートフォリオアプリが表示されるようにしたい。

問題

AWSでデプロイしたのに、ブラウザにアプリが表示されない。
「We're sorry, but something went wrong.」というお決まりのページが出てきてしまう。

エラーログを確認しにいく

確認しにいくエラーログは３つ。
/var/www/pfc-maste(アプリ)/log logディレクトリにある。

[naota@ip-10-0-0-32 log]$ ls
production.log  unicorn.stderr.log  unicorn.stdout.log

catコマンドでログの中身を確認する。

[naota@ip-10-0-0-32 log]$ cat unicorn.stderr.log 

unicorn.stderr.logにはエラーが見つからなかった。
unicorn.stdout.logにもエラーはなかった。

→ unicornは問題なく動いているようだ。

production.logを確認してみる。

[naota@ip-10-0-0-32 log]$ cat production.log 

I, [2020-11-03T04:37:01.136568 #4021]  INFO -- : [8a6d1019-106c-4060-85ba-ba75f1371d48] Completed 500 Internal Server Error in 3ms (ActiveRecord: 0.5ms)
F, [2020-11-03T04:37:01.137067 #4021] FATAL -- : [8a6d1019-106c-4060-85ba-ba75f1371d48]   
F, [2020-11-03T04:37:01.137117 #4021] FATAL -- : [8a6d1019-106c-4060-85ba-ba75f1371d48] NoMethodError (undefined method `id' for nil:NilClass):
F, [2020-11-03T04:37:01.137143 #4021] FATAL -- : [8a6d1019-106c-4060-85ba-ba75f1371d48]   
F, [2020-11-03T04:37:01.137167 #4021] FATAL -- : [8a6d1019-106c-4060-85ba-ba75f1371d48] app/controllers/posts_controller.rb:28:in `index'

エラーが見つかった！

エラーログを読み解く

F, [2020-10-31T17:06:07.715748 #32438] FATAL -- : [2693cb14-dcf4-4f2c-a080-b6d724c839f0] app/controllers/posts_controller.rb:28:in `index'
F, [2020-11-03T04:37:01.137117 #4021] FATAL -- : [8a6d1019-106c-4060-85ba-ba75f1371d48] NoMethodError (undefined method `id' for nil:NilClass):

posts_controller.rbの28行目に、取得しようとしてる何かのidがnil(空っぽ)になっていて取得できない、と言われている。

posts_controller.rbの28行目を確認しに行こう。

def index
  @sampleuser = User.find_by(id: 2)
  @calorie_sum = Post.where(user_id: @sampleuser.id, created_at: Time.zone.now.beginning_of_day..Time.zone.now.end_of_day).sum(:calorie)
end

おそらく@sampleuser.idのidがnilだと言われているのだろう。
なぜかというと、まだusersテーブルに@sampleuser（idが2のユーザー）のデータを入れていないからだ。

user_idが2のuserを作り、さらにpostsテーブルにuser_id=2のユーザーの投稿を保存した。
「これでもう@sample.idがnilになってるよ」と言われなくなるだろう。

SQLの中身を変更したので、MySQLを再起動して、念のためデプロイし直してから、ブラウザを確認してみた。

MySQLを再起動する。

sudo systemctl restart mysqld.service

デプロイをやり直す。

すでに動いているunicornのプロセスをkillしてから

[naota@ip-10-0-0-32 pfc-master]$ RAILS_SERVE_STATIC_FILES=1 unicorn_rails -c config/unicorn.rb -E production -D
[naota@ip-10-0-0-32 pfc-master]$ sudo service nginx restart

さあ、これで解決しただろうと思って確認してみたら、問題が変わってない。。。
なぜだ？

ここからかれこれ6時間くらい、下記のことを一通り試した。

試したこと

・posts_controller#indexのうちグラフ部分を全部コメントアウト。
・メイン画面のグラフ部分のHTMLを全部コメントアウト。
・サイドバーのHTMLを全部コメントアウト。
・charts_controller.rb(グラフのコントローラー)を全部コメントアウト。
・usersテーブルにSequelProでユーザーを追加した時、パスワードが空欄になっていたので手打ちで追加。
・$ rake db:seedでusersテーブルとpostsテーブルにサンプルデータ投入。
・EC2の再起動。
・posts_controller#indexを消去(他の場所に移動させた)。

エラーログを読み解く

その6時間の間、production.logでずっとDEBUGが表示され続けていた。

D, [2020-11-03T06:27:45.917974 #4179] DEBUG -- :    (0.3ms)  SET NAMES utf8,  @@SESSION.sql_mode = CONCAT(CONCAT(@@sql_mode, ',STRICT_ALL_TABLES'), ',NO_AUTO_VALUE_ON_ZERO'),  @@SESSION.sql_auto_is_null = 0, @@SESSION.wait_timeout = 2147483

ずっとこれはエラーで解決すべきものだと認識していた。

このDEBUGを見て考えたこと
・どこかのNULL制約に引っかかってる？
・wait_timeoutとあるから、ページを表示するのに時間がかかりすぎている？データ量が重すぎるのが問題？

DEBUGの意味がわからないので調べた。

STRICT_ALL_TABLES

・すべてのストレージエンジンについて厳密モードを有効にする設定。
・無効なデータ値は拒否される。
・厳密モードは、MySQLがINSERTやUPDATE などのデータ変更で無効な値または欠落した値を処理する方法を制御する。値はいくつかの理由で無効になることがある。たとえば、カラムに対して正しくないデータ型を持っていたり、範囲外であったりすることがある。
・値の欠落が発生するのは、挿入される新しい行の非NULLカラムに値が含まれておらず、そのカラムに明示的なDEFAULT句が定義されていない場合です。(NULLカラムの場合、値が欠落しているときは NULLが挿入される。)
・厳密モードはMySQL5.7でデフォルトで適用されているSQLモード。

MySQLリファレンス 厳密モード

→デフォルトの設定だから、特に何か問題を指摘されてるわけではなさそうだ。

ストレージエンジンとは？
一言でいうと、MySQLなどのRDMBSの心臓部のこと。

通常、RDMBS(リレーショナルデータベース)はいくつかの構成要素によって成り立っており、SQL文を受け取って結果を返すデータベースエンジン部、アプリケーションとデータベースエンジンを結びつけるクライアントモジュールや様々なツール群などから成り立っています。

その中でもサーバ側にて動作するデータベースエンジンはRDBMSの心臓部であり、非常に多くの仕事を担っています。MySQLでは「MySQLサーバ」もしくは「MySQLデーモン」と呼ばれている部分に相当します。

MySQLストレージエンジンの概要(NTTデータ藤塚勤也さん著)

NO_AUTO_VALUE_ON_ZEROとは？

・SQLモードの1つ。SQLモードとは、MySQLでサポートされるSQL構文、および実行されるデータ妥当性チェックの種類を定義するもの(公式ルールみたいなものか)。これにより、MySQLをさまざまな環境で使用したり、MySQLをほかのデータベースサーバーと一緒に使用したりすることがさらに容易になる（MySQLリファレンス SQLモード）。
・NO_AUTO_VALUE_ON_ZERO はAUTO_INCREMENTカラムの処理に影響します。通常は、NULLまたは 0 をカラムに挿入することによって、カラムの次のシーケンス番号を生成する。NO_AUTO_VALUE_ON_ZERO は 0 のこの動作を抑制するため、NULLのみが次のシーケンス番号を生成する。
・このモードは、テーブルの AUTO_INCREMENT カラムに 0 が格納されている場合に便利なことがあります。(ただし、0 を格納することは、推奨される方法ではありません。)たとえば、mysqldump でテーブルをダンプして、テーブルをリロードする場合、MySQL は通常、0 という値を検出すると、新たなシーケンス番号を生成するため、その結果、ダンプされたものとは異なる内容を持つテーブルになります。ダンプファイルをリロードする前に NO_AUTO_VALUE_ON_ZERO を有効にすると、この問題が解決されます。この問題を防ぐために、mysqldump には現在、NO_AUTO_VALUE_ON_ZERO を有効にするステートメントがその出力に自動的に含まれるようになりました。

シーケンス番号とは？

シーケンス番号とは、TCPで送信されるパケットに付けられる通し番号。受信側ではシーケンス番号を参照することによりパケットの正しい順番や通信途上でのパケットの欠落を知ることができる。
It用語辞典 e-Wards シーケンス番号

mysqldumpとは？

・dumpとはバックアップのこと。バックアップとは、データを別のところに保管しておくこと。何かアクシデントがあったときにバックアップしたデータから復元する。復元する作業のことをリストアという。
・データベースは常に稼働し続けていることが求められる場合もある。そのような場合には、仮にアクシデントでデータベースが1つ使えなくなったとしても、予備のデータベースを動かしながら、元のデータベースを全速力で復旧していく。
・MySQLのdumpには「mysqldump」という専用のツールを使う。mysqldumpはMySQLにログインせずに通常のコマンドラインで使用する。
Samrai Blog【MySQL入門】データベースをdumpする！不測の事態に備えよう

こうして原因がわかった

production.logからposts_controller#indexの@sample.idがnilになっているところさえ、一旦コメントアウトすれば、それで簡単に解決すると思ったら、一向に解決せず泥沼にハマってしまった。

どうしようか悩んだ挙句、久しぶりにテックキャンプのカリキュラムのデプロイ部分のページを見直してみた。

そこでついに発見した！

エラー原因は、config/unicorn.rbのポート番号の設定にあった。

今回のエラー原因はこれだった

Nginxを使う場合は、ネットワーク通信の設定を、ポート番号ではなくunicornのソケットファイルで行うべきだった。

config/unicorn.rb

#before もともとはポート番号3000で設定していた
#listen 3000

#after Nginxを使う場合こちらの設定になる
listen "#{app_path}/tmp/sockets/unicorn.sock"

ポート番号とは？

ポートとは、ネットワークでデータを通信するための扉のようなもの。ポート番号はその扉の番号。
・プログラムの種類によって、使うポート（扉）が違う。例えば、メールを送るにはこの扉、メールを受け取るにはこの扉、Webページを見てもらうのはこの扉、などと決まっている。
・IPアドレスを建物の住所に例えるなら、ポート番号は「部屋の番号は何号室か？」という例えになる。コンピュータネットワークにおいて、プロトコル、IPアドレス、ポート番号はまとめると、「どのような方法」で「どこ」の「何号室」に通信をとるのか？という形にいいかえることが出来る。

エンジニアの入り口 【3分で把握】ポート番号とは？と代表的なポート番号まとめ

→ Nginxを使う場合はポート番号ではなく、unicorn.sockというunicornのソケットファイルを参照する設定にしなければならない。
→ ということは、unicorn.sockにはネットワーク通信の設定に関する情報が記述されていると予想される。

ソケットファイルとは？

・ソケットは、TCP / IPソケットに似た特殊なファイルタイプであり、ファイルシステムのアクセス制御によって保護されたプロセス間ネットワークを提供します。
・UNIXドメインソケットは、TCP / IPソケットに似た双方向パイプです。サーバーはクライアントからの接続をリッスンして受け入れ、新しく受け入れられた接続でクライアントと通信できます。**UNIXドメインソケットの特別な点は、IPアドレスとポート番号ではなく、アドレスとしてファイル名を持っていることです。**これにより、ネットワークについて何も知らない他のアプリケーションに、ファイルを開いて読み取りまたは書き込みを指示することができ、データはディスクではなくサーバーに送信されます。

QA STACK ソケットファイルとは

1日かけてやっとブラウザでアプリが表示されるようになりました！

今回の振り返り

今回はスクールのカリキュラムがあったからいいけど、実務に入ったら当然カリキュラムなんてないので、今回のようなことがあってはまずい。

今回の経験を次に生かすために、何が問題で、どうすればよかったか考えた。

・logに書かれたことだけにとらわれすぎていた。
・logに書かれていなくても、デプロイでエラーが生じたのだから、デプロイのために行った一通りの設定を全て確認しにいけばよかった。

→ まずはログをしっかり読むことが大事だが、ログを読んでそこから考えられることを一通りやっても解決しなければ、それまでに設定したファイルを一通り確認しに行こう。