0

Everyday around 13:30 o'clock something is running a cache clean function in our code.

How can find the module?

[2022-06-28T13:30:08.670600+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["CONFIG"],"mode":"matchingTag"}} [] [2022-06-28T13:30:08.719469+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["LAYOUT_GENERAL_CACHE_TAG"],"mode":"matchingTag"}} [] [2022-06-28T13:30:08.928245+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["BLOCK_HTML"],"mode":"matchingTag"}} [] [2022-06-28T13:30:08.947380+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["COLLECTION_DATA"],"mode":"matchingTag"}} [] [2022-06-28T13:30:08.949102+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["REFLECTION"],"mode":"matchingTag"}} [] [2022-06-28T13:30:08.953678+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["DB_DDL"],"mode":"matchingTag"}} [] [2022-06-28T13:30:08.956040+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["EAV"],"mode":"matchingTag"}} [] [2022-06-28T13:30:08.956458+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["INTEGRATION"],"mode":"matchingTag"}} [] [2022-06-28T13:30:08.956781+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["INTEGRATION_API_CONFIG"],"mode":"matchingTag"}} [] [2022-06-28T13:30:08.972854+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"servers":[{"Laminas\Uri\Uri":"http://babygeardk-purge.swarm.powr.host:80/"}],"formattedTagsChunk":"."}} [] [2022-06-28T13:30:08.972927+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["FPC"],"mode":"matchingTag"}} [] [2022-06-28T13:30:08.973789+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["TRANSLATE"],"mode":"matchingTag"}} [] [2022-06-28T13:30:08.974535+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["WEBSERVICE"],"mode":"matchingTag"}} [] [2022-06-28T13:30:09.913340+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["CONFIG"],"mode":"matchingTag"}} [] [2022-06-28T13:30:09.913797+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["LAYOUT_GENERAL_CACHE_TAG"],"mode":"matchingTag"}} [] [2022-06-28T13:30:09.914080+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["BLOCK_HTML"],"mode":"matchingTag"}} [] [2022-06-28T13:30:09.914344+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["COLLECTION_DATA"],"mode":"matchingTag"}} [] [2022-06-28T13:30:09.914606+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["REFLECTION"],"mode":"matchingTag"}} [] [2022-06-28T13:30:09.914868+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["DB_DDL"],"mode":"matchingTag"}} [] [2022-06-28T13:30:09.915130+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["EAV"],"mode":"matchingTag"}} [] [2022-06-28T13:30:09.915390+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["INTEGRATION"],"mode":"matchingTag"}} [] [2022-06-28T13:30:09.915646+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["INTEGRATION_API_CONFIG"],"mode":"matchingTag"}} [] [2022-06-28T13:30:09.917627+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"servers":[{"Laminas\Uri\Uri":"http://babygeardk-purge.swarm.powr.host:80/"}],"formattedTagsChunk":"."}} [] [2022-06-28T13:30:09.917693+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["FPC"],"mode":"matchingTag"}} [] [2022-06-28T13:30:09.917963+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["TRANSLATE"],"mode":"matchingTag"}} [] [2022-06-28T13:30:09.918229+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["WEBSERVICE"],"mode":"matchingTag"}} [] [2022-06-28T13:30:09.921906+00:00] main.INFO: Cron Job [2022-06-28T13:30:10.749799+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"servers":[{"Laminas\Uri\Uri":"http://babygeardk-purge.swarm.powr.host:80/"}],"formattedTagsChunk":".*"}} [] [2022-06-28T13:30:10.749947+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["FPC"],"mode":"matchingTag"}} [] [2022-06-28T13:30:10.750331+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["TRANSLATE"],"mode":"matchingTag"}} [] [2022-06-28T13:30:10.750612+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["WEBSERVICE"],"mode":"matchingTag"}} []

UPDATE, Thank you for your reply, simonthesorcerer. I have added the logging function. Now I get the following in the log. Why does this invalidate the full Varnish cache?

[2022-07-07T08:42:11.549272+00:00] main.DEBUG: cache_invalidate: {"method":"GET","url":"http:/","invalidateInfo":{"tags":["cat_p_104366","cat_c_502","cat_c_701","cat_c_700","cat_c_2","cat_c_256","cat_c_500","amasty_xlanding_page_1","amasty_xlanding_page_2","amasty_xlanding_page_3","amasty_xlanding_page_4","amasty_xlanding_page_5","amasty_xlanding_page_6","amasty_xlanding_page_7","amasty_xlanding_page_9","amasty_xlanding_page_11","amasty_xlanding_page_12","amasty_xlanding_page_13","amasty_xlanding_page_14","amasty_xlanding_page_15","amasty_xlanding_page_16","amasty_xlanding_page_17","amasty_xlanding_page_18","amasty_xlanding_page_19"],"mode":"matchingAnyTag"}} [] [2022-07-07T08:42:11.549326+00:00] main.CRITICAL: Exception: only here for debugging in /home/babygear_dev/public_html/vendor/magento/framework/Cache/InvalidateLogger.php:50 Stack trace: #0 /home/babygear_dev/public_html/vendor/magento/framework/Cache/Frontend/Decorator/Logger.php(60): Magento\Framework\Cache\InvalidateLogger->execute() #1 /home/babygear_dev/public_html/vendor/magento/framework/Cache/Frontend/Decorator/Logger.php(48): Magento\Framework\Cache\Frontend\Decorator\Logger->log() #2 /home/babygear_dev/public_html/vendor/magento/framework/App/Cache.php(96): Magento\Framework\Cache\Frontend\Decorator\Logger->clean() #3 /home/babygear_dev/public_html/vendor/magento/framework/App/Cache/Proxy.php(103): Magento\Framework\App\Cache->clean() #4 /home/babygear_dev/public_html/vendor/magento/module-indexer/Model/Indexer/DeferredCacheCleaner.php(76): Magento\Framework\App\Cache\Proxy->clean() #5 /home/babygear_dev/public_html/vendor/magento/module-indexer/Model/Processor/CleanCache.php(50): Magento\Indexer\Model\Indexer\DeferredCacheCleaner->flush() #6 /home/babygear_dev/public_html/vendor/magento/framework/Interception/Interceptor.php(146): Magento\Indexer\Model\Processor\CleanCache->afterUpdateMview() #7 /home/babygear_dev/public_html/vendor/magento/framework/Interception/Interceptor.php(153): Magento\Indexer\Model\Processor\Interceptor->Magento\Framework\Interception{closure}() #8 /home/babygear_dev/public_html/generated/code/Magento/Indexer/Model/Processor/Interceptor.php(41): Magento\Indexer\Model\Processor\Interceptor->___callPlugins() #9 /home/babygear_dev/public_html/vendor/magento/module-indexer/Cron/UpdateMview.php(31): Magento\Indexer\Model\Processor\Interceptor->updateMview() #10 [internal function]: Magento\Indexer\Cron\UpdateMview->execute() #11 /home/babygear_dev/public_html/vendor/magento/module-cron/Observer/ProcessCronQueueObserver.php(368): call_user_func_array() #12 /home/babygear_dev/public_html/vendor/magento/module-cron/Observer/ProcessCronQueueObserver.php(879): Magento\Cron\Observer\ProcessCronQueueObserver->_runJob() #13 /home/babygear_dev/public_html/vendor/magento/module-cron/Observer/ProcessCronQueueObserver.php(840): Magento\Cron\Observer\ProcessCronQueueObserver->tryRunJob() #14 /home/babygear_dev/public_html/vendor/magento/module-cron/Observer/ProcessCronQueueObserver.php(280): Magento\Cron\Observer\ProcessCronQueueObserver->processPendingJobs() #15 /home/babygear_dev/public_html/vendor/magento/framework/Event/Invoker/InvokerDefault.php(88): Magento\Cron\Observer\ProcessCronQueueObserver->execute() #16 /home/babygear_dev/public_html/vendor/magento/framework/Event/Invoker/InvokerDefault.php(74): Magento\Framework\Event\Invoker\InvokerDefault->_callObserverMethod() #17 /home/babygear_dev/public_html/vendor/magento/framework/Event/Manager.php(66): Magento\Framework\Event\Invoker\InvokerDefault->dispatch() #18 /home/babygear_dev/public_html/generated/code/Magento/Framework/Event/Manager/Proxy.php(95): Magento\Framework\Event\Manager->dispatch() #19 /home/babygear_dev/public_html/vendor/magento/framework/App/Cron.php(86): Magento\Framework\Event\Manager\Proxy->dispatch() #20 /home/babygear_dev/public_html/vendor/magento/module-cron/Console/Command/CronCommand.php(117): Magento\Framework\App\Cron->launch() #21 /home/babygear_dev/public_html/vendor/symfony/console/Command/Command.php(255): Magento\Cron\Console\Command\CronCommand->execute() #22 /home/babygear_dev/public_html/vendor/symfony/console/Application.php(1009): Symfony\Component\Console\Command\Command->run() #23 /home/babygear_dev/public_html/vendor/symfony/console/Application.php(273): Symfony\Component\Console\Application->doRunCommand() #24 /home/babygear_dev/public_html/vendor/magento/framework/Console/Cli.php(115): Symfony\Component\Console\Application->doRun() #25 /home/babygear_dev/public_html/vendor/symfony/console/Application.php(149): Magento\Framework\Console\Cli->doRun() #26 /home/babygear_dev/public_html/bin/magento(23): Symfony\Component\Console\Application->run() #27 {main} [] []

1 Answer 1

1

First of all, check your cronjobs using crontab -l in the shell to see if it is something obvious.

If not:

It looks like the string is logged in vendor/magento/framework/Cache/InvalidateLogger.php method execute().

I'd add logging for a debug backtrace there, to see where the function call originates. May require some additional digging into the code to find the root cause after that.

The extended function could look something like this:

    public function execute($invalidateInfo)
    {
        $this->logger->debug('cache_invalidate: ', $this->makeParams($invalidateInfo));
        // added:
        try {
            throw new \Exception("only here for debugging");
        } catch (\Exception $e) {
            $this->logger->critical($e);
            $this->logger->critical($e->getTraceAsString());
        }
    }

This should send the stacktrace to the exception.log or system.log file and show you which part of your code is responsible.

UPDATE

After looking at the stack trace, I think the "problem" lies here:

Magento\Indexer\Cron\UpdateMview->execute()

...which then runs this:

Magento\Indexer\Model\Processor\CleanCache->afterUpdateMview()

One or more indexers get updated, and afterwards the cache gets cleared. I don't know if it really clears all cache, or if it sends special entities to the cache which get cleared - by looking into private function cleanCache() I see $this->context->getIdentities() and would expect the latter.

Maybe you have a product import running very often which updates everything? Like, the price, stock or other attributes of every product, even if there's no change? This would explain why it does a full cache clear.

2
  • HI, Thank you for your reply. I have added the function, but I don't get why this invalidate the full Varnish cache - please see debug.log in question Jul 7, 2022 at 9:03
  • I updated my answer. Jul 12, 2022 at 14:52

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.