Expand my Community achievements bar.

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