2

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?

-1

This ended up being an issue with a disabled 3rd party XML generation module, which was not only causing issues with Redis, but the latest version of Magento when this site was upgraded to that!

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.