Varnish "Connection reset by peer" error when large catalog is reindexed on schedule

[erikhansen]

Addition information for Re-Open

The Issue was reopened based on several complaints that it was not properly fixed and it still can be reproduced on the 2.2.8 and 2.3.1
For more details and explanation see next comments:

• Varnish "Connection reset by peer" error when large catalog is reindexed on schedule #8815 (comment)
• Varnish "Connection reset by peer" error when large catalog is reindexed on schedule #8815 (comment)

Preconditions

1. Magento EE 2.1.5 with ~10K sample products
2. Server is running PHP version 7.0.15
3. All indexes are configured to "UPDATE BY SCHEDULE"
4. Cron job is running on server. Cron error email address is configured with your email so you get notifications of errors.
5. Server is configured to use Varnish for Full Page Cache
6. Varnish is configured with http_req_hdr_len and http_req_size configured at their default values (per the documentation)

Steps to reproduce

1. In the admin, go to SYSTEM > Export and export a CSV of all ~10K products
2. Import the CSV back into Magento using the SYSTEM > Import interface

Expected result

The import will be processed without any errors.

Actual result

The cron will have an error when reindexing and will send an error like this to the cron email address:

PHP Notice: fwrite(): send of 8192 bytes failed with errno=104 Connection reset by peer in /var/www/stage/releases/20170213214641/vendor/zendframework/zend-http/src/Client/Adapter/Socket.php on line 376

The error above is triggered by line 375 of vendor/zendframework/zend-http/src/Client/Adapter/Socket.php

In order to determine what request was causing the error, I edited the Socket.php file to add logging code at line 375 to log large requests, along with a backtrace:

if (strlen($request) > 8000) {
    file_put_contents('/var/www/stage/current/var/log/connection_error.log', date('c') . PHP_EOL . print_r(debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS, 100), true), FILE_APPEND);
    file_put_contents('/var/www/stage/current/var/log/connection_error.log', date('c') . PHP_EOL . print_r($request, true), FILE_APPEND);
}

The requests that were causing errors were ~1.1MB in size, which exceeded the http_req_size default Varnish setting (which is 32k). While we could crank up that setting to allow the massive requests to be sent to Varnish, this would increase the Varnish memory footprint and is not an acceptable solution. Read this for context on the memory implications: https://www.varnish-cache.org/docs/4.0/reference/varnishd.html#http-req-size

Here is a preview of what the 1.1MB request contained:

PURGE / HTTP/1.1
X-Magento-Tags-Pattern: ((^|,)catalog_product_6574(,|$))|((^|,)catalog_product_6575(,|$))|((^|,)catalog_product_6576(,|$))|((^|,)catalog_product_6577(,|$))|((^|,)catalog_product_6578(,|$))|((^|,)catalog_product_6579(,|$))|((^|,)catalog_product_6580(,|$))|((^|,)catalog_product_6581(,|$))|((^|,)catalog_product_6582(,|$))|((^|,)catalog_product_6583(,|$))|((^|,)catalog_product_6584(,|$))|((^|,)catalog_product_6585(,|$))|((^|,)catalog_product_6586(,|$))|((^|,)catalog_product_6587(,|$))|((^|,)catalog_product_6588(,|$))|((^|,)catalog_product_6589(,|$))|((^|,)catalog_product_6590(,|$))|((^|,)catalog_product_6591(,|$))|((^|,)catalog_product_6593(,|$))|((^|,)catalog_product_6594(,|$))|((^|,)catalog_product_6595(,|$))|((^|,)catalog_product_6596(,|$))|((^|,)catalog_product_6597(,|$))|((^|,)catalog_product_6598(,|$))|((^|,)catalog_product_6599(,|$))|((^|,)catalog_product_6600(,|$))|((^|,)catalog_product_6601(,|$))|((^|,)catalog_product_6602(,|$))|((^|,)catalog_product_6603(,|$))|((^|,)catalog_product_6604(,|$))|((^|,)catalog_product_6605(,|$))|((^|,)catalog_product_6606(,|$))|((^|,)catalog_product_6607(,|$))|((^|,)catalog_product_6608(,|$))|((^|,)catalog_product_6644(,|$))|((^|,)catalog_product_6645(,|$))|((^|,)catalog_product_6646(,|$))|((^|,)catalog_product_6647(,|$))|((^|,)catalog_product_6648(,|$))|((^|,)catalog_product_6649(,|$))|((^|,)catalog_product_6650(,|$))|((^|,)catalog_product_6651(,|$))|((^|,)

In case it is useful for troubleshooting this issue, here is the backtrace logged by the logging code I added to the Socket.php file:

2017-02-26T19:15:46+00:00
Array
(
    [0] => Array
        (
            [file] => /var/www/stage/releases/20170224215342/vendor/magento/module-cache-invalidate/Model/PurgeCache.php
            [line] => 66
            [function] => write
            [class] => Zend\Http\Client\Adapter\Socket
            [type] => ->
        )

    [1] => Array
        (
            [file] => /var/www/stage/releases/20170224215342/vendor/magento/module-cache-invalidate/Observer/InvalidateVarnishObserver.php
            [line] => 65
            [function] => sendPurgeRequest
            [class] => Magento\CacheInvalidate\Model\PurgeCache
            [type] => ->
        )

    [2] => Array
        (
            [file] => /var/www/stage/releases/20170224215342/vendor/magento/framework/Event/Invoker/InvokerDefault.php
            [line] => 73
            [function] => execute
            [class] => Magento\CacheInvalidate\Observer\InvalidateVarnishObserver
            [type] => ->
        )

    [3] => Array
        (
            [file] => /var/www/stage/releases/20170224215342/vendor/magento/framework/Event/Invoker/InvokerDefault.php
            [line] => 61
            [function] => _callObserverMethod
            [class] => Magento\Framework\Event\Invoker\InvokerDefault
            [type] => ->
        )

    [4] => Array
        (
            [file] => /var/www/stage/releases/20170224215342/vendor/magento/framework/Event/Manager.php
            [line] => 66
            [function] => dispatch
            [class] => Magento\Framework\Event\Invoker\InvokerDefault
            [type] => ->
        )

    [5] => Array
        (
            [file] => /var/www/stage/releases/20170224215342/vendor/magento/module-indexer/Model/Processor/CleanCache.php
            [line] => 48
            [function] => dispatch
            [class] => Magento\Framework\Event\Manager
            [type] => ->
        )

    [6] => Array
        (
            [file] => /var/www/stage/releases/20170224215342/vendor/magento/framework/Interception/Interceptor.php
            [line] => 152
            [function] => afterUpdateMview
            [class] => Magento\Indexer\Model\Processor\CleanCache
            [type] => ->
        )

    [7] => Array
        (
            [file] => /var/www/stage/releases/20170224215342/var/generation/Magento/Indexer/Model/Processor/Interceptor.php
            [line] => 39
            [function] => ___callPlugins
            [class] => Magento\Indexer\Model\Processor\Interceptor
            [type] => ->
        )

    [8] => Array
        (
            [file] => /var/www/stage/releases/20170224215342/vendor/magento/module-indexer/Cron/UpdateMview.php
            [line] => 31
            [function] => updateMview
            [class] => Magento\Indexer\Model\Processor\Interceptor
            [type] => ->
        )

    [9] => Array
        (
            [function] => execute
            [class] => Magento\Indexer\Cron\UpdateMview
            [type] => ->
        )

    [10] => Array
        (
            [file] => /var/www/stage/releases/20170224215342/vendor/magento/module-cron/Observer/ProcessCronQueueObserver.php
            [line] => 247
            [function] => call_user_func_array
        )

    [11] => Array
        (
            [file] => /var/www/stage/releases/20170224215342/vendor/magento/module-cron/Observer/ProcessCronQueueObserver.php
            [line] => 195
            [function] => _runJob
            [class] => Magento\Cron\Observer\ProcessCronQueueObserver
            [type] => ->
        )

    [12] => Array
        (
            [file] => /var/www/stage/releases/20170224215342/vendor/magento/framework/Event/Invoker/InvokerDefault.php
            [line] => 73
            [function] => execute
            [class] => Magento\Cron\Observer\ProcessCronQueueObserver
            [type] => ->
        )

    [13] => Array
        (
            [file] => /var/www/stage/releases/20170224215342/vendor/magento/framework/Event/Invoker/InvokerDefault.php
            [line] => 61
            [function] => _callObserverMethod
            [class] => Magento\Framework\Event\Invoker\InvokerDefault
            [type] => ->
        )

    [14] => Array
        (
            [file] => /var/www/stage/releases/20170224215342/vendor/magento/module-staging/Model/Event/Manager.php
            [line] => 97
            [function] => dispatch
            [class] => Magento\Framework\Event\Invoker\InvokerDefault
            [type] => ->
        )

    [15] => Array
        (
            [file] => /var/www/stage/releases/20170224215342/var/generation/Magento/Staging/Model/Event/Manager/Proxy.php
            [line] => 95
            [function] => dispatch
            [class] => Magento\Staging\Model\Event\Manager
            [type] => ->
        )

    [16] => Array
        (
            [file] => /var/www/stage/releases/20170224215342/vendor/magento/framework/App/Cron.php
            [line] => 74
            [function] => dispatch
            [class] => Magento\Staging\Model\Event\Manager\Proxy
            [type] => ->
        )

    [17] => Array
        (
            [file] => /var/www/stage/releases/20170224215342/vendor/magento/module-cron/Console/Command/CronCommand.php
            [line] => 98
            [function] => launch
            [class] => Magento\Framework\App\Cron
            [type] => ->
        )

    [18] => Array
        (
            [file] => /var/www/stage/releases/20170224215342/vendor/symfony/console/Symfony/Component/Console/Command/Command.php
            [line] => 257
            [function] => execute
            [class] => Magento\Cron\Console\Command\CronCommand
            [type] => ->
        )

    [19] => Array
        (
            [file] => /var/www/stage/releases/20170224215342/vendor/symfony/console/Symfony/Component/Console/Application.php
            [line] => 874
            [function] => run
            [class] => Symfony\Component\Console\Command\Command
            [type] => ->
        )

    [20] => Array
        (
            [file] => /var/www/stage/releases/20170224215342/vendor/symfony/console/Symfony/Component/Console/Application.php
            [line] => 195
            [function] => doRunCommand
            [class] => Symfony\Component\Console\Application
            [type] => ->
        )

    [21] => Array
        (
            [file] => /var/www/stage/releases/20170224215342/vendor/magento/framework/Console/Cli.php
            [line] => 96
            [function] => doRun
            [class] => Symfony\Component\Console\Application
            [type] => ->
        )

    [22] => Array
        (
            [file] => /var/www/stage/releases/20170224215342/vendor/symfony/console/Symfony/Component/Console/Application.php
            [line] => 126
            [function] => doRun
            [class] => Magento\Framework\Console\Cli
            [type] => ->
        )

    [23] => Array
        (
            [file] => /var/www/stage/releases/20170224215342/bin/magento
            [line] => 23
            [function] => run
            [class] => Symfony\Component\Console\Application
            [type] => ->
        )

)

[AirmanAJK]

My solution to this problem was to add 2 plugins to Magento:
afterGetOutput for "\Magento\Framework\View\Layout" (sortOrder > 1)
beforeSendPurgeRequest for "\Magento\CacheInvalidate\Model\PurgeCache"

Both solutions check if the 'X-Magento-Tags' header exists, and if so, truncates it to 1000 characters. The obvious implication here is that if you do any operation that would have such a long tags header, you must manually clear your full page cache to make sure no stale content is improperly stored.

Here is a snippet from my Layout plugin:

public function afterGetOutput(\Magento\Framework\View\Layout $subject, $result) {
	$tagsHeader = $this->response->getHeader('X-Magento-Tags');
	if($tagsHeader) {
		$tagsValue = $tagsHeader->getFieldValue();
		if(strlen($tagsValue) > 1000) {
			$shortTagsHeader = substr($tagsValue, 0, 1000);
			$this->response->setHeader('X-Magento-Tags', $shortTagsHeader, true);
		}
	}
	return $result;
}

and here is a snippet from my PurgeCache plugin:

public function beforeSendPurgeRequest(\Magento\CacheInvalidate\Model\PurgeCache $subject, $tagsPattern) {
	if(strlen($tagsPattern) > 1000) {
		return substr($tagsPattern, 0, 1000);
	} else {
		return [$tagsPattern];
	}
}

I realize that this may not be a great solution for the Magento core code, but I think it's fine to use for anyone who understands the implications. Personally, I disable all cache flushing short of the "everything" (.*) value. Magento invalidates too much too often IMO. This makes me responsible for clearing caches after any changes, and I'm fine with that since we only make changes once a day.

Hope this helps.

[Vedrillan]

In my opinion the best approach is to send the purge request by fix batch size, based on amount of tags or request length.

This can be achieved by replacing the observer Magento\CacheInvalidate\Observer\InvalidateVarnishObserver and adding the batching mechanism.

I might as well do a PR if I have the time in the next days.

[erikhansen]

@AirmanAJK Thanks for sharing your workaround, but as you mentioned, that solution is not a good solution for the core code.

@Vedrillan A batching solution sounds like a good solution to this problem.

[swayoleg]

@AirmanAJK Thanks but here are results of implementation on Magento 2.1.4 Enterprice

`exception(s):
Exception #0 (Exception): Notice: Undefined property: MageXo\Fixers\Plugin\Layout\Interceptor::$response in /app/app/code/MageXo/Fixers/Plugin/Layout.php on line 8

Exception #0 (Exception): Notice: Undefined property: MageXo\Fixers\Plugin\Layout\Interceptor::$response in /app/app/code/MageXo/Fixers/Plugin/Layout.php on line 8
#0 /app/app/code/MageXo/Fixers/Plugin/Layout.php(8): Magento\Framework\App\ErrorHandler->handler(8, 'Undefined prope...', '/app/app/code/M...', 8, Array)
#1 /app/var/generation/MageXo/Fixers/Plugin/Layout/Interceptor.php(24): MageXo\Fixers\Plugin\Layout->afterGetOutput(Object(Magento\Framework\View\Layout\Interceptor), '<div class="men...')
#2 /app/vendor/magento/framework/Interception/Interceptor.php(152): MageXo\Fixers\Plugin\Layout\Interceptor->afterGetOutput(Object(Magento\Framework\View\Layout\Interceptor), '<div class="men...')
#3 /app/var/generation/Magento/Framework/View/Layout/Interceptor.php(494): Magento\Framework\View\Layout\Interceptor->___callPlugins('getOutput', Array, Array)
#4 /app/vendor/magento/framework/View/Result/Page.php(243): Magento\Framework\View\Layout\Interceptor->getOutput()
#5 /app/vendor/magento/framework/View/Result/Layout.php(164): Magento\Framework\View\Result\Page->render(Object(Magento\Framework\App\Response\Http\Interceptor))
#6 /app/var/generation/Magento/Backend/Model/View/Result/Page/Interceptor.php(193): Magento\Framework\View\Result\Layout->renderResult(Object(Magento\Framework\App\Response\Http\Interceptor))
#7 /app/vendor/magento/framework/App/Http.php(139): Magento\Backend\Model\View\Result\Page\Interceptor->renderResult(Object(Magento\Framework\App\Response\Http\Interceptor))
#8 /app/vendor/magento/framework/App/Bootstrap.php(258): Magento\Framework\App\Http->launch()
#9 /app/index.php(39): Magento\Framework\App\Bootstrap->run(Object(Magento\Framework\App\Http))
#10 {main}`

[franckgarnier21]

Any update of this issue ?

I report you the same issue with Magento 2 EE 2.0.7 with > 10K products

[denisrpriebe]

@erikhansen @AirmanAJK @Vedrillan Have you guys found a solution to this problem? Do you have any code I could try and implement? Thanks.

[erikhansen]

@denisrpriebe No, I don't have any patch or solution to share.

[erikhansen]

@denisrpriebe Actually, I do have a patch you could try, although I never tested it. If you want it, email me at erik@<domain listed in my Github profile>.

Update: I was incorrect—the patch I had was for a different issue.

[denisrpriebe]

@erikhansen Cool, just shot you an email.

[StoneISStephan]

Hi,

any news on this patch?
Did it work?

Experiencing the same issue on Magento 2.1.8

[Vedrillan]

I did a PR there #8919 but they can't reproduce the issue and as a result closed the PR x)

You can adapt a patch from this https://patch-diff.githubusercontent.com/raw/magento/magento2/pull/8919.diff and apply it on your project.