Cannot sync two AEM 6.4 instances

[dandinu]

Hi guys,

I've been trying to sync two AEM systems using Grabbit and everything seems to be installed properly and active in the bundles on both systems. I can succesfully trigger a job, but after I check /CRX/DE, the content is not synced. Here is my info and what I am trying to do.

What version of AEM are you running?
AEM 6.4.1 with Grabbit 7.1.5

How do you produce the issue?
I installed Grabbit 7.1.5 on both machines and I configured the following config.json on the server:

{
    "serverUsername" : "admin",
    "serverPassword" : "admin",
    "serverHost" : "test-server",
    "serverScheme" : "https",
    "serverPort" : "443",
    "batchSize" : 150,
    "deltaContent" : false,
    "pathConfigurations" :  [
        {
            "path" : "/etc/designs/test-server/clienlibs/test",
            "batchSize" : 50
        }
    ]
}

I run the following command on the same server where the config.json is, and I succesfully trigger a job:
curl -v -X PUT --header 'Content-Type: text/plain' --data-binary @/mnt/crx/author/grabbit/config.json -u admin:admin http://test-client:4502/grabbit/job

* About to connect() to test-client port 4502 (#0)
*   Trying 35.167.4.193...
* Connected to test-client (35.167.4.193) port 4502 (#0)
* Server auth using Basic with user 'admin'
> PUT /grabbit/job HTTP/1.1
> Authorization: Basic YWRtaW46YWRtaW4=
> User-Agent: curl/7.29.0
> Host: test-client:4502
> Accept: */*
> Content-Type: text/plain
> Content-Length: 421
>
* upload completely sent off: 421 out of 421 bytes
< HTTP/1.1 200 OK
< Date: Wed, 17 Apr 2019 16:24:00 GMT
< X-Content-Type-Options: nosniff
< Set-Cookie: cq-authoring-mode=TOUCH;Path=/;Expires=Wed, 24-Apr-2019 16:24:00 GMT;Max-Age=604800
< Expires: Thu, 01 Jan 1970 00:00:00 GMT
< Content-Type: application/json
< GRABBIT_TRANSACTION_ID: 3497236261045048571
< Content-Length: 21
<
* Connection #0 to host test-client left intact

This is what the test-client reports after receiving the config.json:

17.04.2019 11:54:08.481 *INFO* [18.144.0.58 [1555516448434] PUT /grabbit/job HTTP/1.1] com.twcable.grabbit.client.batch.ClientBatchJob Kicked off job with ID : 6678845723766088911
17.04.2019 11:54:08.481 *INFO* [18.144.0.58 [1555516448434] PUT /grabbit/job HTTP/1.1] com.twcable.grabbit.client.servlets.GrabbitJobServlet Jobs started : [6678845723766088911]
17.04.2019 11:54:08.481 *INFO* [18.144.0.58 [1555516448434] PUT /grabbit/job HTTP/1.1] com.twcable.grabbit.client.servlets.GrabbitJobServlet Transaction started 4251115638747771147
17.04.2019 11:54:08.486 *INFO* [clientJobLauncherTaskExecutor-1] com.twcable.grabbit.client.batch.ClientBatchJobExecutionListener Starting job : JobExecution: id=6678845723766088911, version=1, startTime=Wed Apr 17 11:54:08 EDT 2019, endTime=null, lastUpdated=Wed Apr 17 11:54:08 EDT 2019, status=STARTED, exitStatus=exitCode=UNKNOWN;exitDescription=, job=[JobInstance: id=11, version=0, Job=[clientJob]], jobParameters=[{serverPassword=admin, deleteBeforeWrite=false, scheme=https, port=443, transactionID=4251115638747771147, clientUsername=admin, excludePaths=, workflowConfigIds=, batchSize=50, timestamp=1555516448467, serverUsername=admin, host=test-server, pathDeltaContent=false, path=/etc/designs/test-server/clienlibs/test}]


17.04.2019 11:54:08.508 *INFO* [clientJobLauncherTaskExecutor-1] com.twcable.grabbit.client.batch.steps.workflows.WorkflowOffTasklet WorkflowConfig : 
17.04.2019 11:54:08.508 *INFO* [clientJobLauncherTaskExecutor-1] com.twcable.grabbit.client.batch.steps.workflows.WorkflowOffTasklet Nothing to process...
17.04.2019 11:54:08.528 *INFO* [clientJobLauncherTaskExecutor-1] com.twcable.grabbit.client.batch.steps.workspace.DeleteBeforeWriteDecider Will retain nodes under job path for 6678845723766088911...
17.04.2019 11:55:08.645 *INFO* [clientJobLauncherTaskExecutor-1] com.twcable.grabbit.client.batch.ClientBatchJobExecutionListener Cleanup : JobExecution: id=6678845723766088911, version=1, startTime=Wed Apr 17 11:54:08 EDT 2019, endTime=Wed Apr 17 11:55:08 EDT 2019, lastUpdated=Wed Apr 17 11:54:08 EDT 2019, status=FAILED, exitStatus=exitCode=FAILED;exitDescription=, job=[JobInstance: id=11, version=0, Job=[clientJob]], jobParameters=[{serverPassword=admin, deleteBeforeWrite=false, scheme=https, port=443, transactionID=4251115638747771147, clientUsername=admin, excludePaths=, workflowConfigIds=, batchSize=50, timestamp=1555516448467, serverUsername=admin, host=test-server, pathDeltaContent=false, path=/etc/designs/test-server/clienlibs/test}] . Job Complete. Releasing session, and input stream
17.04.2019 11:55:08.649 *INFO* [clientJobLauncherTaskExecutor-1] com.twcable.grabbit.client.batch.ClientBatchJobExecutionListener Grab from test-server for Current Path /etc/designs/test-server/clienlibs/test took : 60164 milliseconds


17.04.2019 12:00:42.695 *INFO* [18.144.0.58 [1555516842644] PUT /grabbit/job HTTP/1.1] com.twcable.grabbit.client.batch.ClientBatchJob Kicked off job with ID : 6569392098779498180
17.04.2019 12:00:42.695 *INFO* [18.144.0.58 [1555516842644] PUT /grabbit/job HTTP/1.1] com.twcable.grabbit.client.servlets.GrabbitJobServlet Jobs started : [6569392098779498180]
17.04.2019 12:00:42.695 *INFO* [18.144.0.58 [1555516842644] PUT /grabbit/job HTTP/1.1] com.twcable.grabbit.client.servlets.GrabbitJobServlet Transaction started 6876129364447537021
17.04.2019 12:00:42.701 *INFO* [clientJobLauncherTaskExecutor-2] com.twcable.grabbit.client.batch.ClientBatchJobExecutionListener Starting job : JobExecution: id=6569392098779498180, version=1, startTime=Wed Apr 17 12:00:42 EDT 2019, endTime=null, lastUpdated=Wed Apr 17 12:00:42 EDT 2019, status=STARTED, exitStatus=exitCode=UNKNOWN;exitDescription=, job=[JobInstance: id=12, version=0, Job=[clientJob]], jobParameters=[{serverPassword=admin, deleteBeforeWrite=false, scheme=https, port=443, transactionID=6876129364447537021, clientUsername=admin, excludePaths=, workflowConfigIds=, batchSize=50, timestamp=1555516842680, serverUsername=aem_admin, host=test-server, pathDeltaContent=false, path=/etc/designs/test-server/clienlibs/test}]


17.04.2019 12:00:42.724 *INFO* [clientJobLauncherTaskExecutor-2] com.twcable.grabbit.client.batch.steps.workflows.WorkflowOffTasklet WorkflowConfig : 
17.04.2019 12:00:42.724 *INFO* [clientJobLauncherTaskExecutor-2] com.twcable.grabbit.client.batch.steps.workflows.WorkflowOffTasklet Nothing to process...
17.04.2019 12:00:42.744 *INFO* [clientJobLauncherTaskExecutor-2] com.twcable.grabbit.client.batch.steps.workspace.DeleteBeforeWriteDecider Will retain nodes under job path for 6569392098779498180...
17.04.2019 12:01:42.808 *INFO* [clientJobLauncherTaskExecutor-2] com.twcable.grabbit.client.batch.ClientBatchJobExecutionListener Cleanup : JobExecution: id=6569392098779498180, version=1, startTime=Wed Apr 17 12:00:42 EDT 2019, endTime=Wed Apr 17 12:01:42 EDT 2019, lastUpdated=Wed Apr 17 12:00:42 EDT 2019, status=FAILED, exitStatus=exitCode=FAILED;exitDescription=, job=[JobInstance: id=12, version=0, Job=[clientJob]], jobParameters=[{serverPassword=admin, deleteBeforeWrite=false, scheme=https, port=443, transactionID=6876129364447537021, clientUsername=admin, excludePaths=, workflowConfigIds=, batchSize=50, timestamp=1555516842680, serverUsername=aem_admin, host=test-server, pathDeltaContent=false, path=/etc/designs/test-server/clienlibs/test}] . Job Complete. Releasing session, and input stream
17.04.2019 12:01:42.812 *INFO* [clientJobLauncherTaskExecutor-2] com.twcable.grabbit.client.batch.ClientBatchJobExecutionListener Grab from test-server for Current Path /etc/designs/test-server/clienlibs/test took : 60112 milliseconds

The job is reported as FAILED and I do not know why.

Does the issue occur consistently?
Yes, I am not able to sync the folder at all. here is what it looks like in ./grabbit.sh:

Job when running:

{
    "endTime": null,
    "exitStatus": {
        "exitCode": "UNKNOWN",
        "exitDescription": "",
        "running": true
    },
    "jcrNodesWritten": -1,
    "jobExecutionId": 6281385809563395306,
    "path": "/etc/designs/test-server/clienlibs/test",
    "startTime": "2019-04-17T16:57:29+0000",
    "timeTaken": -1,
    "transactionID": 1245169299603729269
}

Job when FAILED:

{
    "endTime": "2019-04-17T16:58:29+0000",
    "exitStatus": {
        "exitCode": "FAILED",
        "exitDescription": "",
        "running": false
    },
    "jcrNodesWritten": -1,
    "jobExecutionId": 6281385809563395306,
    "path": "/etc/designs/test-server/clienlibs/test",
    "startTime": "2019-04-17T16:57:29+0000",
    "timeTaken": 60161,
    "transactionID": 1245169299603729269
}

Help pointing in the right direction
Do you guys have any idea what I should be looking at? I have been poking at this for about two days and I can't figure out what's wrong. I'm really hoping someone can point me in the right direction.

[sivaprasad504]

I faced similar issues.. did you check the grabbit bundle active and running on source and destination servers? check by hitting http://server:port/grabbit/job/all on both servers. if both are running then to get the real error message go to configMgr and enable debug logging for grabbitrecevice and aem error.log. those logs will help you in identifying the root cause of the failure.

[dandinu]

Thanks for pointing out the DEBUG selection in configMgr @sivaprasad504. I went in and I checked the /grabbit/job/all on boths systems:
The server displays this (which is normal, since there are were never jobs running on it):

[]

the client displays this (which is fine, since all the jobs are supposed to run on this client, but the FAILED status still exists):

[{
	"transactionID": 1245169299603729269,
	"jobExecutionId": 6281385809563395306,
	"jcrNodesWritten": -1,
	"exitStatus": {
		"exitDescription": "",
		"exitCode": "FAILED",
		"running": false
	},
	"endTime": "2019-04-17T16:58:29+0000",
	"timeTaken": 60161,
	"path": "/etc/designs/test-server/clienlibs/test",
	"startTime": "2019-04-17T16:57:29+0000"
}, {
	"transactionID": 3497236261045048571,
	"jobExecutionId": 1421731600700547502,
	"jcrNodesWritten": -1,
	"exitStatus": {
		"exitDescription": "",
		"exitCode": "FAILED",
		"running": false
	},
	"endTime": "2019-04-17T16:25:00+0000",
	"timeTaken": 60167,
	"path": "/etc/designs/test-server/clienlibs/test",
	"startTime": "2019-04-17T16:24:00+0000"
}, {
	"transactionID": 9051892489963492825,
	"jobExecutionId": 6799961264675336536,
	"jcrNodesWritten": -1,
	"exitStatus": {
		"exitDescription": "",
		"exitCode": "FAILED",
		"running": false
	},
	"endTime": "2019-04-17T16:12:30+0000",
	"timeTaken": 60170,
	"path": "/etc/designs/test-server/clienlibs/test",
	"startTime": "2019-04-17T16:11:30+0000"
}, {
	"transactionID": 6876129364447537021,
	"jobExecutionId": 6569392098779498180,
	"jcrNodesWritten": -1,
	"exitStatus": {
		"exitDescription": "",
		"exitCode": "FAILED",
		"running": false
	},
	"endTime": "2019-04-17T16:01:42+0000",
	"timeTaken": 60112,
	"path": "/etc/designs/test-server/clienlibs/test",
	"startTime": "2019-04-17T16:00:42+0000"
}, {
	"transactionID": 4251115638747771147,
	"jobExecutionId": 6678845723766088911,
	"jcrNodesWritten": -1,
	"exitStatus": {
		"exitDescription": "",
		"exitCode": "FAILED",
		"running": false
	},
	"endTime": "2019-04-17T15:55:08+0000",
	"timeTaken": 60164,
	"path": "/etc/designs/test-server/clienlibs/test",
	"startTime": "2019-04-17T15:54:08+0000"
}, {
	"transactionID": 5772235878355819451,
	"jobExecutionId": 8298874135472688390,
	"jcrNodesWritten": -1,
	"exitStatus": {
		"exitDescription": "",
		"exitCode": "FAILED",
		"running": false
	},
	"endTime": "2019-04-17T15:51:50+0000",
	"timeTaken": 60167,
	"path": "/etc/designs/test-server/clienlibs/test",
	"startTime": "2019-04-17T15:50:50+0000"
}, {
	"transactionID": 4753331250317332505,
	"jobExecutionId": 4460668948926338844,
	"jcrNodesWritten": -1,
	"exitStatus": {
		"exitDescription": "",
		"exitCode": "FAILED",
		"running": false
	}
	...
	TRIMMED FOR BREVITY

After activating the DEBUG mode in condigMgr it seems to spit out a bit more info, however still along the same line. Here is what I mean:

24.04.2019 08:28:15.811 *DEBUG* [18.144.0.58 [1556108895809] PUT /grabbit/job HTTP/1.1] com.twcable.grabbit.client.servlets.GrabbitJobServlet Input: {
    "serverUsername" : "admin",
    "serverPassword" : "admin",
    "serverHost" : "test-server",
    "serverScheme" : "https",
    "serverPort" : "443",
    "batchSize" : 150,
    "deltaContent" : false,
    "pathConfigurations" :  [
        {
            "path" : "/etc/designs/test-server/clienlibs/test",
            "batchSize" : 50
        }
    ]
}

24.04.2019 08:28:15.863 *DEBUG* [18.144.0.58 [1556108895809] PUT /grabbit/job HTTP/1.1] com.twcable.grabbit.client.batch.ClientBatchJob Current Job Params : timestamp=1556108895863,path=/etc/designs/test-server/clienlibs/test,scheme=https,host=test-server,port=443,clientUsername=admin,serverUsername=admin,serverPassword=admin,transactionID=8465422468680473942,excludePaths=,workflowConfigIds=,deleteBeforeWrite=false,pathDeltaContent=false,batchSize=50
24.04.2019 08:28:15.881 *INFO* [18.144.0.58 [1556108895809] PUT /grabbit/job HTTP/1.1] com.twcable.grabbit.client.batch.ClientBatchJob Kicked off job with ID : 7642905644041483526
24.04.2019 08:28:15.881 *INFO* [18.144.0.58 [1556108895809] PUT /grabbit/job HTTP/1.1] com.twcable.grabbit.client.servlets.GrabbitJobServlet Jobs started : [7642905644041483526]
24.04.2019 08:28:15.881 *INFO* [18.144.0.58 [1556108895809] PUT /grabbit/job HTTP/1.1] com.twcable.grabbit.client.servlets.GrabbitJobServlet Transaction started 8465422468680473942
24.04.2019 08:28:15.886 *DEBUG* [clientJobLauncherTaskExecutor-6] com.twcable.grabbit.client.batch.ClientBatchJobExecutionListener SlingRepository : com.adobe.granite.repository.impl.SlingRepositoryImpl@13fb8ca0
24.04.2019 08:28:15.891 *INFO* [clientJobLauncherTaskExecutor-6] com.twcable.grabbit.client.batch.ClientBatchJobExecutionListener Starting job : JobExecution: id=7642905644041483526, version=1, startTime=Wed Apr 24 08:28:15 EDT 2019, endTime=null, lastUpdated=Wed Apr 24 08:28:15 EDT 2019, status=STARTED, exitStatus=exitCode=UNKNOWN;exitDescription=, job=[JobInstance: id=16, version=0, Job=[clientJob]], jobParameters=[{serverPassword=admin, deleteBeforeWrite=false, scheme=https, port=443, transactionID=8465422468680473942, clientUsername=admin, excludePaths=, workflowConfigIds=, batchSize=50, timestamp=1556108895863, serverUsername=admin, host=test-server, pathDeltaContent=false, path=/etc/designs/test-server/clienlibs/test}]


24.04.2019 08:28:15.891 *DEBUG* [clientJobLauncherTaskExecutor-6] com.twcable.grabbit.client.batch.steps.validation.ValidJobDecider com.twcable.grabbit.client.batch.steps.validation.ValidJobDecider Job determined to be valid for job path /etc/designs/test-server/clienlibs/test
24.04.2019 08:28:15.918 *INFO* [clientJobLauncherTaskExecutor-6] com.twcable.grabbit.client.batch.steps.workflows.WorkflowOffTasklet WorkflowConfig :
24.04.2019 08:28:15.919 *INFO* [clientJobLauncherTaskExecutor-6] com.twcable.grabbit.client.batch.steps.workflows.WorkflowOffTasklet Nothing to process...
24.04.2019 08:28:15.938 *INFO* [clientJobLauncherTaskExecutor-6] com.twcable.grabbit.client.batch.steps.workspace.DeleteBeforeWriteDecider Will retain nodes under job path for 7642905644041483526...
24.04.2019 08:28:30.578 *DEBUG* [18.144.0.58 [1556108910571] GET /grabbit/job/7642905644041483526.json HTTP/1.1] com.twcable.grabbit.client.servlets.GrabbitJobServlet Current Status : {"transactionID":8465422468680473942,"jobExecutionId":7642905644041483526,"jcrNodesWritten":-1,"exitStatus":{"exitDescription":"","exitCode":"UNKNOWN","running":true},"endTime":null,"timeTaken":-1,"path":"/etc/designs/test-server/clienlibs/test","startTime":"2019-04-24T12:28:15+0000"}
24.04.2019 08:29:13.661 *DEBUG* [18.144.0.58 [1556108953656] GET /grabbit/job/7642905644041483526.json HTTP/1.1] com.twcable.grabbit.client.servlets.GrabbitJobServlet Current Status : {"transactionID":8465422468680473942,"jobExecutionId":7642905644041483526,"jcrNodesWritten":-1,"exitStatus":{"exitDescription":"","exitCode":"UNKNOWN","running":true},"endTime":null,"timeTaken":-1,"path":"/etc/designs/test-server/clienlibs/test","startTime":"2019-04-24T12:28:15+0000"}
24.04.2019 08:29:16.047 *INFO* [clientJobLauncherTaskExecutor-6] com.twcable.grabbit.client.batch.ClientBatchJobExecutionListener Cleanup : JobExecution: id=7642905644041483526, version=1, startTime=Wed Apr 24 08:28:15 EDT 2019, endTime=Wed Apr 24 08:29:16 EDT 2019, lastUpdated=Wed Apr 24 08:28:15 EDT 2019, status=FAILED, exitStatus=exitCode=FAILED;exitDescription=, job=[JobInstance: id=16, version=0, Job=[clientJob]], jobParameters=[{serverPassword=admin, deleteBeforeWrite=false, scheme=https, port=443, transactionID=8465422468680473942, clientUsername=admin, excludePaths=, workflowConfigIds=, batchSize=50, timestamp=1556108895863, serverUsername=admin, host=test-server, pathDeltaContent=false, path=/etc/designs/test-server/clienlibs/test}] . Job Complete. Releasing session, and input stream
24.04.2019 08:29:16.051 *INFO* [clientJobLauncherTaskExecutor-6] com.twcable.grabbit.client.batch.ClientBatchJobExecutionListener Grab from test-server for Current Path /etc/designs/test-server/clienlibs/test took : 60166 milliseconds


24.04.2019 08:29:21.977 *DEBUG* [18.144.0.58 [1556108961972] GET /grabbit/job/7642905644041483526.json HTTP/1.1] com.twcable.grabbit.client.servlets.GrabbitJobServlet Current Status : {"transactionID":8465422468680473942,"jobExecutionId":7642905644041483526,"jcrNodesWritten":-1,"exitStatus":{"exitDescription":"","exitCode":"FAILED","running":false},"endTime":"2019-04-24T12:29:16+0000","timeTaken":60166,"path":"/etc/designs/test-server/clienlibs/test","startTime":"2019-04-24T12:28:15+0000"}
24.04.2019 08:39:22.059 *WARN* [18.144.0.58 [1556109562058] GET /grabbit/job/.json HTTP/1.1] com.twcable.grabbit.client.servlets.GrabbitJobServlet Bad request to receive job status for : /grabbit/job/.json. A job ID was not provided in the request.

I'm starting to believe this is some sort of silent timeout error, or something that I do not fully know how to track down. Do you guys know if that might be the case?

[sivaprasad504]

Exactly I have faced all these and were able to fix.. it's a default timeout issue. Update timeout setting on both source and destination servers by going to configmgr and search for something with http jetty and update from default 60000 ms which is one hr to 10hrs by adding a zero to it. You will be all set to happy grabbing from then 😀

[sivaprasad504]

Exactly I have faced all these and were able to fix.. it's a default timeout issue. Update timeout setting on both source and destination servers by going to configmgr and search for something with http jetty and update from default 60000 ms which is one hr to 10hrs by adding a zero to it. You will be all set to happy grabbing from then 😀

[dandinu]

Alright, one of the main reasons why the job was always taking around 60 sec, was because of the timeout issue. @sivaprasad504 you had a great suggestion to check that out, because I saw my test-server firewall was blocking the test-client from connecting back.

The funny thing is, now the job fails instantly (156 miliseconds). I would say this is progress, but I am still in the dark about the exact reason:

{
    "endTime": "2019-04-25T16:10:16+0000",
    "exitStatus": {
        "exitCode": "FAILED",
        "exitDescription": "",
        "running": false
    },
    "jcrNodesWritten": -1,
    "jobExecutionId": 1006534669009632152,
    "path": "/etc/designs/test-server/clienlibs/test",
    "startTime": "2019-04-25T16:10:16+0000",
    "timeTaken": 156,
    "transactionID": 3508568264429985364
}

Is there any other more comprehensive log that I can monitor to see why this job fails? Even on DEBUG the Grabbit logs behave like everything is ok.

[dandinu]

I am starting to think that this log message tries to tell me something is wrong, but I cannot figure out what it means:

26.04.2019 08:04:19.347 *DEBUG* [clientJobLauncherTaskExecutor-10] com.twcable.grabbit.client.batch.steps.validation.ValidJobDecider com.twcable.grabbit.client.batch.steps.validation.ValidJobDecider Job determined to be valid for job path /etc/designs/test-server/clienlibs/test
26.04.2019 08:04:19.374 *INFO* [clientJobLauncherTaskExecutor-10] com.twcable.grabbit.client.batch.steps.workflows.WorkflowOffTasklet WorkflowConfig : 
26.04.2019 08:04:19.374 *INFO* [clientJobLauncherTaskExecutor-10] com.twcable.grabbit.client.batch.steps.workflows.WorkflowOffTasklet Nothing to process...
26.04.2019 08:04:19.392 *INFO* [clientJobLauncherTaskExecutor-10] com.twcable.grabbit.client.batch.steps.workspace.DeleteBeforeWriteDecider Will retain nodes under job path for 1781941111019933516...

[sivaprasad504]

AEM error logshould give you more details on the error, which I'm guessing would be on the timeout of jetty http request. go to configMgr and increase that to few hours and try again.

Note: this needs to be done on both source and destination servers.

[srikrishnasai]

Hi @dandinu Can you share following packages if possible i have been trying to get but the links were outdated.

1. Sun-Misc-Fragment-Bundle-1.0.0
2. Grabbit-Apache-Sling-Login-Whitelist-1.0
3. Grabbit-Deserialization-Firewall-Configuration-1.0
4. Grabbit-7.1.5

Thanks,
Krishna