Jason created CAMEL-16370:
-----------------------------
Summary: Camel Salesforce component unable to reconnect after
disconnect from Salesforce
Key: CAMEL-16370
URL: https://issues.apache.org/jira/browse/CAMEL-16370
Project: Camel
Issue Type: Bug
Components: camel-salesforce
Affects Versions: 3.8.0
Environment: Running in a spring-boot (v2.1.18.RELEASE) app in a linux
container deployed to openshift 3.11
Reporter: Jason
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:
{noformat}
[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$1...@7574cf75java.lang.NullPointerException:
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{noformat}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
