Skip to content

Conversation

@convenient
Copy link
Contributor

@convenient convenient commented Sep 18, 2025

Description (*)

Attach extra debug data to the cache_invalidate: log. I recently came across another occurrence of this issue, but within a custom indexer magento/inventory@b6d7223. I believe having extra information on hand would make peoples lives easier.

The indexer was erroneously purging all of redis several times, causing massive performance degradation. We can see frequent drops in redis performance on the web frontend.
redis-destroyed2

And these are nicely correlated with the groupings of cache_invalidate with {"tags":[],"mode":"all"} purges.
redis-destroyed

In this case I knew what I was looking for because I was aware of magento/inventory@b6d7223, but in cases like this I believe it would be neat if the Magento application just provided you with all the information to debug these scenarios up front. This change should make the system behave a bit nicer for both the core application in future (if any similar issues may occur) and for any custom development out there.

With this little bit of extra information, the stack trace will pinpoint the problem for the developers to take action without having to deploy similar logging or make guesswork. Given the impact, I think this is a sensible change. As far as I can see this flow is not really triggered normally in the application in any case.

Manual testing scenarios (*)

Cache flush

cache_invalidate is not called at all, because a flush purges the whole storage separately.

$ rm -f var/log/*; php bin/magento  cache:flush > /dev/null; grep cache_invalidate var/log/debug.log
grep: var/log/debug.log: No such file or directory

Cache clean

As per #33122 cache:clean does not actually clean the whole Magento cache, it only purges the defined tags. So this log is not triggered

$ rm -f var/log/*; php bin/magento  cache:clean > /dev/null; grep cache_invalidate var/log/debug.log
[2025-09-18T14:13:38.894538+00:00] main.DEBUG: cache_invalidate:  {"method":"GET","url":"http:/","invalidateInfo":{"tags":["CONFIG"],"mode":"matchingTag"}} []
[2025-09-18T14:13:38.897990+00:00] main.DEBUG: cache_invalidate:  {"method":"GET","url":"http:/","invalidateInfo":{"tags":["LAYOUT_GENERAL_CACHE_TAG"],"mode":"matchingTag"}} []
[2025-09-18T14:13:38.898470+00:00] main.DEBUG: cache_invalidate:  {"method":"GET","url":"http:/","invalidateInfo":{"tags":["COLLECTION_DATA"],"mode":"matchingTag"}} []
[2025-09-18T14:13:38.898723+00:00] main.DEBUG: cache_invalidate:  {"method":"GET","url":"http:/","invalidateInfo":{"tags":["REFLECTION"],"mode":"matchingTag"}} []
[2025-09-18T14:13:38.898971+00:00] main.DEBUG: cache_invalidate:  {"method":"GET","url":"http:/","invalidateInfo":{"tags":["DB_DDL"],"mode":"matchingTag"}} []
[2025-09-18T14:13:38.899276+00:00] main.DEBUG: cache_invalidate:  {"method":"GET","url":"http:/","invalidateInfo":{"tags":["COMPILED_CONFIG"],"mode":"matchingTag"}} []
[2025-09-18T14:13:38.899522+00:00] main.DEBUG: cache_invalidate:  {"method":"GET","url":"http:/","invalidateInfo":{"tags":["EAV"],"mode":"matchingTag"}} []
[2025-09-18T14:13:38.899769+00:00] main.DEBUG: cache_invalidate:  {"method":"GET","url":"http:/","invalidateInfo":{"tags":["CUSTOMER_NOTIFICATION"],"mode":"matchingTag"}} []
[2025-09-18T14:13:38.900013+00:00] main.DEBUG: cache_invalidate:  {"method":"GET","url":"http:/","invalidateInfo":{"tags":["INTEGRATION"],"mode":"matchingTag"}} []
[2025-09-18T14:13:38.900246+00:00] main.DEBUG: cache_invalidate:  {"method":"GET","url":"http:/","invalidateInfo":{"tags":["INTEGRATION_API_CONFIG"],"mode":"matchingTag"}} []
[2025-09-18T14:13:38.900497+00:00] main.DEBUG: cache_invalidate:  {"method":"GET","url":"http:/","invalidateInfo":{"tags":["GRAPHQL_QUERY_RESOLVER_RESULT"],"mode":"matchingTag"}} []
[2025-09-18T14:13:38.901090+00:00] main.DEBUG: cache_invalidate:  {"method":"GET","url":"http:/","invalidateInfo":{"tags":["WEBSERVICE"],"mode":"matchingTag"}} []
[2025-09-18T14:13:38.901351+00:00] main.DEBUG: cache_invalidate:  {"method":"GET","url":"http:/","invalidateInfo":{"tags":["TRANSLATE"],"mode":"matchingTag"}} []

Additional test cases

//test.php
<?php
use Magento\Framework\App\Bootstrap;
require __DIR__ . '/app/bootstrap.php';

$bootstrap = Bootstrap::create(BP, $_SERVER);
$obj = $bootstrap->getObjectManager();
$logger = $obj->get(\Psr\Log\LoggerInterface::class);
$cache = $obj->get(\Magento\Framework\App\CacheInterface::class);

$logger->debug('cache_invalidate_test - cleaning one');
$cache->clean(['foobar']);

$logger->debug('cache_invalidate_test - cleaning multiple');
$cache->clean(['baz', 'qux']);

$logger->debug('cache_invalidate_test - cleaning no params');
$cache->clean();

$logger->debug('cache_invalidate_test - cleaning empty arrays');
$cache->clean([]);

Here's where we see the logs being triggered, in the scenario where clean is being called without parameters.

$ rm -f var/log/*; php test.php > /dev/null; grep cache_invalidate var/log/debug.log
[2025-09-18T14:15:37.677293+00:00] main.DEBUG: cache_invalidate_test - cleaning one [] []
[2025-09-18T14:15:38.583136+00:00] main.DEBUG: cache_invalidate:  {"method":"GET","url":"http:/","invalidateInfo":{"tags":["foobar"],"mode":"matchingAnyTag"}} []
[2025-09-18T14:15:38.583175+00:00] main.DEBUG: cache_invalidate_test - cleaning multiple [] []
[2025-09-18T14:15:38.583294+00:00] main.DEBUG: cache_invalidate:  {"method":"GET","url":"http:/","invalidateInfo":{"tags":["baz","qux"],"mode":"matchingAnyTag"}} []
[2025-09-18T14:15:38.583312+00:00] main.DEBUG: cache_invalidate_test - cleaning no params [] []
[2025-09-18T14:15:38.583382+00:00] main.DEBUG: cache_invalidate:  {"method":"GET","url":"http:/","invalidateInfo":{"tags":[],"mode":"all"},"trace":[{"file":"/var/www/html/vendor/magento/framework/Cache/Frontend/Decorator/Logger.php","line":60,"function":"execute","class":"Magento\\Framework\\Cache\\InvalidateLogger","type":"->","args":[{"tags":[],"mode":"all"}]},{"file":"/var/www/html/vendor/magento/framework/Cache/Frontend/Decorator/Logger.php","line":48,"function":"log","class":"Magento\\Framework\\Cache\\Frontend\\Decorator\\Logger","type":"->","args":[{"tags":[],"mode":"all"}]},{"file":"/var/www/html/vendor/magento/framework/App/Cache.php","line":102,"function":"clean","class":"Magento\\Framework\\Cache\\Frontend\\Decorator\\Logger","type":"->","args":[]},{"file":"/var/www/html/vendor/magento/framework/App/Cache/Proxy.php","line":103,"function":"clean","class":"Magento\\Framework\\App\\Cache","type":"->","args":[[]]},{"file":"/var/www/html/test.php","line":19,"function":"clean","class":"Magento\\Framework\\App\\Cache\\Proxy","type":"->","args":[]}]} []
[2025-09-18T14:15:38.583606+00:00] main.DEBUG: cache_invalidate:  {"method":"GET","url":"http:/","invalidateInfo":{"tags":[],"mode":"all"},"trace":[{"file":"/var/www/html/vendor/magento/framework/Cache/Frontend/Decorator/Logger.php","line":60,"function":"execute","class":"Magento\\Framework\\Cache\\InvalidateLogger","type":"->","args":[{"tags":[],"mode":"all"}]},{"file":"/var/www/html/vendor/magento/framework/Cache/Frontend/Decorator/Logger.php","line":48,"function":"log","class":"Magento\\Framework\\Cache\\Frontend\\Decorator\\Logger","type":"->","args":[{"tags":[],"mode":"all"}]},{"file":"/var/www/html/vendor/magento/framework/App/Cache.php","line":102,"function":"clean","class":"Magento\\Framework\\Cache\\Frontend\\Decorator\\Logger","type":"->","args":[]},{"file":"/var/www/html/vendor/magento/framework/App/Cache/Proxy.php","line":103,"function":"clean","class":"Magento\\Framework\\App\\Cache","type":"->","args":[[]]},{"file":"/var/www/html/test.php","line":19,"function":"clean","class":"Magento\\Framework\\App\\Cache\\Proxy","type":"->","args":[]}]} []
[2025-09-18T14:15:38.583636+00:00] main.DEBUG: cache_invalidate_test - cleaning empty arrays [] []
[2025-09-18T14:15:38.583696+00:00] main.DEBUG: cache_invalidate:  {"method":"GET","url":"http:/","invalidateInfo":{"tags":[],"mode":"all"},"trace":[{"file":"/var/www/html/vendor/magento/framework/Cache/Frontend/Decorator/Logger.php","line":60,"function":"execute","class":"Magento\\Framework\\Cache\\InvalidateLogger","type":"->","args":[{"tags":[],"mode":"all"}]},{"file":"/var/www/html/vendor/magento/framework/Cache/Frontend/Decorator/Logger.php","line":48,"function":"log","class":"Magento\\Framework\\Cache\\Frontend\\Decorator\\Logger","type":"->","args":[{"tags":[],"mode":"all"}]},{"file":"/var/www/html/vendor/magento/framework/App/Cache.php","line":102,"function":"clean","class":"Magento\\Framework\\Cache\\Frontend\\Decorator\\Logger","type":"->","args":[]},{"file":"/var/www/html/vendor/magento/framework/App/Cache/Proxy.php","line":103,"function":"clean","class":"Magento\\Framework\\App\\Cache","type":"->","args":[[]]},{"file":"/var/www/html/test.php","line":22,"function":"clean","class":"Magento\\Framework\\App\\Cache\\Proxy","type":"->","args":[[]]}]} []
[2025-09-18T14:15:38.583829+00:00] main.DEBUG: cache_invalidate:  {"method":"GET","url":"http:/","invalidateInfo":{"tags":[],"mode":"all"},"trace":[{"file":"/var/www/html/vendor/magento/framework/Cache/Frontend/Decorator/Logger.php","line":60,"function":"execute","class":"Magento\\Framework\\Cache\\InvalidateLogger","type":"->","args":[{"tags":[],"mode":"all"}]},{"file":"/var/www/html/vendor/magento/framework/Cache/Frontend/Decorator/Logger.php","line":48,"function":"log","class":"Magento\\Framework\\Cache\\Frontend\\Decorator\\Logger","type":"->","args":[{"tags":[],"mode":"all"}]},{"file":"/var/www/html/vendor/magento/framework/App/Cache.php","line":102,"function":"clean","class":"Magento\\Framework\\Cache\\Frontend\\Decorator\\Logger","type":"->","args":[]},{"file":"/var/www/html/vendor/magento/framework/App/Cache/Proxy.php","line":103,"function":"clean","class":"Magento\\Framework\\App\\Cache","type":"->","args":[[]]},{"file":"/var/www/html/test.php","line":22,"function":"clean","class":"Magento\\Framework\\App\\Cache\\Proxy","type":"->","args":[[]]}]} []

Contribution checklist (*)

  • Pull request has a meaningful description of its purpose
  • All commits are accompanied by meaningful commit messages
  • All new or changed code is covered with unit/integration tests (if applicable)
  • README.md files for modified modules are updated and included in the pull request if any README.md predefined sections require an update
  • All automated tests passed successfully (all builds are green)

Resolved issues:

  1. resolves [Issue] Add extra debug data to cache_invalidate log #40204: Add extra debug data to cache_invalidate log

@m2-assistant
Copy link

m2-assistant bot commented Sep 18, 2025

Hi @convenient. Thank you for your contribution!
Here are some useful tips on how you can test your changes using Magento test environment.
❗ Automated tests can be triggered manually with an appropriate comment:

  • @magento run all tests - run or re-run all required tests against the PR changes
  • @magento run <test-build(s)> - run or re-run specific test build(s)
    For example: @magento run Unit Tests

<test-build(s)> is a comma-separated list of build names.

Allowed build names are:
  1. Database Compare
  2. Functional Tests CE
  3. Functional Tests EE
  4. Functional Tests B2B
  5. Integration Tests
  6. Magento Health Index
  7. Sample Data Tests CE
  8. Sample Data Tests EE
  9. Sample Data Tests B2B
  10. Static Tests
  11. Unit Tests
  12. WebAPI Tests
  13. Semantic Version Checker

You can find more information about the builds here
ℹ️ Run only required test builds during development. Run all test builds before sending your pull request for review.


For more details, review the Code Contributions documentation.
Join Magento Community Engineering Slack and ask your questions in #github channel.

@ct-prd-pr-scan
Copy link

The security team has been informed about this pull request due to the presence of risky security keywords. For security vulnerability reports, please visit Adobe's vulnerability disclosure program on HackerOne or email [email protected].

2 similar comments
@ct-prd-pr-scan
Copy link

The security team has been informed about this pull request due to the presence of risky security keywords. For security vulnerability reports, please visit Adobe's vulnerability disclosure program on HackerOne or email [email protected].

@ct-prd-pr-scan
Copy link

The security team has been informed about this pull request due to the presence of risky security keywords. For security vulnerability reports, please visit Adobe's vulnerability disclosure program on HackerOne or email [email protected].

@convenient
Copy link
Contributor Author

@magento run all tests

$context['trace'] = (new \Exception)->getTrace();
}
}
$this->logger->debug('cache_invalidate: ', $context);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

btw, if. you pass exception to psr log based on monolog in format like $this->logger->debug('cache_invalidate: ', ['exception'=> new \Exception()]); it will add trace to message

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ooh i didn't know that thanks. I've just given it a quick test like this to see

$this->logger->debug('cache_invalidate: ', ['exception'=> new \Exception()]);

and i get this log, it does the exception but without the full trace

main.DEBUG: cache_invalidate:  {"exception":"[object] (Exception(code: 0):  at /var/www/html/vendor/magento/framework/Cache/InvalidateLogger.php:54)"}

Am I missing a trick?

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can't speak to @kandy's message, but another option is casting the exception to string. That should give the message, code, and full formatted trace. (string)(new \Exception()) (see https://www.php.net/manual/en/exception.tostring.php)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@rhoerr that's decent, looks like this

public function execute($invalidateInfo)
{
    $context = $this->makeParams($invalidateInfo);
    if (isset($invalidateInfo['tags'], $invalidateInfo['mode'])) {
        if ($invalidateInfo['mode'] === 'all' && is_array($invalidateInfo['tags']) && empty($invalidateInfo['tags'])) {
            // If we are sending a purge request to all cache storage capture the trace
            // This is not a usual flow, and likely a bug is causing a performance issue
            $context['exception'] =  (string)(new \Exception('full purge of cache storage triggered'));
        }
    }
    $this->logger->debug('cache_invalidate: ', $context);
}
[2025-09-18T15:50:52.353321+00:00] main.DEBUG: cache_invalidate:  {"method":"GET","url":"http:/","invalidateInfo":{"tags":[],"mode":"all"},"exception":"Exception: full purge of cache storage triggered in /var/www/html/vendor/magento/framework/Cache/InvalidateLogger.php:51
Stack trace:
#0 /var/www/html/vendor/magento/framework/Cache/Frontend/Decorator/Logger.php(60): Magento\\Framework\\Cache\\InvalidateLogger->execute(Array)
#1 /var/www/html/vendor/magento/framework/Cache/Frontend/Decorator/Logger.php(48): Magento\\Framework\\Cache\\Frontend\\Decorator\\Logger->log(Array)
#2 /var/www/html/vendor/magento/framework/App/Cache.php(102): Magento\\Framework\\Cache\\Frontend\\Decorator\\Logger->clean()
#3 /var/www/html/vendor/magento/framework/App/Cache/Proxy.php(103): Magento\\Framework\\App\\Cache->clean(Array)
#4 /var/www/html/test.php(22): Magento\\Framework\\App\\Cache\\Proxy->clean(Array)
#5 {main}"} []

I'm happy with any approach really, so long as we get the full stack trace to work with. Can the adobe team please advise what they prefer :)

@engcom-Hotel
Copy link
Contributor

@magento create issue

@engcom-Hotel engcom-Hotel added Triage: Dev.Experience Issue related to Developer Experience and needs help with Triage to Confirm or Reject it Priority: P2 A defect with this priority could have functionality issues which are not to expectations. labels Sep 23, 2025
@github-project-automation github-project-automation bot moved this to Pending Review in Pull Requests Dashboard Sep 23, 2025
@convenient
Copy link
Contributor Author

@magento run all tests

@convenient
Copy link
Contributor Author

@magento run all tests

@engcom-Hotel
Copy link
Contributor

@magento run all tests

Copy link
Contributor

@engcom-Hotel engcom-Hotel left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thank you @convenient for this PR! This is a valuable improvement for debugging cache performance issues.

Regarding @kandy's comment about exception handling here - they're absolutely right, and this would make the implementation even better.

Suggested change:

Instead of:

$context['exception'] = (string)(new \Exception('full purge of cache storage triggered'));

Use:

$context['exception'] = new \Exception('full purge of cache storage triggered');

This leverages Monolog's native exception handling per PSR-3 standard.

@engcom-Hotel engcom-Hotel moved this from Pending Review to Changes Requested in Community Dashboard Oct 23, 2025
@convenient
Copy link
Contributor Author

Hey @engcom-Hotel can you please see my comment #40196 (comment)

When I used that mechanism it did not contain the full trace, and therefore wouldnt be able to be used to help fix such issues

Copy link
Contributor

@engcom-Hotel engcom-Hotel left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thank you @convenient for your reply!

I am approving this PR for further processing.

@ct-prd-projects-boards-automation ct-prd-projects-boards-automation bot moved this from Changes Requested to Ready for Testing in Community Dashboard Oct 24, 2025
@ct-prd-projects-boards-automation ct-prd-projects-boards-automation bot moved this from Ready for Testing to Review in Progress in Community Dashboard Oct 24, 2025
@engcom-Hotel engcom-Hotel moved this from Review in Progress to Ready for Testing in Community Dashboard Oct 27, 2025
@engcom-Dash engcom-Dash self-assigned this Oct 27, 2025
@ct-prd-projects-boards-automation ct-prd-projects-boards-automation bot moved this from Ready for Testing to Testing in Progress in Community Dashboard Oct 27, 2025
@engcom-Dash
Copy link
Contributor

@magento run all tests

@engcom-Dash
Copy link
Contributor

@magento run all tests

@engcom-Dash
Copy link
Contributor

Hi @convenient
Thanks for the collaboration & contribution!

✔️ QA Passed

Preconditions:
Install fresh Magento 2.4-develop

Manual testing scenarios:

  1. Create a custom PHP script to trigger a full cache purge.
image

Before: ✖️
image

After: ✔️
image

Debug log with extra information for cache_invalidate

Builds are failing, hence moving this PR for extended testing

@engcom-Dash engcom-Dash moved this from Testing in Progress to Extended testing (optional) in Community Dashboard Oct 29, 2025
@engcom-Dash
Copy link
Contributor

@magento run Functional Tests B2B, Functional Tests CE, Unit Tests

@engcom-Dash
Copy link
Contributor

The consistent failures in Functional B2B are known issues and JIRA is open for the same. The other failures are inconsistent and flaky. They neither part of the PR nor failing because of the PR changes.

B2B

Build 1
https://public-results-storage-prod.magento-testing-service.engineering/reports/magento/magento2/pull/40196/45dc12a5e1e3bf2909419eb9f8877086/Functional/allure-report-b2b/index.html#categories
image

Build 2
https://public-results-storage-prod.magento-testing-service.engineering/reports/magento/magento2/pull/40196/53efa3f83c4cf9f416aec93a9f292147/Functional/allure-report-b2b/index.html#categories/8fb3a91ba5aaf9de24cc8a92edc82b5d
image
Known Issue
StorefrontPersistentCartCheckoutAfterSessionExpireLoginAndOrderTest:ACQE-8907

Hence, Moving this PR Merge In Progress

@engcom-Dash engcom-Dash moved this from Extended testing (optional) to Merge in Progress in Community Dashboard Oct 30, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Priority: P2 A defect with this priority could have functionality issues which are not to expectations. Progress: testing in progress Project: Community Picked PRs upvoted by the community Triage: Dev.Experience Issue related to Developer Experience and needs help with Triage to Confirm or Reject it

Projects

Status: Merge in Progress

Development

Successfully merging this pull request may close these issues.

[Issue] Add extra debug data to cache_invalidate log

6 participants