Reverse Replication woes - solved

Hot off the press/keyboard (i.e. not fully tested). With the help of an Adobe support engineer in Basel and an on-site Adobe consultant we discovered what the root cause of the reverse replication problem was.

Namely, that when a user voted in a poll, the new vote AND ALL previous votes were being reverse replicated. This caused a MASSIVE workload on the Author because each node in the /var/replication/outbox did not contain 1 corresponding vote; it actually contained ALL of the votes including the new additional one. This explains why the Author would take 20 minutes to process just 10 nodes in the outbox.

The root cause was in the structure we were using (has been abbreviated):-

/content
   /usergenerated
      /somepoll
         /poll1 [cq:Page]
            /jcr:content [cq:PageContent]
               /question
                  /answers
                     /1
                        /12423434
                        /12312323
                     /2
                        /23463456

Each vote is added under the /answers node as type "nt:unstructured" with the various properties. But, on each submission of a vote, the custom code (a custom SlingPostServlet) was setting the 3 magic properties (cq:distribute, jcr:lastModified & jcr:lastModifiedBy) on "/poll1/jcr:content". This causes the page "poll1" to be marked for reverse replication - and with it, all it's sub-nodes (aggregated).

The solution was to change the nodes that get created to individual pages themselves as follows :-

/content
   /usergenerated
      /somepoll
         /poll1
            /question
               /answers
                  /1
                     /12423434 [cq:Page]
                        /jcr:content [cq:PageContent]
                     /12312323 [cq:Page]
                        /jcr:content [cq:PageContent]
                  /2
                     /23463456 [cq:Page]
                        /jcr:content [cq:PageContent]

And, then to ensure that the 3 magic properties are created on the jcr:content node of each vote node. Note: DO NOT have a jcr:content node anywhere in the intermediate hierarchy because this interferes with the firing of the outbox manager (I think it sees a jcr:content node and assumes that there must be a page there but, because there isn't a page there, then it aborts - and nothing appears in the outbox. I suffered with this problem when I kept "poll1/jcr:content" in the path (i.e. /content/usergenerated/somepoll/poll1/jcr:content/question/answers/1/12423434/jcr:content).

NB, due to our environment, we needed to use a custom SlingPostServlet and start the reverse replication in our project. However, the above structure should work with the normal OOTB page manager activated reverse replication.

The HTML form to post these votes would be something like this :-

<form action="/content/usergenerated/somepoll/poll1/question/answers/1/123456789" method="post" enctype="multipart/form-data">
<input type="hidden" name="./jcr:primaryType" value="cq:Page" />
<input type="hidden" name="././jcr:content/jcr:primaryType" value="cq:PageContent" />
<input type="hidden" name="././jcr:content/answer" value="my_chosen_answer" />

<input type="hidden" name=":redirect" value='/content/website/thankyou.html' />
<button type="submit">Submit</button>
</form>

Reverse Replication woes

So, in my previous post I said how wonderful FP37434 is (the replication stabilisation FP). Unfortunately, it did not solve our problem and we now have a large volume of content to reverse replicate (~50k nodes in /var/replication/outbox across all our publish servers).

We are currently facing 2 problems. When the RR agent polls, the publish server with FP37434 exhibits a huge native memory leak (approx 8GB of native memory is being claimed) causing a great deal of paging on the system.

When we batch this down to only 10 items in the outbox, we noticed that the author takes 30 minutes to process 10 nodes.

Adding extra logging (com.day.cq.replication.content.durbo) at DEBUG level shows that the Author is doing valid work for 30 minutes processing just 10 nodes from the outbox.

It turns out that when a node is added to /content/usergenerated/path/to/something then CQ appears to be adding all of the pre-existing sibling nodes in the newly created node under /var/replication/outbox. You can see this by analysing nodes inside the outbox. This is why 10 nodes takes 30 minutes for the author to process - because it's actually unpacking 10000 nodes.

This probably also explains why our CQ author is performing slowly.

Hopefully, I will remember to post the solution here when we get to it ... :-)

Replication Stablization hotfix

If the flush agent on a publish server stops working, then you probably need cq-5.3.0-featurepack-37434. This featurepack is a nice cumulative one - so no painful installation of dependencies (phew)! And it fixes a LOT of bugs mainly around stabilizing the replication services.

We tried installing feature-pack 37434 via CRX package manager but, it broke the instance in that it would just serve up 404 pages.

However, following the below procedure, we were able to install the feature pack.

a. Install, via apache felix webconsole, the following bundles and make sure they are in the active state (start them manually if needed after installation)
- org.apache.sling.settings-1.0.3-R1067955.jar
- org.apache.sling.intaller.core-3.1.2.jar
- org.apache.sling.intaller.provider.jcr-3.0.4.jar

b. stop the instance, and drop the FP 37434 v4 into crx-quickstart/repository/install folder

c. start the instance and check that all the bundles are active as expected.

d. We also had to reset the org.apache.sling.jcr.resource.internal.JcrResourceResolverFactoryImpl.xml config to include our resource.resolver.mapping configs.

e. com.day.cq.wcm.cq-wcm-core bundle needed starting.

(NB, don't try accessing the instance too soon - monitor the log file to see when it's finished doing things. Otherwise you still get a 404 response).

Lots of data*.tar files in the author

Recently we had a major problem with the Author eating up disk space (> 110GB).

This was caused by the number of data*.tar files, in workspaces/crx.default/, increasing very rapidly BUT, the TAR Optimiser process was not able to keep up pace with it.

I asked DayCare if we could restore an online backup as a shortcut to removing the additional tar files. They said that would not help.

So, we just ran the TAR Optimiser process as much as we possibly could.

It was running at a rate of 1 tar file per 12 hours normally. But, over the weekend, that rate increased and it did manage to chew up ~200 data*.tar files. Amazing.

NB, When running the TAR Optimiser manually, I was able to set the delay from 1.0 milliseconds to 0.25 milliseconds - with a marked improvement in speed.

This delay parameter can be set in the workspace.xml file, so that it is used in your overnight schedule TAR Optimiser job, as follows :-

<PersistenceManager class="com.day.crx.persistence.tar.TarPersistenceManager">
<param name="optimizeSleep" value="0.25"/>
</PersistenceManager>

Fixing a hanging author server

So, we had a problem where the author server would hang.

It would hang for 2-3 hours after startup ("the Loading" would be displayed in the main content area). Then it would work for up to 24 hours. Then the problem would come back and last forever.

The resolution was to apply hotfix 36021 - which had just a few pre-requisites. Ones in bold were already installed but needed re-installing in the correct order.

Do not implement the FineGrainedISMLocking performance change on CRX v2.x!

Installation instructions for the 27 Adobe hotfixes

After each hotfix, slowly and carefully :-

• Check whether the bundles have stopped, if they have wait 10 minutes for them all to re-resolve & restart.
• Look at which jar versions have been installed and see if the new version number is now listed in the bundles list.
• Check if the Author application displays lists of web pages as you browse in the navigation tree
• Check if the DAM tab displays lists of assets as you browse in the navigation tree.
• Check that a web page (eg the homepage) displays ok in authoring mode.
• Check the log file for errors.

NB, A hotfix number in bold means that it is probably already installed & needs just needs re-installing.

i.	Pre-requisite: Journal & Bundle Cache configuration changes are applied.
ii.	Initial Step: Turn off the replication agents
1.	HF	28211	12.03.10
2.	HF	29626	08.06.10
3.	FP	28358-1.2	06.07.10	Add -/tmp as per package description.
4.	FP	30015-1.0	24.07.10
5.	HF	30084	29.07.10
6.	FP	29944-1.0.1	03.08.10	Restart required after this one. The shutdown always hangs. Check that all the bundles start when the server comes back up. You might need to start these bundles:- org.apache.sling.api, org.apache.sling.commons.osgi, org.apache.sling.jcr.resource, com.day.cq.workflow.cq-workflow-console
7.	FP	30397	17.08.10
8.	HF	30518	23.08.10
9.	FP	30553	27.08.10	Restart required after this one. NB this was not required on Test1 but we did it anyway.
10.	FP	31852	14.10.10
11.	FP	30035-2.0	15.10.10	A restart was required here (on test2) to pick up the new versions of the bundles.
12.	FP	29995-1.1	18.10.10	This stops 3 bundles (compat) - this is expected.
13.	FP	30532-2	17.11.10	This one takes ~10 minutes to recover the bundles.
14.	FP	31905	18.11.10
15.	FP	32186	29.11.10
16.	HF	32460	02.12.10	Restart required after this one. Is workflow-impl at 5.3.26 after 20 minutes (after the 1st restart)? Restart again 30 minutes after the first restart has returned. There was no need to do the 2nd restart on Test1. The “workflow-impl” jar needed manually starting after the restart.
17.	FP	31902-1.0	09.12.10	This one takes ~10 minutes to recover the bundles.
18.	FP	30249-3.0	10.02.11	A number of tagging & personalisation bundles stop here & then resolve themselves. Also there was a “Zip file closed” error in the logs.
19.	FP	31033-2.1	24.03.11
20.	HF	34460-1.0	25.03.11	Get a problem where the main content area in the author is not populated - this gets fixed by 34697 …
21.	FP	30815	05.04.11
22.	FP	34697-4.0	28.04.11	Many bundles stop & restart themselves here. Let it settle for 10-20 minutes.
23.	FP	34334-2.0	13.05.11	Cq-dam-core did not update to its new version number. Restart required. It needed starting manually after the restart but it had picked up the right version.
24.	STOP & TAKE A BACKUP!
25.	FP	34901-3.0	13.05.11	There is no need to implement the ‘eventadmin.jar’ workaround anymore. Wcm-core was at 5.3.68 and should go to v5.3.72. There is no need to restart, since 34901-3 (3 Oct 2011).
26.	FP	34071	19.05.11	On Perf, had to wait 10 minutes for “the Loading symptom” to disappear. On test1, 2 bundles stopped and had to wait 5 minutes to resolve themselves.
27.	FP	36021		Got a 500 error (TopLevelComponentContextImpl) when viewing web pages. A restart fixes this.
28.		33200-9.0
29.	Restart the server for good measure!
30.	Final Step: Turn on the replication agents

If I were a CQ systems administrator....

If I were a CQ systems administrator....

Write a script to monitor the repository folder. How big is it? How many tar files are in today? What is the difference between yesterday's tar files total & todays? The motivation for this is that sometimes you get a server increasing in disk space and its because the TAR optimser isn't running for long enough.

grep the logs for the "last stage" of the online backup.

similarly for the TAR optimiser completion step.

To enable logging for JSP pages

Could you also include the information on how we can add the org.apache.sling.commons.log.names values for those which are inside a jsp page. I believe the value needs to be something like apps.myapp if the center.jsp is inside apps/myapps/center.jsp.
However this is not working for me.

Hi, JSPs are compiled into packages below org.apache.jsp with the script path converted to further package parts. So in your example the /apps/myapps/center.jsp is compiled into the package: org.apache.jsp.apps.myapps.

Thus the logger must be setup with this prefixed package.