質問をすることでしか得られない、回答やアドバイスがある。

15分調べてもわからないことは、質問しよう!

ただいまの
回答率

87.34%

AWSでデプロイしたRailsアプリケーションに突然アクセスできなくなってしまった

解決済

回答 2

投稿 編集

  • 評価
  • クリップ 1
  • VIEW 1,570

score 9

実現したいこと

先日AWSでデプロイしたアプリケーションに、突然アクセスできなくなってしまいました。
昨日(19/10/31)の昼13時頃にはアクセスできていた記憶があるのですが、夜21時頃確認してみるとアクセスができませんでした。
読み込みが長く、しばらく待つと「このサイトにアクセスできません URLからの応答時間が長すぎます」と表示されます

前提

先日までは下記設定をした状態で、本番環境のアプリケーションにアクセスできていたことを確認しています。
・サーバーはEC2を使用
・お名前.comで独自ドメインを取得
・Route53を使って独自ドメインのレコードセットを作成(Aタイプ、NSタイプ、SOAタイプ)
・ELBをエンドポイントとして常時SSL化
・Certificate Managerでドメインの検証状態が成功している
・MySQL、nginx、unicornを使用しCapistranoによる自動デプロイ

この後、rspecを使ったテストコードをmasterにマージしたくらいでデプロイ周りに関係する設定は変更していません。

現在の状況

前提を踏まえて、AWSのEC2コンソールで下記内容は確認しました。
・EC2インスタンスランニング状態(ポート:HTTP 80を開き、ソースはロードバランサのセキュリティグループを指定)
・ロードバランサのターゲットグループのステータスはHealty(ポート:HTTP 80を設定)
・ロードバランサのDNS名にはAレコードが設定されている
・ロードバランサのリスナー:HTTPS 443 (SSL認証書も紐づいている)
・コンソールからec2-userにログイン可能
・本番環境内のproduction.logにはFatalやErrorの記述なし
・EC2インスタンスのシステムログの取得 後述します。

また、下記を試しても改善しませんでした。
・EC2インスタンスの再起動、MySQL、nginxの再起動、Capistranoによる自動デプロイは問題なく通る

発生している問題・エラーメッセージ

アプリケーションにアクセスすると、下記画面になります。
イメージ説明

EC2インスタンスのシステムログ

参考までにEC2インスタンスのシステムログを貼っておきます。文字数制限があるので、関係がありそうなところから貼っています。
私自身ログ内容の理解がしきれていないです・・・申し訳ありません。

とりあえずエラーの文字は内容に見えるけど、最後login:で止まってるのが少し気になっています。

devel@redhat.com
[    1.557028] udevd[853]: starting version 173
[    1.626261] SCSI subsystem initialized
[    1.660592] Invalid max_queues (4), will use default max: 1.
[    1.711940] scsi host0: ata_piix
[    1.721724] blkfront: xvda: barrier or flush: disabled; persistent grants: disabled; indirect descriptors: enabled;
[    1.750609]  xvda: xvda1
[    1.757511] scsi host1: ata_piix
[    1.760443] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc100 irq 14
[    1.765634] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc108 irq 15
[    1.952088] tsc: Refined TSC clocksource calibration: 2399.999 MHz
[    1.956839] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2298364cab5, max_idle_ns: 440795214892 ns
growroot: NOCHANGE: disk=/dev/xvda partition=1: size=16773086, it cannot be grown
[    2.012386] EXT4-fs (xvda1): mounted filesystem with ordered data mode. Opts: (null)
[    2.022769] dracut: Remounting /dev/disk/by-label/\x2f with -o noatime,ro
[    2.031186] EXT4-fs (xvda1): mounted filesystem with ordered data mode. Opts: (null)
[    2.039807] dracut: Mounted root filesystem /dev/xvda1
[    2.078573] dracut: Switching root
[    2.129598] random: init: uninitialized urandom read (12 bytes read)
image_name="amzn-ami-hvm"
image_version="2018.03"
image_arch="x86_64"
image_file="INCOMPLETE-amzn-ami-hvm-2018.03.0.20190826-x86_64.ext4.gpt"
image_stamp="1b4e-90f9"
image_date="20190826180617"
recipe_name="amzn ami"
recipe_id="cb0f69d0-ddda-5202-d9f2-9fcb-4fc4-a2ab-af42d9da"
        Welcome to Amazon Linux AMI
Starting udev: [    2.280777] udevd[1569]: starting version 173
[    2.349217] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input3
[    2.383893] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input4
[    2.434995] ACPI: Power Button [PWRF]
[    2.438498] input: Sleep Button as /devices/LNXSYSTM:00/LNXSLPBN:00/input/input5
[    2.494418] ACPI: Sleep Button [SLPF]
[    2.548291] mousedev: PS/2 mouse device common for all mice
[  OK  ]

Setting hostname localhost.localdomain:  [  OK  ]

Setting up Logical Volume Management: [    3.574263] random: lvm: uninitialized urandom read (4 bytes read)
  WARNING: Failed to connect to lvmetad. Falling back to device scanning.
[  OK  ]

Checking filesystems
Checking all file systems.
[/sbin/fsck.ext4 (1) -- /] fsck.ext4 -a /dev/xvda1 
/: clean, 111146/524288 files, 803872/2096635 blocks
[  OK  ]

Remounting root filesystem in read-write mode:  [    3.632428] EXT4-fs (xvda1): re-mounted. Opts: (null)
[  OK  ]

Mounting local filesystems:  [  OK  ]

Enabling local filesystem quotas:  [  OK  ]

[    3.668556] random: dd: uninitialized urandom read (4096 bytes read)
Enabling /etc/fstab swaps:  [  OK  ]

Entering non-interactive startup
Starting LVM metadata daemon: [  OK  ]

Starting LVM poll daemon: [  OK  ]

[    3.808344] random: vgs: uninitialized urandom read (4 bytes read)
[    3.900594] NET: Registered protocol family 10
[    3.909605] Segment Routing with IPv6
Bringing up loopback interface:  [  OK  ]

Bringing up interface eth0:  
Determining IP information for eth0... done.

Determining IPv6 information for eth0... done.
[  OK  ]

Starting auditd: [  OK  ]

Starting system logger: [  OK  ]

Starting irqbalance: [  OK  ]

Starting rngd: [    5.592846] urandom_read: 1 callbacks suppressed
[    5.592847] random: rngd: uninitialized urandom read (16 bytes read)
Unable to open file: /dev/hwrng
[  OK  ]

[    5.631778] random: crng init done
Starting rpcbind: [  OK  ]

Starting NFS statd: [  OK  ]

Starting system message bus: [  OK  ]

Mounting filesystems:  [  OK  ]

Starting acpi daemon: [  OK  ]

Retrigger failed udev events--type=failed is deprecated and will be removed from a future udev release.
[  OK  ]

Starting cloud-init: Cloud-init v. 0.7.6 running 'init-local' at Thu, 31 Oct 2019 14:19:25 +0000. Up 6.26 seconds.
Starting cloud-init: Cloud-init v. 0.7.6 running 'init' at Thu, 31 Oct 2019 14:19:25 +0000. Up 6.46 seconds.
ci-info: ++++++++++++++++++++++++Net device info++++++++++++++++++++++++
ci-info:  Device   Up      Address          Mask          Hw-Address    
ci-info:    lo    True    127.0.0.1      255.0.0.0            .         
ci-info:   eth0   True  172.31.43.121  255.255.240.0  06:0e:49:08:e9:b2 
ci-info: +++++++++++++++++++++++++++++++Route info+++++++++++++++++++++++++++++++
ci-info:  Route    Destination      Gateway        Genmask      Interface  Flags 
ci-info:    0        0.0.0.0      172.31.32.1      0.0.0.0         eth0      UG  
ci-info:    1    169.254.169.254    0.0.0.0    255.255.255.255     eth0      UH  
ci-info:    2      172.31.32.0      0.0.0.0     255.255.240.0      eth0      U   
Starting cloud-init: Cloud-init v. 0.7.6 running 'modules:config' at Thu, 31 Oct 2019 14:19:26 +0000. Up 7.15 seconds.
Starting hibinit-agent: Instance Launch has not enabled Hibernation Configured Flag. hibinit-agent exiting!!
[  OK  ]
Restarting acpid.. Stopping acpi daemon: [  OK  ]

Starting acpi daemon: [  OK  ]

Starting sshd: [  OK  ]

Starting ntpd: [  OK  ]

Starting sendmail: [  OK  ]

Starting sm-client: [  OK  ]

Starting crond: [  OK  ]

Starting atd: [  OK  ]

Starting cloud-init: Cloud-init v. 0.7.6 running 'modules:final' at Thu, 31 Oct 2019 14:19:26 +0000. Up 7.84 seconds.
Cloud-init v. 0.7.6 finished at Thu, 31 Oct 2019 14:19:26 +0000. Datasource DataSourceEc2.  Up 7.92 seconds


Amazon Linux AMI release 2018.03
Kernel 4.14.146-93.123.amzn1.x86_64 on an x86_64

ip-172-31-43-121 login: 

私のわかる範囲のところは全て正常に動いているように見えて、特にエラーもなさそうに見えます。
何か原因に近づく手がかりがありましたらご教示頂けますと幸いです。

追記

今EC2のコンソールを見てみたところ、ロードバランサーへのリクエストがカウントされていないようでした。
何度かアクセスは試みているので、何か手がかりになるかもと思って追記いたしました。

  • 気になる質問をクリップする

    クリップした質問は、後からいつでもマイページで確認できます。

    またクリップした質問に回答があった際、通知やメールを受け取ることができます。

    クリップを取り消します

  • 良い質問の評価を上げる

    以下のような質問は評価を上げましょう

    • 質問内容が明確
    • 自分も答えを知りたい
    • 質問者以外のユーザにも役立つ

    評価が高い質問は、TOPページの「注目」タブのフィードに表示されやすくなります。

    質問の評価を上げたことを取り消します

  • 評価を下げられる数の上限に達しました

    評価を下げることができません

    • 1日5回まで評価を下げられます
    • 1日に1ユーザに対して2回まで評価を下げられます

    質問の評価を下げる

    teratailでは下記のような質問を「具体的に困っていることがない質問」、「サイトポリシーに違反する質問」と定義し、推奨していません。

    • プログラミングに関係のない質問
    • やってほしいことだけを記載した丸投げの質問
    • 問題・課題が含まれていない質問
    • 意図的に内容が抹消された質問
    • 過去に投稿した質問と同じ内容の質問
    • 広告と受け取られるような投稿

    評価が下がると、TOPページの「アクティブ」「注目」タブのフィードに表示されにくくなります。

    質問の評価を下げたことを取り消します

    この機能は開放されていません

    評価を下げる条件を満たしてません

    評価を下げる理由を選択してください

    詳細な説明はこちら

    上記に当てはまらず、質問内容が明確になっていない質問には「情報の追加・修正依頼」機能からコメントをしてください。

    質問の評価を下げる機能の利用条件

    この機能を利用するためには、以下の事項を行う必要があります。

質問への追記・修正、ベストアンサー選択の依頼

  • yu_1985

    2019/11/01 16:15

    エラーが発生するようになったときのアプリケーションのログと、その時のサーバのリソース状況がどうなってるのかが気になります。

    キャンセル

  • AK4747471

    2019/11/01 17:01

    ご連絡ありがとうございます!
    サーバーリソースのチェックの仕方がわからないので、取り急ぎログだけお送りいたします。
    リソースの方はもうしばらくお待ちください。

    ログはAWSサーバーのEC2userとしてログインし、currentフォルダ内のlogフォルダから取り出したものです。

    見た感じunicornで何かエラーが起きてる?かもしれないです。

    current/production.log(かなり長いので最新の分だけです)
    ```
    I, [2019-11-01T03:06:37.679890 #10278] INFO -- : [13685089-7d2e-4d1b-b45c-00600ad2a24a] Started GET "/" for 124.37.165.248 at 2019-11-01 03:06:37 +0000
    I, [2019-11-01T03:06:37.680545 #10278] INFO -- : [13685089-7d2e-4d1b-b45c-00600ad2a24a] Processing by GearsController#index as HTML
    I, [2019-11-01T03:06:37.681676 #10278] INFO -- : [13685089-7d2e-4d1b-b45c-00600ad2a24a] Rendering gears/index.html.haml within layouts/application
    I, [2019-11-01T03:06:37.682884 #10278] INFO -- : [13685089-7d2e-4d1b-b45c-00600ad2a24a] Rendered shared/_header.html.haml (1.0ms)
    D, [2019-11-01T03:06:37.683608 #10278] DEBUG -- : [13685089-7d2e-4d1b-b45c-00600ad2a24a] ESC[1mESC[36mGear Load (0.3ms)ESC[0m ESC[1mESC[34mSELECT `gears`.* FROM `gears` LIMIT 12 OFFSET 0ESC[0m
    D, [2019-11-01T03:06:37.685089 #10278] DEBUG -- : [13685089-7d2e-4d1b-b45c-00600ad2a24a] ESC[1mESC[35m (0.2ms)ESC[0m ESC[1mESC[34mSELECT COUNT(*) FROM `reviews` WHERE `reviews`.`gear_id` = 1ESC[0m
    D, [2019-11-01T03:06:37.685854 #10278] DEBUG -- : [13685089-7d2e-4d1b-b45c-00600ad2a24a] ESC[1mESC[35m (0.2ms)ESC[0m ESC[1mESC[34mSELECT COUNT(*) FROM `reviews` WHERE `reviews`.`gear_id` = 2ESC[0m
    D, [2019-11-01T03:06:37.686706 #10278] DEBUG -- : [13685089-7d2e-4d1b-b45c-00600ad2a24a] ESC[1mESC[35m (0.2ms)ESC[0m ESC[1mESC[34mSELECT COUNT(*) FROM `reviews` WHERE `reviews`.`gear_id` = 3ESC[0m
    D, [2019-11-01T03:06:37.687508 #10278] DEBUG -- : [13685089-7d2e-4d1b-b45c-00600ad2a24a] ESC[1mESC[35m (0.2ms)ESC[0m ESC[1mESC[34mSELECT COUNT(*) FROM `reviews` WHERE `reviews`.`gear_id` = 4ESC[0m
    D, [2019-11-01T03:06:37.688311 #10278] DEBUG -- : [13685089-7d2e-4d1b-b45c-00600ad2a24a] ESC[1mESC[35m (0.2ms)ESC[0m ESC[1mESC[34mSELECT COUNT(*) FROM `reviews` WHERE `reviews`.`gear_id` = 5ESC[0m
    D, [2019-11-01T03:06:37.689097 #10278] DEBUG -- : [13685089-7d2e-4d1b-b45c-00600ad2a24a] ESC[1mESC[35m (0.2ms)ESC[0m ESC[1mESC[34mSELECT COUNT(*) FROM `reviews` WHERE `reviews`.`gear_id` = 6ESC[0m
    D, [2019-11-01T03:06:37.689874 #10278] DEBUG -- : [13685089-7d2e-4d1b-b45c-00600ad2a24a] ESC[1mESC[35m (0.2ms)ESC[0m ESC[1mESC[34mSELECT COUNT(*) FROM `reviews` WHERE `reviews`.`gear_id` = 7ESC[0m
    D, [2019-11-01T03:06:37.690778 #10278] DEBUG -- : [13685089-7d2e-4d1b-b45c-00600ad2a24a] ESC[1mESC[35m (0.2ms)ESC[0m ESC[1mESC[34mSELECT COUNT(*) FROM `reviews` WHERE `reviews`.`gear_id` = 8ESC[0m
    D, [2019-11-01T03:06:37.691659 #10278] DEBUG -- : [13685089-7d2e-4d1b-b45c-00600ad2a24a] ESC[1mESC[35m (0.2ms)ESC[0m ESC[1mESC[34mSELECT COUNT(*) FROM `reviews` WHERE `reviews`.`gear_id` = 9ESC[0m
    D, [2019-11-01T03:06:37.692446 #10278] DEBUG -- : [13685089-7d2e-4d1b-b45c-00600ad2a24a] ESC[1mESC[35m (0.2ms)ESC[0m ESC[1mESC[34mSELECT COUNT(*) FROM `reviews` WHERE `reviews`.`gear_id` = 10ESC[0m
    D, [2019-11-01T03:06:37.693256 #10278] DEBUG -- : [13685089-7d2e-4d1b-b45c-00600ad2a24a] ESC[1mESC[35m (0.2ms)ESC[0m ESC[1mESC[34mSELECT COUNT(*) FROM `reviews` WHERE `reviews`.`gear_id` = 11ESC[0m
    D, [2019-11-01T03:06:37.694091 #10278] DEBUG -- : [13685089-7d2e-4d1b-b45c-00600ad2a24a] ESC[1mESC[35m (0.2ms)ESC[0m ESC[1mESC[34mSELECT COUNT(*) FROM `reviews` WHERE `reviews`.`gear_id` = 12ESC[0m
    I, [2019-11-01T03:06:37.694214 #10278] INFO -- : [13685089-7d2e-4d1b-b45c-00600ad2a24a] Rendered collection of gears/_gear.html.haml [12 times] (10.1ms)
    D, [2019-11-01T03:06:37.694708 #10278] DEBUG -- : [13685089-7d2e-4d1b-b45c-00600ad2a24a] ESC[1mESC[35m (0.2ms)ESC[0m ESC[1mESC[34mSELECT COUNT(*) FROM `gears`ESC[0m
    I, [2019-11-01T03:06:37.696802 #10278] INFO -- : [13685089-7d2e-4d1b-b45c-00600ad2a24a] Rendered gears/index.html.haml within layouts/application (15.1ms)
    I, [2019-11-01T03:06:37.697575 #10278] INFO -- : [13685089-7d2e-4d1b-b45c-00600ad2a24a] Completed 200 OK in 17ms (Views: 13.4ms | ActiveRecord: 2.7ms)
    (END)
    ```

    unicorn.stdout.log
    ```
    (END)
    ```

    unicorn.stderr.log
    ```
    I, [2019-11-01T03:02:16.291931 #14396] INFO -- : executing ["/var/www/my_new_gear/shared/bundle/ruby/2.5.0/bin/unicorn", "-c", "/var/www/my_new_gear/current/config/unicorn.rb", "-E", "deployment", "-D", {11=>#<Kgio::UNIXServer:fd 11>}] (in /var/www/my_new_gear/releases/20191101030201)
    I, [2019-11-01T03:02:16.292041 #14396] INFO -- : forked child re-executing...
    /home/ec2-user/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bundler-2.0.2/lib/bundler/definition.rb:32:in `build': /var/www/my_new_gear/releases/20191031142348/Gemfile not found (Bundler::GemfileNotFound)
    from /home/ec2-user/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bundler-2.0.2/lib/bundler.rb:135:in `definition'
    from /home/ec2-user/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bundler-2.0.2/lib/bundler.rb:101:in `setup'
    from /home/ec2-user/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bundler-2.0.2/lib/bundler/setup.rb:20:in `<top (required)>'
    from /home/ec2-user/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/core_ext/kernel_require.rb:59:in `require'
    from /home/ec2-user/.rbenv/versions/2.5.1/lib/ruby/2.5.0/rubygems/core_ext/kernel_require.rb:59:in `require'
    E, [2019-11-01T03:02:16.394934 #10199] ERROR -- : reaped #<Process::Status: pid 14396 exit 1> exec()-ed
    124.37.165.248, 172.31.28.168 - - [01/Nov/2019:03:02:24 +0000] "GET / HTTP/1.0" 200 - 0.0205
    124.37.165.248, 172.31.28.168 - - [01/Nov/2019:03:03:16 +0000] "GET / HTTP/1.0" 200 - 0.0199
    124.37.165.248, 172.31.28.168 - - [01/Nov/2019:03:03:17 +0000] "DELETE /users/sign_out HTTP/1.0" 302 - 0.0103
    124.37.165.248, 172.31.28.168 - - [01/Nov/2019:03:03:18 +0000] "GET / HTTP/1.0" 200 - 0.0192
    124.37.165.248, 172.31.28.168 - - [01/Nov/2019:03:06:37 +0000] "GET / HTTP/1.0" 200 - 0.0189
    ```

    キャンセル

  • AK4747471

    2019/11/01 18:35

    下記返信で回答になっているかわかりませんが。。。
    AWSのリソース状況をチェックしましたが、[AWS コスト管理へようこそ
    今回は初めてのため、コストと使用状況のデータの準備に少しお時間がかかります。24 時間後にもう一度お試しください。]と表示されてしまいました。

    ちなみに本アプリは転職活動の際にポートフォリオとして作成しているもので、個人でやっているものなのでアクセス量という意味では私くらいしかアクセスしないようなものだとは思います。。

    キャンセル

回答 2

check解決した方法

+1

今度こそ自己解決いたしました。
ロードバランサーのセキュリティインバウンドで、ソースの指定がマイIPになっていました・・・・。

ロードバランサーを構築しなおしたら自宅のWifiではアクセスできたけど、別の場所ではIPが変わってアクセスできなかったというだけみたいです・・・。
お恥ずかしいです・・ご協力ありがとうございます。

投稿

  • 回答の評価を上げる

    以下のような回答は評価を上げましょう

    • 正しい回答
    • わかりやすい回答
    • ためになる回答

    評価が高い回答ほどページの上位に表示されます。

  • 回答の評価を下げる

    下記のような回答は推奨されていません。

    • 間違っている回答
    • 質問の回答になっていない投稿
    • スパムや攻撃的な表現を用いた投稿

    評価を下げる際はその理由を明確に伝え、適切な回答に修正してもらいましょう。

0

自己解決しました。

ロードバランサのリクエストがカウントされていないことから、ロードバランサの再作成を行いました。
お手数おかけしました。

【追記】
未解決を外しました。
2時間ほど問題なくアクセスできたいのですが、再度繋がらなくなってしまいました。
再度ヒント募集中です・・・。すいません・・・。

投稿

編集

  • 回答の評価を上げる

    以下のような回答は評価を上げましょう

    • 正しい回答
    • わかりやすい回答
    • ためになる回答

    評価が高い回答ほどページの上位に表示されます。

  • 回答の評価を下げる

    下記のような回答は推奨されていません。

    • 間違っている回答
    • 質問の回答になっていない投稿
    • スパムや攻撃的な表現を用いた投稿

    評価を下げる際はその理由を明確に伝え、適切な回答に修正してもらいましょう。

15分調べてもわからないことは、teratailで質問しよう!

  • ただいまの回答率 87.34%
  • 質問をまとめることで、思考を整理して素早く解決
  • テンプレート機能で、簡単に質問をまとめられる

同じタグがついた質問を見る