Expand my Community achievements bar.

Don’t miss the AEM Skill Exchange in SF on Nov 14—hear from industry leaders, learn best practices, and enhance your AEM strategy with practical tips.
SOLVED

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

Avatar

Level 2

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.

1 Accepted Solution

Avatar

Correct answer by
Level 2

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 @Jörg_Hoh @EstebanBustamante 

 

 

View solution in original post

9 Replies

Avatar

Community Advisor

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



Esteban Bustamante

Avatar

Employee Advisor

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.

Avatar

Level 2

@Jörg_Hoh 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

Avatar

Employee Advisor

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

Avatar

Level 2

@Jörg_Hoh 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

Avatar

Employee Advisor

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.

Avatar

Level 2

@Jörg_Hoh  Adding screen shots of the replication agent on the publisher that does not work on the regular replication but on the replication events:

And in the logs of this agent I see the invalidate.cache without the author activated pages though I see some author activated pages/exp fragments as well:

2023-06-16 18:27:07 - INFO - dispatcher2uswest1Agent : ------------------------------------------------
2023-06-16 18:27:07 - INFO - dispatcher2uswest1Agent : Replication (TEST) of /content successful.
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : Creating content for path /content
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : Create new HttpClient for dispatcher2uswest1Agent
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : * HTTP Version: 1.1
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : * Connect Timeout: 900000
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : * Socket Timeout: 900000
2023-06-16 18:36:02 - DEBUG - dispatcher2uswest1Agent : adding header: CQ-Action:Test
2023-06-16 18:36:02 - DEBUG - dispatcher2uswest1Agent : adding header: CQ-Handle:/content
2023-06-16 18:36:02 - DEBUG - dispatcher2uswest1Agent : adding header: CQ-Path:/content
2023-06-16 18:36:02 - DEBUG - dispatcher2uswest1Agent : adding header: Host:flush
2023-06-16 18:36:02 - DEBUG - dispatcher2uswest1Agent : deserialize content for delivery
2023-06-16 18:36:02 - DEBUG - dispatcher2uswest1Agent : No message body: Content ReplicationContent.VOID is empty
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : Sending GET request to http://10.55.0.106:80/dispatcher/invalidate.cache
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : sent. Response: 200 OK
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : ------------------------------------------------
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : Sending message to 10.55.0.106:80
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : >> GET /dispatcher/invalidate.cache HTTP/1.0
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : >> CQ-Action: Test
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : >> CQ-Handle: /content
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : >> CQ-Path: /content
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : >> Referer: about:blank
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : >> Content-Length: 0
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : >> Content-Type: application/octet-stream
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : >> Host: flush
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : --
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : << HTTP/1.1 200 OK
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : << Date: Fri, 16 Jun 2023 18:36:02 GMT
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : << Server: Apache
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : << X-Dispatcher: dispatcher2uswest1
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : << X-Vhost: flush
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : << Content-Length: 13
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : << Content-Type: text/html; charset=UTF-8
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : <<
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : <<
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : Message sent.
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : ------------------------------------------------
2023-06-16 18:36:02 - INFO - dispatcher2uswest1Agent : Replication (TEST) of /content successful.

Screen Shot 2023-06-16 at 2.27.15 PM.pngScreen Shot 2023-06-16 at 2.27.26 PM.pngScreen Shot 2023-06-16 at 2.27.22 PM.pngScreen Shot 2023-06-16 at 2.26.59 PM.png

Avatar

Level 2

Seen this New relic header: in the test call below:

X-NewRelic-App-Data: PxQFVFJbDQYBR1BSDgUGU1QJBgdASkE1VQBsEFlWR1NQEVAOXz0cMQhfWQY6TEpWUwEIFFITG1ZKARoDTFZTUAFVC1YLChgCH0cMBwZQCgAFAg4FVFMKUFJVQ05RUFsVAWw=

 

Is it possible that NewRelic is sending test requests. I could not find any other monitoring service doing a replication test so far:

 

16.06.2023 00:01:36.273 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.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@17b8f4a4, aggregateHandler=null}
16.06.2023 00:01:36.273 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 Creating content for path /content
16.06.2023 00:01:36.274 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 Create new HttpClient for publish2uswest1Agent
16.06.2023 00:01:36.274 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 * Auth User: admin
16.06.2023 00:01:36.274 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 * HTTP Version: 1.1
16.06.2023 00:01:36.274 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 * Connect Timeout: 900000
16.06.2023 00:01:36.274 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 * Socket Timeout: 900000
16.06.2023 00:01:36.274 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 Sending POST request to http://10.55.0.124:4503/bin/receive?sling:authRequestLogin=1&binaryless=true
16.06.2023 00:01:36.280 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 sent. Response: 200
16.06.2023 00:01:36.280 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 ------------------------------------------------
16.06.2023 00:01:36.280 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 Sending message to 10.55.0.124:4503
16.06.2023 00:01:36.280 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 >> POST /bin/receive HTTP/1.0
16.06.2023 00:01:36.280 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 >> Action: Test
16.06.2023 00:01:36.280 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 >> Path: /content
16.06.2023 00:01:36.280 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 >> Handle: /content
16.06.2023 00:01:36.280 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 >> Referer: about:blank
16.06.2023 00:01:36.280 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 >> Content-Length: 0
16.06.2023 00:01:36.280 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 >> Content-Type: application/octet-stream
16.06.2023 00:01:36.280 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 --
16.06.2023 00:01:36.280 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 << HTTP/1.1 200 OK
16.06.2023 00:01:36.280 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 << Date: Fri, 16 Jun 2023 00:01:36 GMT
16.06.2023 00:01:36.280 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 << X-Content-Type-Options: nosniff
16.06.2023 00:01:36.280 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 << X-Frame-Options: SAMEORIGIN
16.06.2023 00:01:36.280 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 << Content-Type: text/plain;charset=utf-8
16.06.2023 00:01:36.280 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 << X-NewRelic-App-Data: PxQFVFJbDQYBR1BSDgUGU1QJBgdASkE1VQBsEFlWR1NQEVAOXz0cMQhfWQY6TEpWUwEIFFITG1ZKARoDTFZTUAFVC1YLChgCH0cMBwZQCgAFAg4FVFMKUFJVQ05RUFsVAWw=
16.06.2023 00:01:36.280 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 << Content-Length: 26
16.06.2023 00:01:36.280 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 <<
16.06.2023 00:01:36.280 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 << ReplicationAction TEST ok.
16.06.2023 00:01:36.280 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 Message sent.
16.06.2023 00:01:36.281 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 ------------------------------------------------
16.06.2023 00:01:36.281 *INFO* [[0:0:0:0:0:0:0:1] [1686873696271] GET /etc/replication/agents.author/publish2uswest1.test.html HTTP/1.1] com.day.cq.replication.Agent.publish2uswest1 Replication (TEST) of /content successful.

Avatar

Correct answer by
Level 2

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 @Jörg_Hoh @EstebanBustamante