Layout corruption with php-fpm (a Magento 1 problem returns)

[maderlock]

Preconditions

1. Run Magento 2 (any version) under php-fpm. Any valid php version - tested with php 5.6 to 7.0.11

Steps to reproduce

1. Hit it with heavy traffic including xmlrpc calls
2. Visit a page on frontend or backend

Expected result

Actual result

1. Page displays without head tag (sometimes - intermittent)

This is fixed by clearing the layout cache. This displays in the same way as an issue in Magento 1 - see https://www.c3media.co.uk/blog/c3-news/security-fix-might-take-site

The fix in Magento 1 was to add the following to bootstrap.php:

if (function_exists('libxml_disable_entity_loader')) {
    libxml_disable_entity_loader(false);
}

Why is this needed? Because there are a number of places in Magento 2 where $oldval = libxml_disable_entity_loader(true) is called and then later libxml_disable_entity_loader($oldval). In theory this should be fine, but the value is not thread-safe, so when running under php-fpm it only requires a call to occur in between these statements for the entire thread to end up set to TRUE. Why this then corrupts to cache it was never clear in Magento 1, but that was the upshot.

The above fix was added in Magento 1.9.2.0, but was not included in Magento 2. In one file (vendor/magento/framework/Xml/Security.php) there is an acknowledgment of the issue:

        /**
         * If running with PHP-FPM we perform an heuristic scan
         * We cannot use libxml_disable_entity_loader because of this bug
         * @see https://bugs.php.net/bug.php?id=64938
         */

...but sadly it still calls libxml_disable_entity_loader despite the warning. This is also called in some of the Zend and Symfony components, so it's not really reasonable to handle all these situations. Thus the need for the suggested fix.

Not entirely sure how to fix this in the short-term, as unlike Magento 2 we cannot just edit the bootstrap.php file in Magento 2.1.0. Any suggestions?

[maderlock]

I've tested the fix and unfortunately the cache corruption has occurred again, so it may be that the cause of this problem is different, or the fix needs to be different for Magento 2.

[convenient]

Can you please post a screenshot of the error when it happens? I'm trying to replicate on vanilla need to find something to hook into my bash script so that my scripts can identify a failure programmatically.

For now i'll focus on the page missing a tag in its entirety.

[convenient]

Theoretically if your instance was vanilla and your website suffered this error, would the output look similar to this?

[convenient]

I've spent an hour or so playing and have a few thoughts, although sadly no solution. I hope I actually get my hands on a demonstrable case of this bug at some point in the future.

M1 and configuration corruption

There were multiple errors that could cause config corruption in M1, aside from the cache locking race condition (https://github.com/convenient/magento-ce-ee-config-corruption-bug#update-good-news-a-patch-from-magento) the most likely culprit would be running PHP-FPM and the non thread-safe function libxml_disable_entity_loader.

https://bugs.php.net/bug.php?id=64938
https://bugs.php.net/bug.php?id=73328
https://bugs.php.net/bug.php?id=62577

libxml_disable_entity_loader breaks XML file loading

TL;DR

• Breaks simplexml_load_file
• Breaks XMLReader
• But not simplexml_load_string

The summary of the above is the status of libxml_disable_entity_loader is erroneously shared between PHP-FPM threads, causing failures to load otherwise valid xml files. These failed loads do not cause the system to throw an exception, and the erroneously generated content is cached for the next user meaning an admin has to flush the relevant cache for the system to become active again.

The calls that trigger libxml_disable_entity_loader(true) will likely be completely unrelated to config or layout generation, but due to the threaded nature it simply needs to be called during the same time period.

My readings suggest that the libxml_disable_entity_loader functionality only affects the simplexml_load_file method and the XMLReader object, a combination of file_get_contents and simplexml_load_string seems to be safe.

See gist here for a quick confirmation of these thoughts https://gist.github.com/convenient/5af567eae7090ed333c6cd366e77d357.

The XML file loading loading in M2 looks safer than M1

Whereas M1 made extensive use of simplexml_load_file, M2 seems to have refactored to use the safer pairing of simplexml_load_string(file_get_contents($path).

This can be seen in Magento\Framework\View\Model\Layout\Merge::_loadFileLayoutUpdatesXml, which uses Magento\Framework\Filesystem\Driver\File::fileGetContents to load the layout xml files and then uses Magento\Framework\View\Model\Layout\Merge::_loadXmlString to actually turn the string into a usable object.

This is also consistent with your findings that smashing libxml_disable_entity_loader(false); into your index.php does not solve the issue. It doesn't fix the issue as Magento is not using simplexml_load_file nor XMLReader to load the file, it is using safe functionality which does not care about the status of libxml_disable_entity_loader.

A quick sanity check

I did a quick check of the system for any other bits of code that might be loading XML in a non-thread-safe-manner, however it only turned up tests/dev tools and the magento setup modules. None of these things should be kicking off in sites that are in production mode. Unless I'm making a massive misunderstanding, which very possible! Perhaps it's worthwhile running a similar check on your code base to ensure that no modules are using the affected functions.

grep -r "simplexml_load_file" . | grep -v "/dev/tests/"

./app/code/Magento/Dhl/Test/Unit/Model/CarrierTest.php:        $xml = simplexml_load_file(
./app/code/Magento/Dhl/Test/Unit/Model/CarrierTest.php:        $empty = $billingNumberOnly = $outputImageOnly = simplexml_load_file(
./lib/internal/Magento/Framework/Simplexml/Test/Unit/ElementTest.php:        $xml = simplexml_load_file($xmlData[0], $xmlData[1]);
./lib/internal/Magento/Framework/Simplexml/Test/Unit/ElementTest.php:        $xml = simplexml_load_file($xmlData[0], $xmlData[1]);
./pub/errors/processor.php:        return ($configPath) ? simplexml_load_file($configPath) : null;
./setup/src/Magento/Setup/Module/Dependency/Parser/Config/Xml.php:        return \simplexml_load_file($file)->xpath('/config/module')[0];
./setup/src/Magento/Setup/Module/I18n/Parser/Adapter/Xml.php:        $xml = simplexml_load_file($file);
./vendor/magento/magento-composer-installer/src/MagentoHackathon/Composer/Magento/PackageXmlParser.php:        $package = simplexml_load_file($this->getFile()->getPathname());
./vendor/magento/magento-composer-installer/src/MagentoHackathon/Composer/Magento/PackageXmlParser.php:            $targets = simplexml_load_file(__DIR__ . '/../../../../res/target.xml');
./vendor/magento/zendframework1/library/Zend/Config.php:     * Handle any errors from simplexml_load_file or parse_ini_file

Similarly I couldn't find any usages of XMLReader in the vanilla source code, no luck there.

I wonder if there are other xml reading functions that are affected by libxml_disable_entity_loader that I may have missed.

Perhaps logging the exception thats suppressed in Magento\Framework\Filesystem\Glob::glob would fully rule out the glob aspect of the layout generation as a candidate.

[maderlock]

Thanks for all that work! I will try and go through it soon. For now, I'll just note that I thought there were unsafe calls in symfony and zend components that are manually turning on libxml_disable_entity_loader. Thanks again,

[eldonbite]

One of our projects was experiencing this issue as well, and as a workaround, we configured a cron task for clearing the layout cache every 3 hours just to avoid broken pages from being shown on the site.

We recently upgraded to Magento 2.1.3, and along with it, disabled the cron task for cleaning the layout cache. So far there are no reports of this issue occurring again. Anybody else experienced the same?

[convenient]

@eldonbite What version did you upgrade from? Do you have any other debug info to add?

[eldonbite]

Hi @convenient,

We were previously running 2.1.2.