Magento2: 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:

• https://github.com/magento/magento2/issues/8815#issuecomment-493552366
• https://github.com/magento/magento2/issues/8815#issuecomment-504731799

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 "MagentoFrameworkViewLayout" (sortOrder > 1)
beforeSendPurgeRequest for "MagentoCacheInvalidateModelPurgeCache"

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 MagentoCacheInvalidateObserverInvalidateVarnishObserver 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.

[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 https://github.com/magento/magento2/pull/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.

[denisrpriebe]

For anyone else experiencing this, I had to disabled "Full Page Caching" within cache management in the admin...or you can do it through the command line. Once I did that, I no longer received the notice.

[AirmanAJK]

@denisrpriebe Simply not using the full page cache is hardly a solution. If CMS pages weren't loading, you surely wouldn't suggest deleting them all to fix the problem, right?

[denisrpriebe]

@AirmanAJK I understand your point. I'm not proposing a solution but rather an alternative for what worked for me. I think some documentation is better than none when it comes to a Magento issue.

[markalston]

@Vedrillan Thanks! I have been having this problem forever and still have it with 2.1.9. Your patch seems like the obvious fix. No tags are lost and simply sent in batches. Hopefully it will be added to 2.2.

[franckgarnier21]

@Vedrillan Thank you for your pull request, and it seems not managed correctly in 2.2 too...

They may need to improve their test coverages to the limit in this file : vendor/magento/module-cache-invalidate/Test/Unit/Observer/InvalidateVarnishObserverTest.php:66

[J-Fricke]

Any movement on this issue? We had this happening and then implemented a patch which sent over the requests in smaller batches, however, this sometimes ended up with way too many requests sent to varnish and overloaded the ephemeral ports eventually creating 500 errors on the site for users after getting slow to process. Our solution most likely will have to be to increase the http_req_size value to one which will accommodate these larger requests unless a better solution is proposed.

[jdubbya]

@J-Fricke We also received a patch that separated the invalidation request into smaller batches and quickly discovered that every time the cron jobs run a PURGE request with almost every active product in the catalog was being sent to the Varnish server for processing. This happens even when there are no updates happening in the admin or via the API. Separating the large PURGE requests into batches caused too many PURGE requests to the varnish server each minute and caused memory issues with the Varnish process because of the constant requests to remove things from cache. I expect that increasing the http_req_size may cause similar problems for you. It seems like there is another issue possibly related to indexing that is causing this in our case. Have you inspected the purge requests to see if what is being invalidated makes sense in your case?

[J-Fricke]

@jdubbya We are currently testing removing the chunking patch and increasing the values Varnish can send/receive based on this: https://devdocs.magento.com/guides/v2.2/config-guide/varnish/tshoot-varnish-503.html - This guide only discusses http_resp_hdr_len & http_resp_size, though only increasing those values did not fix our issue. We have a current test we'll continue over the next couple of days with increasing http_req_hdr_len & http_req_size as well to matching values as the response ones. I'll update this thread once we are confident in the testing.

As an aside, I'm curious what users would do if their catalog count * 21 exceeds the Varnish maximums would do to solve this issue? Perhaps a combinations of chunking and increasing the values to the max. I was pointed to a solution Fast.ly used for their extension which also leveraged some chunking, so that's probably the case.

[ghost]

Hi @erikhansen , thank you for your report.
We've acknowledged the issue and added to our backlog.

[magento-engcom-team]

@maksek Thank you for verifying the issue. Based on the provided information internal tickets MAGETWO-95275, MAGETWO-95276 were created

[sdzhepa]

Hello @erikhansen @J-Fricke

Thank you for contribution and collaboration!

The corresponding internal tickets MAGETWO-95276, MC-5655(MAGETWO-95275) were fixed and closed by Magento team

Delivered to 2.3-develop branch and should be available with 2.3.1 release
Please see details in the next commits:

• 677356e
• af3de71

Delivered to 2.2-develop branch and should be available with 2.2.8 release
Please see details in the next commits:

• 485ad0b

[joaolisboa]

I'm on version 2.2.8 with the fix and I must add that this was not properly fixed. We had issues on Varnish 4.0.5 due to incorrect tags sent by Magento due to the way the tags are split when sent in batches. Since you're splitting the tags by pipe and there are pipes inside each individual tag it can generate two invalid requests.

Right after the PURGE request I added logs to see each header being sent and this is the output after catching large requests being made. Pay attention to the last two requests.

varnish_magento_headers.log

Looking only at the last two headers, the last tag of the first header, continues in the next request because it split in the incorrect pipe.

One header ends in: ((^|,)cat_c_1191(,
The other continues with: $))

If you count the chars in the first header they add up to 7678, right next to the limit defined in the file PurgeCache.php. This is because the code incorrectly splits by pipes, but the pipe is a valid char inside the tag which means the tags are already incorrectly split the moment the explode() is done. So when checking if ((^|,)cat_c_1191(,|$)) fits in the header, in reality it is checking if $)) still fits in the header but there are 3 additional chars, which surpasses the limit of 7680. To replicate the issue I simply concatenated the last two headers and sent them through the splitTags function. You should see the same result.

[gigadesign1]

I have the same issue and can confirm that the issue was not properly fixed.

We were experiencing the varnish cache to be fully flushed every time our warehouse updated the stocks of a larger number of products.

After some debugging I found this in the varnish log:
ReqHeader X-Magento-Tags-Pattern: $))|((^|,)cat_p_769(,|$))|((^|,)cat_p_776(,|$))|((^|,)cat_p_768(,|$))|((^|,)cat_p_891(,|$))|((^|,)cat_p_97(,|$))|((^|,)cat_p_193(,|$))|((^|,)cat_p_949(,|$))|((^|,)cat_p_950(,|$))|((^|,)cat_p_312(,|$))|((^|,)cat_p_884(,|$))|((^|,)c
VCL_Error ban(): Regex compile error: unmatched parentheses

Apparently the regex being incorrect results in the varnish cache being fully flushed.

I'm on Magento 2.3.1 and varnish 4.1.1

[sdzhepa]

Hello @joaolisboa, @gigadesign1 @erikhansen

Thank you for the feedback!

I updated description with your comments and reopen the issue as "was not properly fixed"

[pczerkas]

The solution is to replace line in https://github.com/magento/magento2/commit/485ad0b67779ea3a59c89daa64f0e290e3311657 :
$formattedTags = explode('|', $tagsPattern);
with:
$formattedTags = array_filter(preg_split('/(?<=\))\|(?=\()/', $tagsPattern));

[m2-assistant[bot]]

Hi @engcom-Delta. Thank you for working on this issue.
In order to make sure that issue has enough information and ready for development, please read and check the following instruction: :point_down:

• [ ] 1. Verify that issue has all the required information. (Preconditions, Steps to reproduce, Expected result, Actual result).
  Details

  If the issue has a valid description, the label Issue: Format is valid will be added to the issue automatically. Please, edit issue description if needed, until label Issue: Format is valid appears.

• [ ] 2. Verify that issue has a meaningful description and provides enough information to reproduce the issue. If the report is valid, add Issue: Clear Description label to the issue by yourself.

• [ ] 3. Add Component: XXXXX label(s) to the ticket, indicating the components it may be related to.

• [ ] 4. Verify that the issue is reproducible on 2.3-develop branch

  Details

  - Add the comment @magento give me 2.3-develop instance to deploy test instance on Magento infrastructure.
  - If the issue is reproducible on 2.3-develop branch, please, add the label Reproduced on 2.3.x.
  - If the issue is not reproducible, add your comment that issue is not reproducible and close the issue and _stop verification process here_!

• [ ] 5. Add label Issue: Confirmed once verification is complete.

• [ ] 6. Make sure that automatic system confirms that report has been added to the backlog.

[engcom-Delta]

@joaolisboa @gigadesign1 @pczerkas Unfortunately, I cannot reproduce issue on 2.3-develop CE and 2.3-develop EE.
Testing scenario:

• Generate 10K products
• Configure varnish v.4.1.1
• Set indexers to "UPDATE BY SCHEDULE"
• Run bin/magento cron:install
• In the admin, go to SYSTEM > Export and export a CSV of all ~10K products
• Import the CSV back into Magento using the SYSTEM > Import interface

Result:
:heavy_check_mark: Import is finished without errors.

• Go to Catalog->Product

• Check products using checkbox ( in my case I used Select All for testing)
  

• Click Actions->Update Attributes

• Set Advanced Inventory->Stock Availability=Out of Stock
• Click Save

Result:
:heavy_check_mark: Stock Status is updated without errors

Could you take a look if my steps are correct?

[Vedrillan]

From the 1st update The cron will have an error when reindexing, the error is not in the BO, it is in the reindexing cronjob...

[ihor-sviziev]

@engcom-Delta,
Could you review comment following comment https://github.com/magento/magento2/issues/8815#issuecomment-543085600 and try to reproduce the issue during reindexing cron job run?

[magento-engcom-team]

Hi @erikhansen. Thank you for your report.
The issue has been fixed in magento/magento2#26256 by @moloughlin in 2.4-develop branch
Related commit(s):

• e2123017375ee389cb49514c7b1e3d60b9aa6e1b
• 4c223031e12bf6de7380ff8b13688d475f92f8d0
• fc2ce73d3352ad7180f64540c5369193ebb413f9
• a9d376d7c9c9a0e0dd37cb4c485ff7e93f56c764
• 5e69e824709d2a3eece6cffd4b04c82f9c891dd0
• 479c0cc0ec1a0e0af34efba671274102db7542e3
• d0ef6aea8f4e8690c6e164a4445c4847245c4ce9
• 85b3ffd90bfc9b415c6e8fcfb990caf92ab7980e
• 116c1910520fe2081e09e91dca6b04716f25dbbb
• 0926f5c008d0c272fc7828fbe2cfed60d93ac8cc
• ffb1174bfcd19b9f3de04a59ad1ec10c0b4913d2
• 99b26a4f9c22462e35d17ed1958d66fb31fe9e28
• a19274e203a884b92e0fcd2b0cda40ea4d4e8080

The fix will be available with the upcoming 2.4.1 release.