What module is causing cache clean everyday around 13.30 o'clock

Question

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

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