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} [] []

Improve this question
1
  • if it had been at the hour it could be the cron that magento has internally to wipe cache at midnight server time
    – iphigenie
    May 3 at 9:07

1 Answer 1

Reset to default
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.

Improve this answer
3
  • 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
    – Jesper Brejning
    Jul 7, 2022 at 9:03
  • I updated my answer.
    – simonthesorcerer
    Jul 12, 2022 at 14:52
  • why reindexing automatically flushes so much of the cache, while not having methods for re-warming the flushed cache, is a big magento annoyance. I might want to reindex my search index but not want every single category and products block to be wiped! And it puts a cache wipe in its internal cron too, with no explanation
    – iphigenie
    May 3 at 9:02

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge that you have read and understand our privacy policy and code of conduct.

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