Exchange Synchronization error

Hello, 

We use Exchange Synchronization but the syncengine stops working intermittently at night around 1 AM... 

The synchronization then starts to work again when we restart Tomcat service.

This post looks similar.

Here are the logs : 

exchangesyncengine

ERROR [SyncEngine thread]: [26-févr.-2022 00:50:30.401] com.sage.scrm.syncengine.core.engine.error.SageSyncEngineException: com.sage.scrm.syncengine.exchange.engine.model.error.SageSDataEndpointException: com.sage.crm.httpconsumer.error.SageHttpConsumerException: POST on https://##SERVERNAME##/sdata/crmj/crmExchange/-/appointments/$syncTarget?trackingId=e61dd7b3-f010-4bd2-9354-b2c8b0bf67c4 failed: 500
ERROR [SyncEngine thread]: [26-févr.-2022 00:50:30.401] com.sage.scrm.syncengine.core.engine.error.SageSyncEngineException: com.sage.scrm.syncengine.exchange.engine.model.error.SageSDataEndpointException: com.sage.crm.httpconsumer.error.SageHttpConsumerException: POST on https://##SERVERNAME##/sdata/crmj/crmExchange/-/appointments/$syncTarget?trackingId=e61dd7b3-f010-4bd2-9354-b2c8b0bf67c4 failed: 500
ERROR [SyncEngine thread]: [26-févr.-2022 00:50:30.401] com.sage.scrm.syncengine.core.engine.error.SageSyncEngineException: com.sage.scrm.syncengine.exchange.engine.model.error.SageSDataEndpointException: com.sage.crm.httpconsumer.error.SageHttpConsumerException: POST on https://##SERVERNAME##/sdata/crmj/crmExchange/-/appointments/$syncTarget?trackingId=e61dd7b3-f010-4bd2-9354-b2c8b0bf67c4 failed: 500
com.sage.scrm.syncengine.core.engine.error.SageSyncEngineException: com.sage.scrm.syncengine.exchange.engine.model.error.SageSDataEndpointException: com.sage.crm.httpconsumer.error.SageHttpConsumerException: POST on https://##SERVERNAME##/sdata/crmj/crmExchange/-/appointments/$syncTarget?trackingId=e61dd7b3-f010-4bd2-9354-b2c8b0bf67c4 failed: 500
at com.sage.scrm.syncengine.exchange.engine.SynchronisationProcess.execute(SynchronisationProcess.java:202) ~[classes/:?]
at com.sage.scrm.syncengine.exchange.engine.SynchronisationThread.synchroniseResourceOneWay(SynchronisationThread.java:296) ~[classes/:?]
at com.sage.scrm.syncengine.exchange.engine.SynchronisationThread.synchroniseResourcesOneWay(SynchronisationThread.java:285) ~[classes/:?]
at com.sage.scrm.syncengine.exchange.engine.SynchronisationThread.run(SynchronisationThread.java:173) [classes/:?]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_152]
Caused by: com.sage.scrm.syncengine.exchange.engine.model.error.SageSDataEndpointException: com.sage.crm.httpconsumer.error.SageHttpConsumerException: POST on https://##SERVERNAME##/sdata/crmj/crmExchange/-/appointments/$syncTarget?trackingId=e61dd7b3-f010-4bd2-9354-b2c8b0bf67c4 failed: 500
at com.sage.scrm.syncengine.exchange.sdata.SCRMEndpoint.sendToSyncTarget(SCRMEndpoint.java:199) ~[classes/:?]
at com.sage.scrm.syncengine.exchange.engine.SynchronisationProcess.execute(SynchronisationProcess.java:169) ~[classes/:?]
... 4 more
Caused by: com.sage.crm.httpconsumer.error.SageHttpConsumerException: POST on https://##SERVERNAME##/sdata/crmj/crmExchange/-/appointments/$syncTarget?trackingId=e61dd7b3-f010-4bd2-9354-b2c8b0bf67c4 failed: 500
at com.sage.crm.httpconsumer.HttpConsumer.doPostPut(HttpConsumer.java:1046) ~[httpConsumer-21R2.jar:?]
at com.sage.crm.httpconsumer.HttpConsumer.doPost(HttpConsumer.java:847) ~[httpConsumer-21R2.jar:?]
at com.sage.crm.httpconsumer.HttpConsumer.doPost(HttpConsumer.java:819) ~[httpConsumer-21R2.jar:?]
at com.sage.scrm.syncengine.exchange.sdata.SCRMEndpoint.sendToSyncTarget(SCRMEndpoint.java:191) ~[classes/:?]
at com.sage.scrm.syncengine.exchange.engine.SynchronisationProcess.execute(SynchronisationProcess.java:169) ~[classes/:?]
... 4 more

Tomcat localhost_access_log

0:0:0:0:0:0:0:1 - - [26/Feb/2022:00:50:29 +0100] "POST /crmj/crmExchange/-/appointments/$syncTarget?originalHostCRMRedirector=##SERVERNAME##&trackingId=e61dd7b3-f010-4bd2-9354-b2c8b0bf67c4 HTTP/1.1" 202 306
0:0:0:0:0:0:0:1 - - [26/Feb/2022:00:50:30 +0100] "GET /crmj/crmExchange/-/appointments/$syncTarget?originalHostCRMRedirector=##SERVERNAME##&trackingId=e61dd7b3-f010-4bd2-9354-b2c8b0bf67c4 HTTP/1.1" 500 363
0:0:0:0:0:0:0:1 - - [26/Feb/2022:00:50:30 +0100] "POST /crmj/crmExchange/-/$service/updateSynchronizationStatus?originalHostCRMRedirector=##SERVERNAME## HTTP/1.1" 401 647
0:0:0:0:0:0:0:1 - - [26/Feb/2022:00:50:30 +0100] "POST /crmj/crmExchange/-/$service/updateSynchronizationStatus?originalHostCRMRedirector=##SERVERNAME## HTTP/1.1" 200 56

Tomcat catalina.log

ID: 1487
Response-Code: 200
Encoding: UTF-8
Content-Type: text/xml; charset=utf-8
Headers: {X-Proxy-BackendServerStatus=[200], x-EwsHandler=[ResolveNames], transfer-encoding=[chunked], Alt-Svc=[h3=":443",h3-29=":443"], Server=[Microsoft-IIS/10.0], X-Proxy-RoutingCorrectness=[1], X-CalculatedBETarget=[DB8PR03MB5801.eurprd03.prod.outlook.com], request-id=[72591df1-9b9e-eb69-4c52-5598dcc84925], X-RUM-Validated=[1], Date=[Fri, 25 Feb 2022 23:50:28 GMT], X-FEProxyInfo=[DB9PR01CA0011.EURPRD01.PROD.EXCHANGELABS.COM], X-BEServer=[DB8PR03MB5801], X-CalculatedFETarget=[DB9PR01CU001.internal.outlook.com], Cache-Control=[private], X-DiagInfo=[DB8PR03MB5801], X-BackEndHttpStatus=[200, 200], X-AspNet-Version=[4.0.30319], X-FEServer=[LO2P265CA0095, DB9PR01CA0011], X-BeSku=[WCS5], Set-Cookie=[exchangecookie=2bce21764fd9435ea6b7275fa544d4c1; expires=Sat, 25-Feb-2023 23:50:29 GMT; path=/; secure; HttpOnly], content-type=[text/xml; charset=utf-8], X-Powered-By=[ASP.NET], X-FirstHopCafeEFZ=[LHR]}
Payload: <?xml version="1.0" encoding="utf-8"?><s:Envelope xmlns:s="">schemas.xmlsoap.org/.../"><s:Header><h:ServerVersionInfo MajorVersion="15" MinorVersion="20" MajorBuildNumber="5017" MinorBuildNumber="26" Version="V2018_01_08" xmlns:h="">schemas.microsoft.com/.../types" xmlns:xsd="">www.w3.org/.../XMLSchema" xmlns:xsi="">www.w3.org/.../s:Header><s:Body><m:ResolveNamesResponse xmlns:m="">schemas.microsoft.com/.../messages" xmlns:xsd="">www.w3.org/.../XMLSchema" xmlns:xsi="">www.w3.org/.../XMLSchema-instance" xmlns:t="">schemas.microsoft.com/.../types"><m:ResponseMessages><m:ResolveNamesResponseMessage ResponseClass="Error"><m:MessageText>No results were found.</m:MessageText><m:ResponseCode>ErrorNameResolutionNoResults</m:ResponseCode><m:DescriptiveLinkKey>0</m:DescriptiveLinkKey></m:ResolveNamesResponseMessage></m:ResponseMessages></m:ResolveNamesResponse></s:Body></s:Envelope>
--------------------------------------
26-Feb-2022 00:50:29.545 INFOS [Sync Source APPOINTMENT Queue Thread] org.apache.cxf.interceptor.LoggingOutInterceptor$LoggingCallback.onClose Outbound Message
---------------------------
ID: 1488
Address: outlook.office365.com/.../Exchange.asmx
Encoding: UTF-8
Content-Type: text/xml
Headers: {SOAPAction=["http://schemas.microsoft.com/exchange/services/2006/messages/ResolveNames"], Authorization=[Basic Y2xlY29ycmVAYW50aXNzLmZyOkV1cGdweHA2NCEh], Accept=[*/*]}
Payload: <soap:Envelope xmlns:soap="">schemas.xmlsoap.org/.../"><soap:Header><RequestServerVersion xmlns:ns2="">schemas.microsoft.com/.../messages" xmlns="">schemas.microsoft.com/.../types" Version="Exchange2007_SP1" /></soap:Header><soap:Body><ns2:ResolveNames xmlns="">schemas.microsoft.com/.../types" xmlns:ns2="">schemas.microsoft.com/.../messages" ReturnFullContactData="false"><ns2:UnresolvedEntry>smtp:[email protected]</ns2:UnresolvedEntry></ns2:ResolveNames></soap:Body></soap:Envelope>
--------------------------------------
26-Feb-2022 00:50:29.699 INFOS [Sync Source APPOINTMENT Queue Thread] org.apache.cxf.interceptor.LoggingInInterceptor.logging Inbound Message
----------------------------
ID: 1488
Response-Code: 200
Encoding: UTF-8
Content-Type: text/xml; charset=utf-8
Headers: {X-Proxy-BackendServerStatus=[200], x-EwsHandler=[ResolveNames], transfer-encoding=[chunked], Alt-Svc=[h3=":443",h3-29=":443"], Server=[Microsoft-IIS/10.0], X-Proxy-RoutingCorrectness=[1], X-CalculatedBETarget=[DB8PR03MB5801.eurprd03.prod.outlook.com], request-id=[bd43dbc3-7b3c-7196-dae0-3b14eeee18df], X-RUM-Validated=[1], Date=[Fri, 25 Feb 2022 23:50:29 GMT], X-FEProxyInfo=[DB6P195CA0003.EURP195.PROD.OUTLOOK.COM], X-BEServer=[DB8PR03MB5801], X-CalculatedFETarget=[DB6P195CU001.internal.outlook.com], Cache-Control=[private], X-DiagInfo=[DB8PR03MB5801], X-BackEndHttpStatus=[200, 200], X-AspNet-Version=[4.0.30319], X-FEServer=[LO2P265CA0095, DB6P195CA0003], X-BeSku=[WCS5], Set-Cookie=[exchangecookie=1572a4da458442448476e6c1a8ed9560; expires=Sat, 25-Feb-2023 23:50:29 GMT; path=/; secure; HttpOnly], content-type=[text/xml; charset=utf-8], X-Powered-By=[ASP.NET], X-FirstHopCafeEFZ=[LHR]}
Payload: <?xml version="1.0" encoding="utf-8"?><s:Envelope xmlns:s="">schemas.xmlsoap.org/.../"><s:Header><h:ServerVersionInfo MajorVersion="15" MinorVersion="20" MajorBuildNumber="5017" MinorBuildNumber="26" Version="V2018_01_08" xmlns:h="">schemas.microsoft.com/.../types" xmlns:xsd="">www.w3.org/.../XMLSchema" xmlns:xsi="">www.w3.org/.../s:Header><s:Body><m:ResolveNamesResponse xmlns:m="">schemas.microsoft.com/.../messages" xmlns:xsd="">www.w3.org/.../XMLSchema" xmlns:xsi="">www.w3.org/.../XMLSchema-instance" xmlns:t="">schemas.microsoft.com/.../types"><m:ResponseMessages><m:ResolveNamesResponseMessage ResponseClass="Error"><m:MessageText>No results were found.</m:MessageText><m:ResponseCode>ErrorNameResolutionNoResults</m:ResponseCode><m:DescriptiveLinkKey>0</m:DescriptiveLinkKey></m:ResolveNamesResponseMessage></m:ResponseMessages></m:ResolveNamesResponse></s:Body></s:Envelope>
--------------------------------------
26-Feb-2022 00:55:31.706 INFOS [SyncEngine thread] org.apache.cxf.interceptor.LoggingOutInterceptor$LoggingCallback.onClose Outbound Message
---------------------------

Thanks

Parents
  • If the service is stopping then it should put something in the server's event log.  Is there any more information there?

  • Thank you for your answer. The service isn't really stopping, it continues to run with errors, the syncengine still tries to sync each 5 minutes.

    I went to event logs but the errors I see at bug's date doesn't look related to my issue: 

     

    The PerfNet error says : "Unable to open the Server service performance object. The first four bytes (DWORD) of the Data section contains the status code."

  • Thank you, I did what was recommended in the link. I will tell you if the error remains.
    However, I don't think the event log is related to my issue because latest Exchange synchronization errors aren't preceded by any PerfNet error (and even any event log error at all).

    Couldn't it actually be related to sdatas or crmj as said in the error 500 ?

    ERROR [SyncEngine thread]: [26-févr.-2022 00:50:30.401] com.sage.scrm.syncengine.core.engine.error.SageSyncEngineException: com.sage.scrm.syncengine.exchange.engine.model.error.SageSDataEndpointException: com.sage.crm.httpconsumer.error.SageHttpConsumerException: POST on https://##SERVERNAME##/sdata/crmj/crmExchange/-/appointments/$syncTarget?trackingId=e61dd7b3-f010-4bd2-9354-b2c8b0bf67c4 failed: 500

    This specific error happens each time we detect synchronization malfunctions (always between midnight and +- 2 AM).

  • We've had our share of these weird Tomcat issues, all of which we've reported to CRM Support (NA) and some of which got escalated to Dublin.  Most were ultimately deemed unresolvable.  So fwiw, my "rogue" workaround is to reboot the server nightly using Task Scheduler.  Some IT folks push back on this, but rebooting the server nightly can have side-benefits, given that the server OS and other software programs - e.g. Crystal Reports, connectivity to other applications, etc. - can all have similar problems where they run OK for a while, but eventually fail.  Almost always, these problem programs can be reset by a server reboot.  Of course the preferred solution is to find and fix the ultimate source of the problem, but at some point, we all have other jobs to do, so a workaround is our best recourse.

    Incidentally, the Task Scheduler command to reboot the server is simply the word "shutdown" with the '/r' switch, so:

         shutdown /r

         

  • Alright, thank you for this informations. 

    As you said, that's not a solution but as we have nothing better to do for the moment, we use the workaround. We now restart Tomcat nightly and it works. 

    As it can help other users that share this issue : the way we restart Tomcat is showed in this post's answer

  • My only comment on this would be, would you not add the /f switch as well to the comment in order to 'force' it to do the reboot in case of some other rogue program not allowing the reboot to happen?

  • Hello Christophe,

    I see this problem with  2021 R2 version . What CRM version are you on?

Reply Children
No Data