AEM 6.5 Publisher getting a lot of non-author related replication requests to clear dispatcher cache | Community
Skip to main content
eagleinhills
eagleinhills
Level 2
June 16, 2023
Solved

AEM 6.5 Publisher getting a lot of non-author related replication requests to clear dispatcher cache

  • June 16, 2023
  • 2 replies
  • 1643 views

We have been running into an issue where the publisher logs have a lot of invalidate cache request not related to the author page/assets publish. Any ideas why are we getting this?

 

An example of such is pasted below.

 

15.06.2023 18:38:12.852 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.impl.ReplicatorImpl Setting up replication with options: ReplicationOptions{synchronous=true, revision='null', suppressStatusUpdate=true, suppressVersions=true, filter=com.day.cq.replication.AgentIdFilter@b2d4698, aggregateHandler=null}
15.06.2023 18:38:12.853 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent Creating content for path /content
15.06.2023 18:38:12.853 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent Create new HttpClient for dispatcher2uswest1Agent
15.06.2023 18:38:12.853 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent * HTTP Version: 1.1
15.06.2023 18:38:12.853 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent * Connect Timeout: 900000
15.06.2023 18:38:12.854 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent * Socket Timeout: 900000
15.06.2023 18:38:12.854 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent Sending GET request to http://10.55.0.106:80/dispatcher/invalidate.cache
15.06.2023 18:38:12.855 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent sent. Response: 200 OK
15.06.2023 18:38:12.855 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent ------------------------------------------------
15.06.2023 18:38:12.855 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent Sending message to 10.55.0.106:80
15.06.2023 18:38:12.855 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent >> GET /dispatcher/invalidate.cache HTTP/1.0
15.06.2023 18:38:12.855 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent >> CQ-Action: Test
15.06.2023 18:38:12.855 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent >> CQ-Handle: /content
15.06.2023 18:38:12.855 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent >> CQ-Path: /content
15.06.2023 18:38:12.855 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent >> Referer: about:blank
15.06.2023 18:38:12.855 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent >> Content-Length: 0
15.06.2023 18:38:12.855 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent >> Content-Type: application/octet-stream
15.06.2023 18:38:12.855 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent >> Host: flush
15.06.2023 18:38:12.855 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent --
15.06.2023 18:38:12.855 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent << HTTP/1.1 200 OK
15.06.2023 18:38:12.855 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent << Date: Thu, 15 Jun 2023 18:38:12 GMT
15.06.2023 18:38:12.855 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent << Server: Apache
15.06.2023 18:38:12.856 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent << X-Dispatcher: dispatcher2uswest1
15.06.2023 18:38:12.856 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent << X-Vhost: flush
15.06.2023 18:38:12.856 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent << Content-Length: 13
15.06.2023 18:38:12.856 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent << Content-Type: text/html; charset=UTF-8
15.06.2023 18:38:12.856 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent <<
15.06.2023 18:38:12.856 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent <<
15.06.2023 18:38:12.856 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent Message sent.
15.06.2023 18:38:12.856 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent ------------------------------------------------
15.06.2023 18:38:12.856 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent Replication (TEST) of /content successful.
15.06.2023 18:38:12.856 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.impl.ReplicatorImpl Processed 1 paths in this replications: setup 0ms, check 0ms, pre 1ms, build 0ms, queue 3ms, update 0ms, total 4ms

 

This is very different from the regular author related replication which happens a lot less often:

 

15.06.2023 09:58:04.219 *INFO* [Adobe Granite ChainReplicationService Processor] com.day.cq.replication.impl.ReplicatorImpl Setting up replication with options: ReplicationOptions{synchronous=false, revision='null', suppressStatusUpdate=true, suppressVersions=true, filter=com.day.cq.replication.impl.ChainReplicationService$1@341fe802, aggregateHandler=null}
15.06.2023 09:58:04.222 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent.queue Processing job for agent dispatcher2uswest1Agent
15.06.2023 09:58:04.223 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent Sending GET request to http://10.55.0.106:80/dispatcher/invalidate.cache
15.06.2023 09:58:04.225 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent sent. Response: 200 OK
15.06.2023 09:58:04.225 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent ------------------------------------------------
15.06.2023 09:58:04.225 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent Sending message to 10.55.0.106:80
15.06.2023 09:58:04.225 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent >> GET /dispatcher/invalidate.cache HTTP/1.0
15.06.2023 09:58:04.225 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent >> CQ-Action: Activate
15.06.2023 09:58:04.225 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent >> CQ-Handle: /content/coherentweb/en/news
15.06.2023 09:58:04.225 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent >> CQ-Path: /content/coherentweb/en/news
15.06.2023 09:58:04.225 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent >> Referer: about:blank
15.06.2023 09:58:04.225 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent >> Content-Length: 0
15.06.2023 09:58:04.225 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent >> Content-Type: application/octet-stream
15.06.2023 09:58:04.225 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent >> Host: flush
15.06.2023 09:58:04.225 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent --
15.06.2023 09:58:04.225 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent << HTTP/1.1 200 OK
15.06.2023 09:58:04.225 *INFO* [Adobe Granite ChainReplicationService Processor] com.day.cq.replication.Agent.dispatcher2uswest1Agent Creating content for path /content/coherentweb/en/events/laser-world-photonics-2023
15.06.2023 09:58:04.225 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent << Date: Thu, 15 Jun 2023 09:58:04 GMT
15.06.2023 09:58:04.225 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent << Server: Apache
15.06.2023 09:58:04.225 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent << X-Dispatcher: dispatcher2uswest1
15.06.2023 09:58:04.225 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent << X-Vhost: flush
15.06.2023 09:58:04.225 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent << Content-Length: 13
15.06.2023 09:58:04.225 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent << Content-Type: text/html; charset=UTF-8
15.06.2023 09:58:04.225 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent <<
15.06.2023 09:58:04.225 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent <<
15.06.2023 09:58:04.226 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent Message sent.
15.06.2023 09:58:04.226 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent ------------------------------------------------
15.06.2023 09:58:04.226 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent Replication (ACTIVATE) of /content/coherentweb/en/news successful.
15.06.2023 09:58:04.226 *INFO* [sling-threadpool-8539d8b5-f56a-4e1b-8181-3b8f73ee9077-(apache-sling-job-thread-pool)-33-com_day_cq_replication_job_dispatcher2uswest1Agent(com/day/cq/replication/job/dispatcher2uswest1Agent)] com.day.cq.replication.Agent.dispatcher2uswest1Agent.queue Job for agent dispatcher2uswest1Agent processed in 4ms. Ok.

This post is no longer active and is closed to new replies. Need help? Start a new post to ask your question.
Best answer by eagleinhills

In that case I would check what monitoring system runs on the publish machine itself (thus accessing the system via "localhost:4502" or so) which triggers this call.


Turns out that CQ-Action: Test header sent to the invalidate.cache was just to test the connectivity as part of monitoring. I have confirmed by observing the dispatcher cache that these events do not clear the full dispatcher cache 

 

Thank you for your help @joerghoh @estebanbustamante 

 

 

2 replies

EstebanBustamante
Community Advisor and Adobe Champion
EstebanBustamanteCommunity Advisor and Adobe Champion
Community Advisor and Adobe Champion
June 16, 2023

Can you check if your flush agent queue has items that are not related to the page/resource which is being activated?

Esteban Bustamante
    joerghoh
    Adobe Employee
    joerghohAdobe Employee
    Adobe Employee
    June 16, 2023

    If you check the exact path, you can spot the "test" in there.

     

    This seems to be a connection test, so maybe part of a monitoring.

      eagleinhills
      eagleinhillsAuthor
      Level 2
      June 16, 2023

      @joerghoh but it keeps on sending invalidate.cache requests. My fear is that it might be clearing the full cache 

      15.06.2023 18:38:12.854 *INFO* [[0:0:0:0:0:0:0:1] [1686854292851] GET /etc/replication/agents.publish/dispatcher2uswest1Agent.test.html HTTP/1.1] com.day.cq.replication.Agent.dispatcher2uswest1Agent Sending GET request to http://10.55.0.106:80/dispatcher/invalidate.cache

        eagleinhills
        eagleinhillsAuthor
        Level 2
        June 16, 2023

        in that case the dispatcher should log on INFO a message "Activation detected ..."; can you check your dispatcher log for this?


        @joerghoh found around over a 100 entries in the dispatcher log matching this though our site is not edited heavily. It is usually a few dozen edits per day max but there are a lot of invalidate cache calls in dispatcher and the fact that these calls happen regularly i.e. many times in each hour:

         

        [Thu Jun 15 03:13:48 2023] [I] [pid 10895:tid 140542260274944] "GET /dispatcher/invalidate.cache" 200 purge [coherent/-] 0ms

          Terms & ConditionsAccessibility statement

          Loading footer...