Q&A
エラーが発生するようになったときのアプリケーションのログと、その時のサーバのリソース状況がどうなってるのかが気になります。
実現したいこと
先日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のコンソールを見てみたところ、ロードバランサーへのリクエストがカウントされていないようでした。
何度かアクセスは試みているので、何か手がかりになるかもと思って追記いたしました。
ご連絡ありがとうございます！
サーバーリソースのチェックの仕方がわからないので、取り急ぎログだけお送りいたします。
リソースの方はもうしばらくお待ちください。
ログは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
```
下記返信で回答になっているかわかりませんが。。。
AWSのリソース状況をチェックしましたが、[AWS コスト管理へようこそ
今回は初めてのため、コストと使用状況のデータの準備に少しお時間がかかります。24 時間後にもう一度お試しください。]と表示されてしまいました。
ちなみに本アプリは転職活動の際にポートフォリオとして作成しているもので、個人でやっているものなのでアクセス量という意味では私くらいしかアクセスしないようなものだとは思います。。
回答2件
0
自己解決
今度こそ自己解決いたしました。
ロードバランサーのセキュリティインバウンドで、ソースの指定がマイIPになっていました・・・・。
ロードバランサーを構築しなおしたら自宅のWifiではアクセスできたけど、別の場所ではIPが変わってアクセスできなかったというだけみたいです・・・。
お恥ずかしいです・・ご協力ありがとうございます。
投稿2019/11/01 10:50
総合スコア9
0
自己解決しました。
ロードバランサのリクエストがカウントされていないことから、ロードバランサの再作成を行いました。
お手数おかけしました。
【追記】
未解決を外しました。
2時間ほど問題なくアクセスできたいのですが、再度繋がらなくなってしまいました。
再度ヒント募集中です・・・。すいません・・・。
投稿2019/11/01 02:53
編集2019/11/01 06:53総合スコア9
あなたの回答
tips
プレビュー
