Using Redis and Cm_RedisSession module to store sessions, I'm seeing a 502 Bad Gateway error when a customer is signed in (but not when they are in the customer account section).
The php error was not useful, but the issue seems to be the Redis connection timing out, I added a php-fpm slowfile to trigger after 10s:
[24-Sep-2018 16:06:45] [pool examplecom] pid 1102
script_filename =
/var/www/vhosts/example.com/htdocs/index.php
[0x00007f8cd6402c98] usleep()
/var/www/vhosts/example.com/htdocs/app/code/community/Cm/RedisSession/Model/Session.php:332
[0x00007fff364e5bc0]
read() unknown:0
[0x00007f8cd6402a78] session_start()
/var/www/vhosts/example.com/htdocs/app/code/core/Mage/Core/Model/Session/Abstract/Varien.php:135
[0x00007f8cd64029
30] start()
/var/www/vhosts/example.com/htdocs/app/code/core/Mage/Core/Model/Session/Abstract/Varien.php:229
[0x00007f8cd64027
e0] init()
/var/www/vhosts/example.com/htdocs/app/code/core/Mage/Core/Model/Session/Abstract.php:84
[0x00007f8cd64026e0]
init() /var/www/vhosts/example.com/htdocs/app/code/core/Mage/Core/Model/Session.php:42
[0x00007f8cd64025a8]
__construct()
/var/www/vhosts/example.com/htdocs/app/code/core/Mage/Core/Model/Config.php:1354
[0x00007f8cd6402488]
getModelInstance() /var/www/vhosts/example.com/htdocs/app/Mage.php:463
[0x00007f8cd6402350] getModel()
/var/www/vhosts/example.com/htdocs/app/Mage.php:477
[0x00007f8cd64021f0] getSingleton()
/var/www/vhosts/example.com/htdocs/app/code/core/Mage/Core/Controller/Varien/Action.php:493
[0x00007f8cd64020d0]
preDispatch()
/var/www/vhosts/example.com/htdocs/app/code/core/Mage/Core/Controller/Front/Action.php:69
[0x00007f8cd6401f10]
preDispatch()
/var/www/vhosts/example.com/htdocs/app/code/core/Mage/Core/Controller/Varien/Action.php:407
[0x00007f8cd6401cf8]
dispatch()
/var/www/vhosts/example.com/htdocs/app/code/core/Mage/Core/Controller/Varien/Router/Standard.php:254
[0x00007f8cd6
401aa0] match()
/var/www/vhosts/example.com/htdocs/app/code/local/Elegento/Royal/Controller/Standard.php:82
[0x00007f8cd6401968]
match()
/var/www/vhosts/example.com/htdocs/app/code/core/Mage/Core/Controller/Varien/Front.php:172
[0x00007f8cd6401808]
dispatch() /var/www/vhosts/example.com/htdocs/app/code/core/Mage/Core/Model/App.php:365
[0x00007f8cd6401660] run()
/var/www/vhosts/example.com/htdocs/app/Mage.php:684
[0x00007f8cd6401508] run()
/var/www/vhosts/example.com/htdocs/index.php:96
And then upped the logging for Redis:
2018-09-24T15:06:37+00:00 DEBUG (7): example.com
|1102:
Cm_RedisSession_Model_Session initialized for connection to localhost:6379 after 0.00004
seconds
2018-09-24T15:06:37+00:00 DEBUG (7): example.com
|1102: Connected to
Redis
2018-09-24T15:06:37+00:00 DEBUG (7): example.com
|1102: Attempting to take lock on ID
sess_hudu2cu9falvjeers8rr0vtlk6
2018-09-24T15:06:37+00:00 DEBUG (7): example.com
|1102: Waiting
0.51 seconds for lock on ID sess_hudu2cu9falvjeers8rr0vtlk6 (1 tries, lock pid is , 0.00025 seconds
elapsed)
2018-09-24T15:06:37+00:00 DEBUG (7): example.com
|1102: Waiting 0.50 seconds for lock on
ID sess_hudu2cu9falvjeers8rr0vtlk6 (2 tries, lock pid is , 0.51052 seconds elapsed)
2018-09-24T15:06:38+00:00 DEBUG
(7): example.com
|1102: Waiting 0.50 seconds for lock on ID sess_hudu2cu9falvjeers8rr0vtlk6 (3
tries, lock pid is , 1.01081 seconds elapsed)
2018-09-24T15:06:38+00:00 DEBUG (7):
example.com
|1102: Waiting 0.50 seconds for lock on ID sess_hudu2cu9falvjeers8rr0vtlk6 (4 tries,
lock pid is , 1.51107 seconds elapsed)
2018-09-24T15:06:39+00:00 DEBUG (7): example.com
|1102:
Waiting 0.50 seconds for lock on ID sess_hudu2cu9falvjeers8rr0vtlk6 (5 tries, lock pid is , 2.01136 seconds
elapsed)
2018-09-24T15:06:39+00:00 DEBUG (7): example.com
|1102: Waiting 0.50 seconds for lock on
ID sess_hudu2cu9falvjeers8rr0vtlk6 (6 tries, lock pid is , 2.51163 seconds elapsed)
2018-09-24T15:06:40+00:00 DEBUG
(7): example.com
|1102: Waiting 0.50 seconds for lock on ID sess_hudu2cu9falvjeers8rr0vtlk6 (7
tries, lock pid is , 3.01189 seconds elapsed)
2018-09-24T15:06:40+00:00 DEBUG (7):
example.com
|1102: Waiting 0.50 seconds for lock on ID sess_hudu2cu9falvjeers8rr0vtlk6 (8 tries,
lock pid is , 3.51210 seconds elapsed)
2018-09-24T15:06:41+00:00 DEBUG (7): example.com
|1102:
Waiting 0.50 seconds for lock on ID sess_hudu2cu9falvjeers8rr0vtlk6 (9 tries, lock pid is , 4.01236 seconds
elapsed)
2018-09-24T15:06:41+00:00 DEBUG (7): example.com
|1102: Waiting 0.50 seconds for lock on
ID sess_hudu2cu9falvjeers8rr0vtlk6 (10 tries, lock pid is , 4.51262 seconds elapsed)
2018-09-24T15:06:42+00:00 DEBUG
(7): example.com
|1102: Waiting 0.50 seconds for lock on ID sess_hudu2cu9falvjeers8rr0vtlk6 (11
tries, lock pid is , 5.01288 seconds elapsed)
2018-09-24T15:06:42+00:00 DEBUG (7):
example.com
|1102: Waiting 0.50 seconds for lock on ID sess_hudu2cu9falvjeers8rr0vtlk6 (12 tries,
lock pid is , 5.51309 seconds elapsed)
2018-09-24T15:06:43+00:00 DEBUG (7): example.com
|1102:
Waiting 0.50 seconds for lock on ID sess_hudu2cu9falvjeers8rr0vtlk6 (13 tries, lock pid is , 6.01336 seconds
elapsed)
2018-09-24T15:06:43+00:00 DEBUG (7): example.com
|1102: Waiting 0.50 seconds for lock on
ID sess_hudu2cu9falvjeers8rr0vtlk6 (14 tries, lock pid is , 6.51363 seconds elapsed)
2018-09-24T15:06:44+00:00 DEBUG
(7): example.com
|1102: Waiting 0.50 seconds for lock on ID sess_hudu2cu9falvjeers8rr0vtlk6 (15
tries, lock pid is , 7.01389 seconds elapsed)
2018-09-24T15:06:44+00:00 DEBUG (7):
example.com
|1102: Waiting 0.50 seconds for lock on ID sess_hudu2cu9falvjeers8rr0vtlk6 (16 tries,
lock pid is , 7.51409 seconds elapsed)
2018-09-24T15:06:45+00:00 DEBUG (7): example.com
|1102:
Waiting 0.50 seconds for lock on ID sess_hudu2cu9falvjeers8rr0vtlk6 (17 tries, lock pid is , 8.01441 seconds
elapsed)
2018-09-24T15:06:45+00:00 DEBUG (7): example.com
|1102: Waiting 0.50 seconds for lock on
ID sess_hudu2cu9falvjeers8rr0vtlk6 (18 tries, lock pid is , 8.51470 seconds elapsed)
2018-09-24T15:06:46+00:00 DEBUG
(7): example.com
|1102: Waiting 0.50 seconds for lock on ID sess_hudu2cu9falvjeers8rr0vtlk6 (19
tries, lock pid is , 9.01497 seconds elapsed)
2018-09-24T15:06:46+00:00 DEBUG (7):
example.com
|1102: Checking for zombies after 9.51523 seconds of
waiting...
2018-09-24T15:06:46+00:00 INFO (6): example.com
|1102: Detected zombie process
(example.com
|1134) for sess_hudu2cu9falvjeers8rr0vtlk6 (1 waiting)
/ (217.35.98.181 -
Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.99
Safari/537.36)
2018-09-24T15:06:46+00:00 DEBUG (7): example.com
|1102: Data read for ID
sess_hudu2cu9falvjeers8rr0vtlk6 in 0.00007 seconds
The call stack looks pretty normal, with exception of the Elegento_Royal module, however, all this does is display a maintenance page if enabled, which it is not. I've upped the frontend_break and timeout settings, although it's still timing out after 10s because it's detecting a deadlock holder...
Any thoughts on what I should be looking at next?
