[Issue] Add extra debug data to cache_invalidate log #40204
Description
This issue is automatically created based on existing pull request: #40196: Add extra debug data to cache_invalidate log
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.
And these are nicely correlated with the groupings of cache_invalidate with {"tags":[],"mode":"all"} purges.
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)