There are obviously tons of reasons why replications and invalidations might fail or be delayed in an activation process. This page will document the expected case and maybe give you some pointers where to look at. If this page helped you, do support it by clicking on the annoying features everywhere :)
Expected Author log on Author to Publish activation:
16.02.2022 09:00:44.305 *INFO* [192.168.0.4 [1644998444303] POST /bin/replicate HTTP/1.1] com.day.cq.replication.impl.ReplicatorImpl Setting up replication with options: ReplicationOptions{synchronous=false, revision='null', suppressStatusUpdate=false, suppressVersions=false, filter=null, aggregateHandler=null}
16.02.2022 09:00:44.306 *INFO* [192.168.0.4 [1644998444303] POST /bin/replicate HTTP/1.1] com.day.cq.wcm.core.impl.VersionManagerImpl Refuse to create new version for unmodified page /content/weretail/en.
16.02.2022 09:00:44.307 *INFO* [192.168.0.4 [1644998444303] POST /bin/replicate HTTP/1.1] com.day.cq.replication.Agent.publish Creating content for path /content/weretail/en
16.02.2022 09:00:44.313 *INFO* [192.168.0.4 [1644998444303] POST /bin/replicate HTTP/1.1] com.day.cq.replication.impl.ReplicationContentFactoryProviderImpl Created new repository content at /var/replication/data/9b472eb6-586d-45e1-95af-156e54d2d19c/fc/fce2956a-8714-45cc-aec7-0818298afb6e (size=2728, lastmod=2022-02-16T09:00:44.000+01:00)
16.02.2022 09:00:44.330 *INFO* [192.168.0.4 [1644998444303] POST /bin/replicate HTTP/1.1] com.day.cq.replication.Agent.publish.queue Replication request queued for publish at /content/weretail/en.
16.02.2022 09:00:44.333 *INFO* [192.168.0.4 [1644998444303] POST /bin/replicate HTTP/1.1] com.day.cq.replication.impl.ReplicatorImpl Processed replication: setup 0ms, checked 0ms, pre 2ms, build 8ms, queued 15ms, status 3ms, total 28ms
16.02.2022 09:00:44.346 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish.queue Processing job for agent publish
16.02.2022 09:00:44.357 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish Sending POST request to http://publish.example.com:8080/bin/receive?sling:authRequestLogin=1
16.02.2022 09:00:44.657 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish sent. Response: 200 OK
16.02.2022 09:00:44.657 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish ------------------------------------------------
16.02.2022 09:00:44.657 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish Sending message to publish.example.com:8080
16.02.2022 09:00:44.657 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish >> POST /bin/receive HTTP/1.0
16.02.2022 09:00:44.657 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish >> Action: Activate
16.02.2022 09:00:44.657 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish >> Path: /content/weretail/en
16.02.2022 09:00:44.657 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish >> Handle: /content/weretail/en
16.02.2022 09:00:44.657 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish >> Referer: about:blank
16.02.2022 09:00:44.657 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish >> ...spooling 2728 bytes...
16.02.2022 09:00:44.657 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish --
16.02.2022 09:00:44.657 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish << HTTP/1.1 200 OK
16.02.2022 09:00:44.657 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish << Connection: keep-alive
16.02.2022 09:00:44.657 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish << X-Content-Type-Options: nosniff
16.02.2022 09:00:44.657 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish << X-Frame-Options: SAMEORIGIN
16.02.2022 09:00:44.657 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish << Content-Type: text/plain;charset=utf-8
16.02.2022 09:00:44.657 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish << Content-Length: 30
16.02.2022 09:00:44.657 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish << Date: Wed, 16 Feb 2022 08:00:44 GMT
16.02.2022 09:00:44.657 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish <<
16.02.2022 09:00:44.657 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish << ReplicationAction ACTIVATE ok.
16.02.2022 09:00:44.657 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish Message sent.
16.02.2022 09:00:44.657 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish ------------------------------------------------
16.02.2022 09:00:44.657 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish Replication (ACTIVATE) of /content/weretail/en successful.
16.02.2022 09:00:44.660 *INFO* [sling-threadpool-fb6951f3-3164-45e8-a29e-2688b93dfc82-(apache-sling-job-thread-pool)-6-com_day_cq_replication_job_publish(com/day/cq/replication/job/publish)] com.day.cq.replication.Agent.publish.queue Job for agent publish processed in 313ms. Ok.
Expected Publish log on Author to Publish activation (non debug):
16.02.2022 08:07:33.107 *INFO* [192.168.0.5 [1644998853041] POST /bin/receive HTTP/1.1] com.day.cq.replication.impl.content.durbo.DurboImporter imported content in 64ms for durbo request on path: /content/weretail/en 16.02.2022 08:07:33.107 *INFO* [192.168.0.5 [1644998853041] POST /bin/receive HTTP/1.1] com.day.cq.replication.impl.servlets.ReplicationServlet Processed replication action in 64ms: ACTIVATE of /content/weretail/en
Expected Publish log on Publish to Dispatcher invalidation
16.02.2022 08:07:35.139 *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@49249bc1, aggregateHandler=null}
16.02.2022 08:07:35.140 *INFO* [Adobe Granite ChainReplicationService Processor] com.day.cq.replication.Agent.flush Creating content for path /content/weretail/en
16.02.2022 08:07:35.147 *INFO* [Adobe Granite ChainReplicationService Processor] com.day.cq.replication.Agent.flush.queue Replication request queued for flush at /content/weretail/en.
16.02.2022 08:07:35.226 *INFO* [Adobe Granite ChainReplicationService Processor] com.day.cq.replication.Agent.flush-old.queue Replication request queued for flush-old at /content/weretail/en.
16.02.2022 08:07:35.226 *INFO* [Adobe Granite ChainReplicationService Processor] com.day.cq.replication.impl.ReplicatorImpl Processed replication: setup 0ms, checked 0ms, pre 1ms, build 0ms, queued 86ms, status 0ms, total 87ms
16.02.2022 08:07:35.226 *INFO* [Adobe Granite ChainReplicationService Processor] com.day.cq.replication.impl.ChainReplicationService Chain-Replicated ACTIVATE of /content/weretail/en
16.02.2022 08:07:35.255 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old.queue Processing job for agent flush-old
16.02.2022 08:07:35.255 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old Sending GET request to http://www.example.com:80/dispatcher/invalidate.cache
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old sent. Response: 200 OK
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old ------------------------------------------------
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old Sending message to www.example.com:80
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old >> GET /dispatcher/invalidate.cache HTTP/1.0
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old >> CQ-Action: Activate
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old >> CQ-Handle: /content/weretail/en
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old >> CQ-Path: /content/weretail/en
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old >> Referer: about:blank
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old >> Content-Length: 0
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old >> Content-Type: application/octet-stream
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old --
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old << HTTP/1.1 200 OK
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old << Date: Wed, 16 Feb 2022 08:07:35 GMT
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old << Server: Apache/2.4.6 (CentOS) OpenSSL/1.0.2k-fips mod_auth_kerb/5.4 PHP/5.4.16 SVN/1.7.14 Communique/4.2.3
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old << Strict-Transport-Security: max-age=15768000
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old << Cache-Control: max-age=2592000
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old << Expires: Fri, 18 Mar 2022 08:07:35 GMT
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old << Content-Length: 13
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old << Content-Type: text/html; charset=UTF-8
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old <<
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old <<
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old Message sent.
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old ------------------------------------------------
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old Replication (ACTIVATE) of /content/weretail/en successful.
16.02.2022 08:07:35.279 *INFO* [sling-threadpool-0587a13c-c1dd-4980-92fb-8f09835a557a-(apache-sling-job-thread-pool)-4-com_day_cq_replication_job_flush-old(com/day/cq/replication/job/flush-old)] com.day.cq.replication.Agent.flush-old.queue Job for agent flush-old processed in 24ms. Ok.
Pointers:
- Check the timing of the Chain Replication. If the timing is not in milliseconds and a sequential processing is set up, the items can queue up in the sling job queue but not show up in the flush agent queue.