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
Jun 16, 2023 11:04 AM UTC
Solved

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

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.
eagleinhills
eagleinhillsAccepted solution
Level 2
Jun 18, 2023 7:56 PM UTC

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 

 

 

View reply

9 replies

joerghoh
joerghoh
Employee
Jun 16, 2023 1:47 PM UTC

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.

Translate
    eagleinhills
    eagleinhillsAuthor
    Level 2
    Jun 16, 2023 3:11 PM UTC

    @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

    Translate
      joerghoh
      joerghoh
      Employee
      Jun 16, 2023 3:25 PM UTC

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

      Translate
        EstebanBustamante
        EstebanBustamante
        New Participant
        Jun 16, 2023 1:30 PM UTC

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

        Translate
        Esteban Bustamante
          Terms & ConditionsAccessibility statement

          Loading footer...