magento2: Redis session concurrency error not correctly handled (intermittent "Area Code Is Not Set" report)

Preconditions

1. Magento 2.1.15 (although I believe this will affect 2.2)
2. php 7.0
3. Use redis for sessions

Steps to reproduce

1. Trigger a redis ConcurrentConnectionsExceededException when loading a web page, instructions for emulating this error are included in the section titled “To emulate locally”

Expected result

1. A redis session error is reported, clearly highlighting the error.

Actual result

1. Area code is not set report is generated. This error is seemingly unrelated making the actual issue hard to diagnose and fix.

Notes and explanation

I’ve spent the last few days debugging a randomly occurring report page.

a:4:{i:0;s:20:"Area code is not set";i:1;s:5126:"#0 /Users/lukerodgers/src/magento2/vendor/magento/module-customer/Model/Plugin/CustomerNotification.php(66): Magento\Framework\App\State->getAreaCode()
#1 /Users/lukerodgers/src/magento2/vendor/magento/framework/Interception/Interceptor.php(123): Magento\Customer\Model\Plugin\CustomerNotification->beforeDispatch(Object(Magento\Cms\Controller\Index\Index\Interceptor), Object(Magento\Framework\App\Request\Http))
#2 /Users/lukerodgers/src/magento2/var/generation/Magento/Cms/Controller/Index/Index/Interceptor.php(39): Magento\Cms\Controller\Index\Index\Interceptor->___callPlugins('dispatch', Array, Array)
#3 /Users/lukerodgers/src/magento2/vendor/magento/framework/App/FrontController.php(55): Magento\Cms\Controller\Index\Index\Interceptor->dispatch(Object(Magento\Framework\App\Request\Http))
#4 /Users/lukerodgers/src/magento2/vendor/magento/framework/Interception/Interceptor.php(74): Magento\Framework\App\FrontController->dispatch(Object(Magento\Framework\App\Request\Http))
#5 /Users/lukerodgers/src/magento2/vendor/magento/framework/Interception/Chain/Chain.php(70): Magento\Framework\App\FrontController\Interceptor->___callParent('dispatch', Array)
#6 /Users/lukerodgers/src/magento2/vendor/magento/framework/Interception/Chain/Chain.php(63): Magento\Framework\Interception\Chain\Chain->invokeNext('Magento\\Framewo...', 'dispatch', Object(Magento\Framework\App\FrontController\Interceptor), Array, 'requestPreproce...')
#7 /Users/lukerodgers/src/magento2/vendor/magento/module-store/App/FrontController/Plugin/RequestPreprocessor.php(94): Magento\Framework\Interception\Chain\Chain->Magento\Framework\Interception\Chain\{closure}(Object(Magento\Framework\App\Request\Http))
#8 /Users/lukerodgers/src/magento2/vendor/magento/framework/Interception/Chain/Chain.php(67): Magento\Store\App\FrontController\Plugin\RequestPreprocessor->aroundDispatch(Object(Magento\Framework\App\FrontController\Interceptor), Object(Closure), Object(Magento\Framework\App\Request\Http))
#9 /Users/lukerodgers/src/magento2/vendor/magento/framework/Interception/Chain/Chain.php(63): Magento\Framework\Interception\Chain\Chain->invokeNext('Magento\\Framewo...', 'dispatch', Object(Magento\Framework\App\FrontController\Interceptor), Array, 'install')
#10 /Users/lukerodgers/src/magento2/vendor/magento/framework/Module/Plugin/DbStatusValidator.php(69): Magento\Framework\Interception\Chain\Chain->Magento\Framework\Interception\Chain\{closure}(Object(Magento\Framework\App\Request\Http))
#11 /Users/lukerodgers/src/magento2/vendor/magento/framework/Interception/Chain/Chain.php(67): Magento\Framework\Module\Plugin\DbStatusValidator->aroundDispatch(Object(Magento\Framework\App\FrontController\Interceptor), Object(Closure), Object(Magento\Framework\App\Request\Http))
#12 /Users/lukerodgers/src/magento2/vendor/magento/framework/Interception/Chain/Chain.php(63): Magento\Framework\Interception\Chain\Chain->invokeNext('Magento\\Framewo...', 'dispatch', Object(Magento\Framework\App\FrontController\Interceptor), Array, 'front-controlle...')
#13 /Users/lukerodgers/src/magento2/vendor/magento/module-page-cache/Model/App/FrontController/VarnishPlugin.php(55): Magento\Framework\Interception\Chain\Chain->Magento\Framework\Interception\Chain\{closure}(Object(Magento\Framework\App\Request\Http))
#14 /Users/lukerodgers/src/magento2/vendor/magento/framework/Interception/Chain/Chain.php(67): Magento\PageCache\Model\App\FrontController\VarnishPlugin->aroundDispatch(Object(Magento\Framework\App\FrontController\Interceptor), Object(Closure), Object(Magento\Framework\App\Request\Http))
#15 /Users/lukerodgers/src/magento2/vendor/magento/framework/Interception/Interceptor.php(138): Magento\Framework\Interception\Chain\Chain->invokeNext('Magento\\Framewo...', 'dispatch', Object(Magento\Framework\App\FrontController\Interceptor), Array, 'front-controlle...')
#16 /Users/lukerodgers/src/magento2/vendor/magento/module-page-cache/Model/App/FrontController/BuiltinPlugin.php(69): Magento\Framework\App\FrontController\Interceptor->Magento\Framework\Interception\{closure}(Object(Magento\Framework\App\Request\Http))
#17 /Users/lukerodgers/src/magento2/vendor/magento/framework/Interception/Interceptor.php(142): Magento\PageCache\Model\App\FrontController\BuiltinPlugin->aroundDispatch(Object(Magento\Framework\App\FrontController\Interceptor), Object(Closure), Object(Magento\Framework\App\Request\Http))
#18 /Users/lukerodgers/src/magento2/var/generation/Magento/Framework/App/FrontController/Interceptor.php(26): Magento\Framework\App\FrontController\Interceptor->___callPlugins('dispatch', Array, Array)
#19 /Users/lukerodgers/src/magento2/vendor/magento/framework/App/Http.php(135): Magento\Framework\App\FrontController\Interceptor->dispatch(Object(Magento\Framework\App\Request\Http))
#20 /Users/lukerodgers/src/magento2/vendor/magento/framework/App/Bootstrap.php(258): Magento\Framework\App\Http->launch()
#21 /Users/lukerodgers/src/magento2/pub/index.php(37): Magento\Framework\App\Bootstrap->run(Object(Magento\Framework\App\Http))
#22 {main}";s:3:"url";s:15:"/?no_cache=true";s:11:"script_name";s:10:"/index.php";}

• The error message is “Area Code is not set”.
• The error is intermittent and hard to reproduce, and sometimes takes many page refreshes to occur.
• The error does not always occur on the same page, it seemed to be random pages.

Through a lot of file_put_contents logging I managed to track down the issue. It was that the Magento\Framework\App\State object which threw the exception was a different instance than the one configured in Magento\Framework\App\Http::launch which had the area code set. 💥

Here’s the code journey for how this error can occur, and a way of how to demonstrate it locally. I am referring to code in 2.1.15 but others have seen it in the 2.2 series as well.

TL;DR to fix this error report on your website

Increase your redis max_concurrency in app/etc/env.php and flush your config cache. It fixed the issue (session locking) for me.

To emulate locally

Go into Cm\RedisSession\Handler and amend read to throw the exception.

    public function read($sessionId)
    {
+       throw new ConcurrentConnectionsExceededException();

Load up your homepage and see the Area Code Is Not Set report generated.

Broken journey explanation

https://github.com/magento/magento2/blob/2.1.15/lib/internal/Magento/Framework/App/Bootstrap.php#L249-L270

The application bootstrap goes through the process of instantiating the object manager, launching the application, and sending the response (or handling errors).

https://github.com/magento/magento2/blob/2.1.15/lib/internal/Magento/Framework/App/Bootstrap.php#L229-L241

This section instantiates the object manager, creates the Magento\Framework\App\Http which then creates Magento\Framework\App\State as a dependency (with no area code set).

https://github.com/magento/magento2/blob/2.1.15/lib/internal/Magento/Framework/App/Http.php#L128-L135

The application is launched and the area code is set against the Magento\Framework\App\State object. As this is a singleton we should have the area code set for the entirety of the request. The request is then dispatched.

https://github.com/magento/magento2/blob/2.1.15/lib/internal/Magento/Framework/Session/SessionManager.php#L167-L189

Now that the request is underway the SessionManager will initialise (with session_start) and try to read your session information.

https://github.com/magento/magento2/blob/2.1.15/lib/internal/Magento/Framework/Session/SaveHandler/Redis.php#L43-L50

This is the section of code which actually tries to read the session. The error here is in the handling of ConcurrentConnectionsExceededException, the catch requires the errors/503.php page but does not stop the program execution.

https://github.com/magento/magento2/blob/2.1.15/pub/errors/503.php#L1-L12

The errors/503.php creates an error processor, processes the error, and sends the response.

https://github.com/magento/magento2/blob/2.1.15/pub/errors/processorFactory.php#L21-L27

The processor factory creates a new instance of the object manager using the ObjectManagerFactory, meaning all shared instances from the previous object manager are no longer relevant for this instance.

https://github.com/magento/magento2/blob/2.1.15/lib/internal/Magento/Framework/App/ObjectManagerFactory.php#L182-L183

Even worse, in the background of the ObjectManagerFactory it overrides the global reference to the object manager.

This means that

• We had part of our application initialised with one object manager, the State was created and an area code was set.
• A redis error was thrown and errors/503.php was required
  • A new object manager was instantiated and set to be the shared global one.
  • No area code is set against State because this only occurs in the Magento\Framework\App\Http::launch function
  • Headers and content were sent by errors/503.php
• The request is allowed to continue processing PHP code after this point because there is nothing terminating the request after errors/503.php was required.
• The request continues to process “as normal”, but with the object manager created by the error handler, the one without an area code.
• Any code currently holding a reference to the first object manager will continue to use it.
• Other magento code attempts to get the area code, can’t find it because it is using the new object manager, generates a report highlighting the wrong area of code as the problem.

Proposed code change

Essentially we tried to throw an error, failed, and a different error was triggered from a different part of the application because we had two versions of the object manager in memory.

As far as I can see only two parts of the application require errors/503.php in this manner.

• The http app uses it in the error handling of a request.
• The redis read handler has the issue that I’ve demonstrated above.

I propose we pass back the exception from the redis handler to the http app rather than trying to trigger a 503 page manually, this will terminate the request and generate a usable error report.

//Magento\Framework\Session\SaveHandler
    public function read($sessionId)
    {
        try {
            return parent::read($sessionId);
        } catch (ConcurrentConnectionsExceededException $e) {
+           throw $e;
-           require $this->filesystem->getDirectoryRead(DirectoryList::PUB)->getAbsolutePath('errors/503.php');
        }
    }

a:4:{i:0;s:0:"";i:1;s:6680:"#0 /Users/lukerodgers/src/magento2/vendor/magento/framework/Session/SaveHandler/Redis.php(46): Cm\RedisSession\Handler->read('oh8dob2oqbuuin3...')
#1 /Users/lukerodgers/src/magento2/vendor/magento/framework/Session/SaveHandler.php(93): Magento\Framework\Session\SaveHandler\Redis->read('oh8dob2oqbuuin3...')
#2 [internal function]: Magento\Framework\Session\SaveHandler->read('oh8dob2oqbuuin3...')
#3 /Users/lukerodgers/src/magento2/vendor/magento/framework/Session/SessionManager.php(189): session_start()
#4 /Users/lukerodgers/src/magento2/vendor/magento/framework/Interception/Interceptor.php(146): Magento\Framework\Session\SessionManager->start()
#5 /Users/lukerodgers/src/magento2/var/generation/Magento/Backend/Model/Auth/Session/Interceptor.php(169): Magento\Backend\Model\Auth\Session\Interceptor->___callPlugins('start', Array, Array)
#6 /Users/lukerodgers/src/magento2/vendor/magento/framework/Session/SessionManager.php(130): Magento\Backend\Model\Auth\Session\Interceptor->start()
#7 /Users/lukerodgers/src/magento2/vendor/magento/module-backend/Model/Auth/Session.php(97): Magento\Framework\Session\SessionManager->__construct(Object(Magento\Framework\App\Request\Http), Object(Magento\Framework\Session\SidResolver\Proxy), Object(Magento\Framework\Session\Config), Object(Magento\Framework\Session\SaveHandler), Object(Magento\Framework\Session\Validator), Object(Magento\Framework\Session\Storage), Object(Magento\Framework\Stdlib\Cookie\PhpCookieManager), Object(Magento\Framework\Stdlib\Cookie\CookieMetadataFactory), Object(Magento\Framework\App\State))
#8 /Users/lukerodgers/src/magento2/var/generation/Magento/Backend/Model/Auth/Session/Interceptor.php(14): Magento\Backend\Model\Auth\Session->__construct(Object(Magento\Framework\App\Request\Http), Object(Magento\Framework\Session\SidResolver\Proxy), Object(Magento\Framework\Session\Config), Object(Magento\Framework\Session\SaveHandler), Object(Magento\Framework\Session\Validator), Object(Magento\Framework\Session\Storage), Object(Magento\Framework\Stdlib\Cookie\PhpCookieManager), Object(Magento\Framework\Stdlib\Cookie\CookieMetadataFactory), Object(Magento\Framework\App\State), Object(Magento\Framework\Acl\Builder\Proxy), Object(Magento\Backend\Model\Url), Object(Magento\Backend\App\Config))
#9 /Users/lukerodgers/src/magento2/vendor/magento/framework/ObjectManager/Factory/AbstractFactory.php(111): Magento\Backend\Model\Auth\Session\Interceptor->__construct(Object(Magento\Framework\App\Request\Http), Object(Magento\Framework\Session\SidResolver\Proxy), Object(Magento\Framework\Session\Config), Object(Magento\Framework\Session\SaveHandler), Object(Magento\Framework\Session\Validator), Object(Magento\Framework\Session\Storage), Object(Magento\Framework\Stdlib\Cookie\PhpCookieManager), Object(Magento\Framework\Stdlib\Cookie\CookieMetadataFactory), Object(Magento\Framework\App\State), Object(Magento\Framework\Acl\Builder\Proxy), Object(Magento\Backend\Model\Url), Object(Magento\Backend\App\Config))
#10 /Users/lukerodgers/src/magento2/vendor/magento/framework/ObjectManager/Factory/Dynamic/Developer.php(66): Magento\Framework\ObjectManager\Factory\AbstractFactory->createObject('Magento\\Backend...', Array)
#11 /Users/lukerodgers/src/magento2/vendor/magento/framework/ObjectManager/ObjectManager.php(71): Magento\Framework\ObjectManager\Factory\Dynamic\Developer->create('Magento\\Backend...')
#12 /Users/lukerodgers/src/magento2/vendor/magento/framework/ObjectManager/Factory/AbstractFactory.php(144): Magento\Framework\ObjectManager\ObjectManager->get('Magento\\Backend...')
#13 /Users/lukerodgers/src/magento2/vendor/magento/framework/ObjectManager/Factory/AbstractFactory.php(232): Magento\Framework\ObjectManager\Factory\AbstractFactory->resolveArgument(Array, 'Magento\\Backend...', NULL, 'authStorage', 'Magento\\Backend...')
#14 /Users/lukerodgers/src/magento2/vendor/magento/framework/ObjectManager/Factory/Dynamic/Developer.php(34): Magento\Framework\ObjectManager\Factory\AbstractFactory->resolveArgumentsInRuntime('Magento\\Backend...', Array, Array)
#15 /Users/lukerodgers/src/magento2/vendor/magento/framework/ObjectManager/Factory/Dynamic/Developer.php(59): Magento\Framework\ObjectManager\Factory\Dynamic\Developer->_resolveArguments('Magento\\Backend...', Array, Array)
#16 /Users/lukerodgers/src/magento2/vendor/magento/framework/ObjectManager/ObjectManager.php(71): Magento\Framework\ObjectManager\Factory\Dynamic\Developer->create('Magento\\Backend...')
#17 /Users/lukerodgers/src/magento2/vendor/magento/framework/ObjectManager/Factory/AbstractFactory.php(144): Magento\Framework\ObjectManager\ObjectManager->get('Magento\\Backend...')
#18 /Users/lukerodgers/src/magento2/vendor/magento/framework/ObjectManager/Factory/AbstractFactory.php(232): Magento\Framework\ObjectManager\Factory\AbstractFactory->resolveArgument(Array, 'Magento\\Backend...', NULL, 'auth', 'Magento\\Staging...')
#19 /Users/lukerodgers/src/magento2/vendor/magento/framework/ObjectManager/Factory/Dynamic/Developer.php(34): Magento\Framework\ObjectManager\Factory\AbstractFactory->resolveArgumentsInRuntime('Magento\\Staging...', Array, Array)
#20 /Users/lukerodgers/src/magento2/vendor/magento/framework/ObjectManager/Factory/Dynamic/Developer.php(59): Magento\Framework\ObjectManager\Factory\Dynamic\Developer->_resolveArguments('Magento\\Staging...', Array, Array)
#21 /Users/lukerodgers/src/magento2/vendor/magento/framework/ObjectManager/ObjectManager.php(71): Magento\Framework\ObjectManager\Factory\Dynamic\Developer->create('Magento\\Staging...')
#22 /Users/lukerodgers/src/magento2/vendor/magento/framework/Interception/PluginList/PluginList.php(232): Magento\Framework\ObjectManager\ObjectManager->get('Magento\\Staging...')
#23 /Users/lukerodgers/src/magento2/vendor/magento/framework/Interception/Interceptor.php(121): Magento\Framework\Interception\PluginList\PluginList->getPlugin('Magento\\Framewo...', 'staging_preview...')
#24 /Users/lukerodgers/src/magento2/var/generation/Magento/Framework/App/FrontController/Interceptor.php(26): Magento\Framework\App\FrontController\Interceptor->___callPlugins('dispatch', Array, Array)
#25 /Users/lukerodgers/src/magento2/vendor/magento/framework/App/Http.php(135): Magento\Framework\App\FrontController\Interceptor->dispatch(Object(Magento\Framework\App\Request\Http))
#26 /Users/lukerodgers/src/magento2/vendor/magento/framework/App/Bootstrap.php(258): Magento\Framework\App\Http->launch()
#27 /Users/lukerodgers/src/magento2/pub/index.php(37): Magento\Framework\App\Bootstrap->run(Object(Magento\Framework\App\Http))
#28 {main}";s:3:"url";s:15:"/?no_cache=true";s:11:"script_name";s:10:"/index.php";}

Let me know your feedback, if this approach is agreed I will raise a PR.