Credentials are not passed from client to server

[kooroshd]

When I try to run a sync using the grabbit.sh script, the server (Grabbit sender) does not see the credentials I've entered in the configuration file ("serverUsername" and "serverPassword"). This is causing the sync to fail for JCR nodes that require authentication.

On the server when I look at the access log the request is received as "anonymous":

104.198.99.189 - anonymous 17/Oct/2017:00:53:42 -0700 "GET /grabbit/content?path=/content/sm/test-site&after=2017-10-13T21:10:00.603Z HTTP/1.1" 500 400 "-" "okhttp/3.5.0"

The job fails:

{ "transactionID": 2241996975981270300, "jobExecutionId": 2611751303286100000, "jcrNodesWritten": -1, "exitStatus": { "exitDescription": "", "exitCode": "FAILED", "running": false }, "endTime": "2017-10-17T07:53:42+0000", "timeTaken": 589, "path": "/content/sm/test-site", "startTime": "2017-10-17T07:53:42+0000" }

I'm using Grabbit 7.1.2 and AEM 6.2. I've installed all three required AEM packages. The sync works for JCR nodes that don't require authentication.

[jbornemann]

Any additional information you could provide such as sender, receiver logs?

Hmm, do you only see one anonymous request? Initially, that is to be expected. If authorization is required, the receiver is set to respond back with an Authorization header only if challenged, via an initial 401.

https://github.com/TWCable/grabbit/blob/master/src/main/groovy/com/twcable/grabbit/client/batch/steps/http/CreateHttpConnectionTasklet.groovy

[kooroshd]

I don't see any other log entries related to Grabbit in access.log on the sender side. Also, no entries in the grabbit-send.log. Below, I've pasted what I see in the grabbit-receive.log.

I installed Grabbit 7.0.2 and it works as expected. Requests for authenticated JCR nodes works fine. The problem is with version 7.1.2.

Here is the log entries from grabbit-receive.log:

19.10.2017 14:38:22.350 DEBUG [0:0:0:0:0:0:0:1 [1508449102332] PUT /grabbit/job HTTP/1.1] com.twcable.grabbit.client.servlets.GrabbitJobServlet Input: { "serverUsername": "admin", "serverPassword": "admin", "serverHost": "localhost", "serverPort": "4503", "batchSize": 250, "deltaContent": false, "pathConfigurations": [ { "path": "/content/sm/test-site" } ] } 19.10.2017 14:38:22.544 DEBUG [0:0:0:0:0:0:0:1 [1508449102332] PUT /grabbit/job HTTP/1.1] com.twcable.grabbit.client.batch.ClientBatchJob Current Job Params : timestamp=1508449102541,path=/content/sm/test-site,scheme=http,host=localhost,port=4503,clientUsername=admin,serverUsername=admin,serverPassword=admin,transactionID=5012635073117530862,excludePaths=,workflowConfigIds=,deleteBeforeWrite=false,pathDeltaContent=false,batchSize=250 19.10.2017 14:38:22.596 INFO [0:0:0:0:0:0:0:1 [1508449102332] PUT /grabbit/job HTTP/1.1] com.twcable.grabbit.client.batch.ClientBatchJob Kicked off job with ID : 15766065766841094 19.10.2017 14:38:22.596 INFO [0:0:0:0:0:0:0:1 [1508449102332] PUT /grabbit/job HTTP/1.1] com.twcable.grabbit.client.servlets.GrabbitJobServlet Jobs started : [15766065766841094] 19.10.2017 14:38:22.596 INFO [0:0:0:0:0:0:0:1 [1508449102332] PUT /grabbit/job HTTP/1.1] com.twcable.grabbit.client.servlets.GrabbitJobServlet Transaction started 5012635073117530862 19.10.2017 14:38:22.600 DEBUG [clientJobLauncherTaskExecutor-1] com.twcable.grabbit.client.batch.ClientBatchJobExecutionListener SlingRepository : com.adobe.granite.repository.impl.SlingRepositoryImpl@53e7ccbf 19.10.2017 14:38:22.611 INFO [clientJobLauncherTaskExecutor-1] com.twcable.grabbit.client.batch.ClientBatchJobExecutionListener Starting job : JobExecution: id=15766065766841094, version=1, startTime=Thu Oct 19 14:38:22 PDT 2017, endTime=null, lastUpdated=Thu Oct 19 14:38:22 PDT 2017, status=STARTED, exitStatus=exitCode=UNKNOWN;exitDescription=, job=[JobInstance: id=3, version=0, Job=[clientJob]], jobParameters=[{serverPassword=admin, deleteBeforeWrite=false, scheme=http, port=4503, transactionID=5012635073117530862, clientUsername=admin, excludePaths=, workflowConfigIds=, batchSize=250, timestamp=1508449102541, serverUsername=admin, host=localhost, pathDeltaContent=false, path=/content/sm/test-site}]

19.10.2017 14:38:22.612 DEBUG [clientJobLauncherTaskExecutor-1] com.twcable.grabbit.client.batch.steps.validation.ValidJobDecider com.twcable.grabbit.client.batch.steps.validation.ValidJobDecider Job determined to be valid for job path /content/sm/test-site 19.10.2017 14:38:22.715 INFO [clientJobLauncherTaskExecutor-1] com.twcable.grabbit.client.batch.steps.workflows.WorkflowOffTasklet WorkflowConfig : 19.10.2017 14:38:22.715 INFO [clientJobLauncherTaskExecutor-1] com.twcable.grabbit.client.batch.steps.workflows.WorkflowOffTasklet Nothing to process... 19.10.2017 14:38:22.739 INFO [clientJobLauncherTaskExecutor-1] com.twcable.grabbit.client.batch.steps.workspace.DeleteBeforeWriteDecider Will retain nodes under job path for 15766065766841094... 19.10.2017 14:38:22.906 WARN [clientJobLauncherTaskExecutor-1] com.twcable.grabbit.client.batch.steps.http.CreateHttpConnectionTasklet Received a status of 500 when attempting to create a connection to localhost. Bailing out. See debug log for more details. 19.10.2017 14:38:22.906 DEBUG [clientJobLauncherTaskExecutor-1] com.twcable.grabbit.client.batch.steps.http.CreateHttpConnectionTasklet Request to start a connection with localhost resulted in: Response{protocol=http/1.1, code=500, message=Server Error, url=http://localhost:4503/grabbit/content?path=/content/sm/test-site&after=}. 19.10.2017 14:38:22.934 INFO [clientJobLauncherTaskExecutor-1] com.twcable.grabbit.client.batch.ClientBatchJobExecutionListener Cleanup : JobExecution: id=15766065766841094, version=1, startTime=Thu Oct 19 14:38:22 PDT 2017, endTime=Thu Oct 19 14:38:22 PDT 2017, lastUpdated=Thu Oct 19 14:38:22 PDT 2017, status=FAILED, exitStatus=exitCode=FAILED;exitDescription=, job=[JobInstance: id=3, version=0, Job=[clientJob]], jobParameters=[{serverPassword=admin, deleteBeforeWrite=false, scheme=http, port=4503, transactionID=5012635073117530862, clientUsername=admin, excludePaths=, workflowConfigIds=, batchSize=250, timestamp=1508449102541, serverUsername=admin, host=localhost, pathDeltaContent=false, path=/content/sm/test-site}] . Job Complete. Releasing session, and input stream 19.10.2017 14:38:22.940 INFO [clientJobLauncherTaskExecutor-1] com.twcable.grabbit.client.batch.ClientBatchJobExecutionListener Grab from localhost for Current Path /content/sm/test-site took : 338 milliseconds

[kooroshd]

Also, here is an entry from error.log from the sender instance:

19.10.2017 14:38:22.890 ERROR [127.0.0.1 [1508449102860] GET /grabbit/content HTTP/1.1] org.apache.sling.engine.impl.SlingRequestProcessorImpl service: Uncaught Throwable javax.jcr.PathNotFoundException: Node with path /content/sm/test-site does not exist. at org.apache.jackrabbit.oak.jcr.session.SessionImpl.getNode(SessionImpl.java:305) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.apache.sling.jcr.base.SessionProxyHandler$SessionProxyInvocationHandler.invoke(SessionProxyHandler.java:116) at com.sun.proxy.$Proxy7.getNode(Unknown Source) at com.twcable.grabbit.server.services.impl.DefaultServerService$_getContentForRootPath_closure1.doCall(DefaultServerService.groovy:75) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:90) at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:324) at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:278) at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1016) at groovy.lang.Closure.call(Closure.java:423) at groovy.lang.Closure.call(Closure.java:439) at com.twcable.grabbit.jcr.JcrUtil.withSession(JcrUtil.groovy:80) at com.twcable.grabbit.server.services.impl.DefaultServerService.getContentForRootPath(DefaultServerService.groovy:64) at com.twcable.grabbit.server.GrabbitContentPullServlet.doGet(GrabbitContentPullServlet.groovy:86) at org.apache.sling.api.servlets.SlingSafeMethodsServlet.mayService(SlingSafeMethodsServlet.java:269) at org.apache.sling.api.servlets.SlingSafeMethodsServlet.service(SlingSafeMethodsServlet.java:345) at org.apache.sling.api.servlets.SlingSafeMethodsServlet.service(SlingSafeMethodsServlet.java:376) at org.apache.sling.engine.impl.request.RequestData.service(RequestData.java:546) at org.apache.sling.engine.impl.filter.SlingComponentFilterChain.render(SlingComponentFilterChain.java:44) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:77) at com.day.cq.personalization.impl.TargetComponentFilter.doFilter(TargetComponentFilter.java:96) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at com.day.cq.wcm.core.impl.WCMDebugFilter.doFilter(WCMDebugFilter.java:151) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at com.day.cq.wcm.core.impl.WCMComponentFilter.filterRootInclude(WCMComponentFilter.java:362) at com.day.cq.wcm.core.impl.WCMComponentFilter.doFilter(WCMComponentFilter.java:177) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at org.apache.sling.engine.impl.SlingRequestProcessorImpl.processComponent(SlingRequestProcessorImpl.java:282) at org.apache.sling.engine.impl.filter.RequestSlingFilterChain.render(RequestSlingFilterChain.java:49) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:77) at com.adobe.cq.social.ugcbase.security.impl.SaferSlingPostServlet.doFilter(SaferSlingPostServlet.java:114) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at com.day.cq.dam.core.impl.assetlinkshare.AdhocAssetShareAuthHandler.doFilter(AdhocAssetShareAuthHandler.java:381) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at com.day.cq.dam.core.impl.servlet.ActivityRecordHandler.doFilter(ActivityRecordHandler.java:155) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:73) at com.adobe.granite.requests.logging.impl.RequestLoggerImpl.doFilter(RequestLoggerImpl.java:114) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at com.adobe.granite.csrf.impl.CSRFFilter.doFilter(CSRFFilter.java:220) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at org.apache.sling.security.impl.ContentDispositionFilter.doFilter(ContentDispositionFilter.java:181) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at com.day.cq.wcm.core.impl.AuthoringUIModeServiceImpl.doFilter(AuthoringUIModeServiceImpl.java:292) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at com.day.cq.wcm.core.impl.warp.TimeWarpFilter.doFilter(TimeWarpFilter.java:106) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at com.day.cq.wcm.mobile.core.impl.redirect.RedirectFilter.doFilter(RedirectFilter.java:248) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at org.apache.sling.engine.impl.debug.RequestProgressTrackerLogFilter.doFilter(RequestProgressTrackerLogFilter.java:95) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at com.day.cq.analytics.provisioning.impl.UserAuthenticationRequestFilter.doFilter(UserAuthenticationRequestFilter.java:119) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at com.adobe.cq.social.commons.cors.CORSAuthenticationFilter.doFilter(CORSAuthenticationFilter.java:91) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at com.day.cq.wcm.foundation.forms.impl.FormsHandlingServlet.doFilter(FormsHandlingServlet.java:285) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at com.adobe.granite.optout.impl.OptOutFilter.doFilter(OptOutFilter.java:74) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at com.day.cq.wcm.core.impl.WCMRequestFilter.doFilter(WCMRequestFilter.java:90) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at com.adobe.cq.mcm.campaign.servlets.CampaignCopyTracker.doFilter(CampaignCopyTracker.java:100) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at org.apache.sling.rewriter.impl.RewriterFilter.doFilter(RewriterFilter.java:83) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at com.adobe.granite.httpcache.impl.InnerCacheFilter.doFilter(InnerCacheFilter.java:77) at com.adobe.granite.httpcache.impl.InnerCacheFilter.doFilter(InnerCacheFilter.java:56) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at org.apache.sling.i18n.impl.I18NFilter.doFilter(I18NFilter.java:129) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at com.adobe.granite.rest.impl.servlet.ApiResourceFilter.doFilter(ApiResourceFilter.java:67) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at org.apache.sling.bgservlets.impl.BackgroundServletStarterFilter.doFilter(BackgroundServletStarterFilter.java:169) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at com.adobe.granite.resourceresolverhelper.impl.ResourceResolverHelperImpl.doFilter(ResourceResolverHelperImpl.java:84) at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:68) at org.apache.sling.engine.impl.SlingRequestProcessorImpl.doProcessRequest(SlingRequestProcessorImpl.java:151) at org.apache.sling.engine.impl.SlingMainServlet.service(SlingMainServlet.java:216) at org.apache.felix.http.base.internal.handler.ServletHandler.handle(ServletHandler.java:85) at org.apache.felix.http.base.internal.dispatch.InvocationChain.doFilter(InvocationChain.java:79) at com.adobe.granite.license.impl.LicenseCheckFilter.doFilter(LicenseCheckFilter.java:308) at org.apache.felix.http.base.internal.handler.FilterHandler.handle(FilterHandler.java:135) at org.apache.felix.http.base.internal.dispatch.InvocationChain.doFilter(InvocationChain.java:74) at org.apache.felix.http.sslfilter.internal.SslFilter.doFilter(SslFilter.java:89) at org.apache.felix.http.base.internal.handler.FilterHandler.handle(FilterHandler.java:135) at org.apache.felix.http.base.internal.dispatch.InvocationChain.doFilter(InvocationChain.java:74) at org.apache.sling.security.impl.ReferrerFilter.doFilter(ReferrerFilter.java:290) at org.apache.felix.http.base.internal.handler.FilterHandler.handle(FilterHandler.java:135) at org.apache.felix.http.base.internal.dispatch.InvocationChain.doFilter(InvocationChain.java:74) at org.apache.sling.i18n.impl.I18NFilter.doFilter(I18NFilter.java:129) at org.apache.felix.http.base.internal.handler.FilterHandler.handle(FilterHandler.java:135) at org.apache.felix.http.base.internal.dispatch.InvocationChain.doFilter(InvocationChain.java:74) at org.apache.sling.featureflags.impl.FeatureManager.doFilter(FeatureManager.java:116) at org.apache.felix.http.base.internal.handler.FilterHandler.handle(FilterHandler.java:135) at org.apache.felix.http.base.internal.dispatch.InvocationChain.doFilter(InvocationChain.java:74) at org.apache.sling.engine.impl.log.RequestLoggerFilter.doFilter(RequestLoggerFilter.java:75) at org.apache.felix.http.base.internal.handler.FilterHandler.handle(FilterHandler.java:135) at org.apache.felix.http.base.internal.dispatch.InvocationChain.doFilter(InvocationChain.java:74) at org.apache.felix.http.base.internal.dispatch.Dispatcher.dispatch(Dispatcher.java:124) at org.apache.felix.http.base.internal.DispatcherServlet.service(DispatcherServlet.java:61) at javax.servlet.http.HttpServlet.service(HttpServlet.java:725) at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:812) at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:587) at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:221) at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127) at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515) at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:215) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) at org.eclipse.jetty.server.Server.handle(Server.java:499) at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311) at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257) at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635) at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555) at java.lang.Thread.run(Thread.java:748)

[jbornemann]

Looks like AEM 6.2 is sending back a 500 instead of a request for authorization. We might have to change to be preemptive like before

[sagarsane]

Thanks @kooroshd for pointing this our! Opened #193 ..

[jbornemann]

Try https://github.com/TWCable/grabbit/releases/tag/7.1.3-alpha @kooroshd and see if this fixes your issue