[CAMEL-16370] Camel Salesforce component unable to reconnect after disconnect from Salesforce

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 3.8.0, 3.11.0
• Fix Version/s: 3.14.0
• Component/s: camel-salesforce

Environment

Running in a spring-boot (v2.1.18.RELEASE) app in a linux container deployed to openshift 3.11

• Estimated Complexity: Unknown
• Assignee: Unassigned
• Reporter: Jason
• Created: 18/Mar/21 15:12
• Updated: 14/Nov/21 09:02
• Resolved: 14/Nov/21 09:02

Description

We are consuming Salesforce platform-events following the documented recommendations and our connection will not reconnect after being disconnected, apparently, from Salesforce.  I am not quite certain as to the circumstances that Salesforce sends some sort of disconnect signal, but that is what's logged from the SubscriptionHelper class. Our initial connection to Salesforce is successful and we are able to receive platform-events up until the point of the spontaneous disconnection.  Re-connection fails consistently and always in the same way.  Logging is slightly different across version, but the behavior seems to always be the same.

Our only work around for this is to run our service consuming this message like a cron job and restart it every 15 minutes (period we settled on through experimentation).  This is not how we'd prefer to sun this service, it's quite hacky and we'd like to not have to force a restart to work around what appears to an issue with how the reconnect is handled.

 

Here is the stacktrace:

[DEBUG] 2021-03-17 13:30:48,513 org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper$5 [SalesforceHttpClient@60c73e58-25 ] - Received messages [

{clientId=[--------redacted--------], channel=/meta/connect, id=21, successful=true}][DEBUG] 2021-03-17 13:30:48,513 org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper [SalesforceHttpClient@60c73e58-25 ] - [CHANNEL:META_CONNECT]: {clientId=[--------redacted--------], channel=/meta/connect, id=21, successful=true}

[DEBUG] 2021-03-17 13:32:38,588 org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper$5 [SalesforceHttpClient@60c73e58-25 ] - Received messages [

{clientId=[--------redacted--------], channel=/meta/connect, id=22, successful=true}]
[DEBUG] 2021-03-17 13:32:38,589 org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper [SalesforceHttpClient@60c73e58-25 ] - [CHANNEL:META_CONNECT]: {clientId=[--------redacted--------], channel=/meta/connect, id=22, successful=true}

[DEBUG] 2021-03-17 13:34:28,665 org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper$5 [SalesforceHttpClient@60c73e58-25 ] - Received messages [

{clientId=[--------redacted--------], channel=/meta/connect, id=23, successful=true}]
[DEBUG] 2021-03-17 13:34:28,666 org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper [SalesforceHttpClient@60c73e58-25 ] - [CHANNEL:META_CONNECT]: {clientId=[--------redacted--------], channel=/meta/connect, id=23, successful=true}

[DEBUG] 2021-03-17 13:34:28,766 org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper$5 [SalesforceHttpClient@60c73e58-32 ] - Received messages [

{channel=/meta/disconnect}

, {clientId=[--------redacted--------], advice=

{reconnect=none, interval=0}, channel=/meta/connect, id=24, error=401::Authentication invalid, successful=false}]
[INFO ] 2021-03-17 13:34:28,769 org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper [SalesforceHttpClient@60c73e58-26 ] - Restarting on unexpected disconnect from Salesforce...
[DEBUG] 2021-03-17 13:34:28,769 org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper [SalesforceHttpClient@60c73e58-26 ] - Waiting to disconnect...
[DEBUG] 2021-03-17 13:34:28,770 org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper [SalesforceHttpClient@60c73e58-32 ] - [CHANNEL:META_CONNECT]: {clientId=[--------redacted--------], advice={reconnect=none, interval=0}

, channel=/meta/connect, id=24, error=401::Authentication invalid, successful=false}[WARN ] 2021-03-17 13:34:28,771 org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper [SalesforceHttpClient@60c73e58-32 ] - Connect failure: {clientId=[--------redacted--------], advice=

{reconnect=none, interval=0}

, channel=/meta/connect, id=24, error=401::Authentication invalid, successful=false}
[DEBUG] 2021-03-17 13:34:33,769 org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper [SalesforceHttpClient@60c73e58-26 ] - Pausing for 0 msecs before restart attempt
[DEBUG] 2021-03-17 13:34:33,770 org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper [SalesforceHttpClient@60c73e58-26 ] - Stopped the helper and destroyed the client
[DEBUG] 2021-03-17 13:34:33,862 org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper$5 [SalesforceHttpClient@60c73e58-30 ] - Received messages [{ext={sfdc=

{failureReason=401::Authentication invalid}

, replay=true, payload.format=true}, advice=

{reconnect=none}, channel=/meta/handshake, id=25, error=403::Handshake denied, successful=false}][DEBUG] 2021-03-17 13:34:33,863 org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper [SalesforceHttpClient@60c73e58-30 ] - [CHANNEL:META_HANDSHAKE]: {ext={sfdc={failureReason=401::Authentication invalid}, replay=true, payload.format=true}, advice={reconnect=none}

, channel=/meta/handshake, id=25, error=403::Handshake denied, successful=false}
[WARN ] 2021-03-17 13:34:33,863 org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper [SalesforceHttpClient@60c73e58-30 ] - Handshake failure: {ext={sfdc=

{failureReason=401::Authentication invalid}

, replay=true, payload.format=true}, advice=

{reconnect=none}

, channel=/meta/handshake, id=25, error=403::Handshake denied, successful=false}
[INFO ] 2021-03-17 13:34:33,863 org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper [SalesforceHttpClient@60c73e58-30 ] - Cleaning session (logout) from SalesforceSession before restarting client
[INFO ] 2021-03-17 13:34:33,867 org.cometd.bayeux.client.ClientSession [SalesforceHttpClient@60c73e58-30 ] - Exception while invoking listener org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper$[e-mail]: null at org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper$1.onMessage(SubscriptionHelper.java:148) at org.cometd.common.AbstractClientSession$AbstractSessionChannel.notifyOnMessage(AbstractClientSession.java:583) at org.cometd.common.AbstractClientSession$AbstractSessionChannel.notifyMessageListeners(AbstractClientSession.java:568) at org.cometd.common.AbstractClientSession.notifyListeners(AbstractClientSession.java:308) at org.cometd.common.AbstractClientSession.lambda$receive$4(AbstractClientSession.java:269) at org.cometd.bayeux.Promise$2.succeed(Promise.java:103) at org.cometd.common.AsyncFoldLeft$AbstractLoop.run(AsyncFoldLeft.java:199) at org.cometd.common.AsyncFoldLeft.run(AsyncFoldLeft.java:93) at org.cometd.common.AbstractClientSession.extendIncoming(AbstractClientSession.java:103) at org.cometd.common.AbstractClientSession.receive(AbstractClientSession.java:263) at org.cometd.client.BayeuxClient.failHandshake(BayeuxClient.java:721) at org.cometd.client.BayeuxClient.processHandshake(BayeuxClient.java:707) at org.cometd.client.BayeuxClient.processMessages(BayeuxClient.java:615) at org.cometd.client.BayeuxClient.access$2000(BayeuxClient.java:101) at org.cometd.client.BayeuxClient$MessageTransportListener.onMessages(BayeuxClient.java:1260) at org.cometd.client.transport.LongPollingTransport$2.onComplete(LongPollingTransport.java:240) at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:218) at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:210) at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:481) at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:461) at org.eclipse.jetty.client.HttpReceiver.responseSuccess(HttpReceiver.java:424) at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.messageComplete(HttpReceiverOverHTTP.java:365) at org.eclipse.jetty.http.HttpParser.handleContentMessage(HttpParser.java:585) at org.eclipse.jetty.http.HttpParser.parseContent(HttpParser.java:1702) at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1531) at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.parse(HttpReceiverOverHTTP.java:204) at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:144) at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:79) at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:131) at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:169) at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:540) at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:395) at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:161) at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:773) at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:905) at java.base/java.lang.Thread.run(Thread.java:834)
[ERROR] 2021-03-17 13:36:23,773 org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper [SalesforceHttpClient@60c73e58-26 ] - Error restarting: Exception during HANDSHAKE: 401::Authentication invalidorg.apache.camel.CamelException: Exception during HANDSHAKE: 401::Authentication invalid at org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper.connect(SubscriptionHelper.java:223) at org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper.doStart(SubscriptionHelper.java:212) at org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper.performClientRestart(SubscriptionHelper.java:304) at org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper.access$1000(SubscriptionHelper.java:60) at org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper$4.run(SubscriptionHelper.java:249) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:773) at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:905) at java.base/java.lang.Thread.run(Thread.java:834)Caused by: org.apache.camel.component.salesforce.api.SalesforceException: 401::Authentication invalid at org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper.getFailure(SubscriptionHelper.java:340) at org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper.access$300(SubscriptionHelper.java:60) at org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper$1.onMessage(SubscriptionHelper.java:132) at org.cometd.common.AbstractClientSession$AbstractSessionChannel.notifyOnMessage(AbstractClientSession.java:583) at org.cometd.common.AbstractClientSession$AbstractSessionChannel.notifyMessageListeners(AbstractClientSession.java:568) at org.cometd.common.AbstractClientSession.notifyListeners(AbstractClientSession.java:308) at org.cometd.common.AbstractClientSession.lambda$receive$4(AbstractClientSession.java:269) at org.cometd.bayeux.Promise$2.succeed(Promise.java:103) at org.cometd.common.AsyncFoldLeft$AbstractLoop.run(AsyncFoldLeft.java:199) at org.cometd.common.AsyncFoldLeft.run(AsyncFoldLeft.java:93) at org.cometd.common.AbstractClientSession.extendIncoming(AbstractClientSession.java:103) at org.cometd.common.AbstractClientSession.receive(AbstractClientSession.java:263) at org.cometd.client.BayeuxClient.failHandshake(BayeuxClient.java:721) at org.cometd.client.BayeuxClient.processHandshake(BayeuxClient.java:707) at org.cometd.client.BayeuxClient.processMessages(BayeuxClient.java:615) at org.cometd.client.BayeuxClient.access$2000(BayeuxClient.java:101) at org.cometd.client.BayeuxClient$MessageTransportListener.onMessages(BayeuxClient.java:1260) at org.cometd.client.transport.LongPollingTransport$2.onComplete(LongPollingTransport.java:240) at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:218) at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:210) at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:481) at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:461) at org.eclipse.jetty.client.HttpReceiver.responseSuccess(HttpReceiver.java:424) at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.messageComplete(HttpReceiverOverHTTP.java:365) at org.eclipse.jetty.http.HttpParser.handleContentMessage(HttpParser.java:585) at org.eclipse.jetty.http.HttpParser.parseContent(HttpParser.java:1702) at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1531) at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.parse(HttpReceiverOverHTTP.java:204) at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:144) at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:79) at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:131) at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:169) at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:540) at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:395) at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:161) at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375) ... 3 common frames omitted
[ERROR] 2021-03-17 13:36:23,774 org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper [SalesforceHttpClient@60c73e58-26 ] - Failed to restart after pausing for 0 msecs