[CAMEL-12812] Salesforce component tries to reconnect when unsubscribing from topic in case of "403::Handshake denied" error

• Type: Bug
• Status: Resolved
• Priority: Minor
• Resolution: Abandoned
• Affects Version/s: 2.21.2, 2.22.1
• Component/s: camel-salesforce
• Estimated Complexity: Unknown
• Assignee: Unassigned
• Reporter: Andrey Tyurin
• Created: 14/Sep/18 23:52
• Updated: 22/Mar/21 18:04
• Resolved: 22/Mar/21 18:03

Description

Hi.

We've faced some strange behavior when salesforce component is shutting down.

When SF component is unsubscribing from channel and it gets some error, e.g. "403::Handshake denied" it tries then reconnect to SF. But why? if it is shutting down.

This causes long process of logout from SF: about 4 minutes.

We do not have specific scenario, but only exceptions for this case.

 

2018-08-31 05:40:51.454 [SalesforceHttpClient@b9f06a7-293] INFO org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper - Restarting on unexpected disconnect from Salesforce... 2018-08-31 05:40:51.454 [SalesforceHttpClient@b9f06a7-293] DEBUG org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper - Waiting to disconnect... 2018-08-31 05:40:51.455 [SalesforceHttpClient@b9f06a7-288] DEBUG org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper - [CHANNEL:META_CONNECT]: {clientId=kteskpq4fgf192z1zpdm0ml1ebe, advice=

{reconnect=none, interval=0}, channel=/meta/connect, id=29, error=401::Authentication invalid, successful=false} 2018-08-31 05:40:51.455 [SalesforceHttpClient@b9f06a7-288] WARN org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper - Connect failure: {clientId=kteskpq4fgf192z1zpdm0ml1ebe, advice={reconnect=none, interval=0}

, channel=/meta/connect, id=29, error=401::Authentication invalid, successful=false} 2018-08-31 05:40:56.516 [SalesforceHttpClient@b9f06a7-292] INFO org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper - Cleaning session (logout) from SalesforceSession before restarting client 2018-08-31 05:41:39.156 Camel (camel-1) thread #105 - ShutdownTask INFO org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper - Unsubscribing from channel /topic/myCompanyExtRoutPsr... ... 2018-08-31 05:42:19.156 Camel (camel-1) thread #105 - ShutdownTask WARN org.apache.camel.impl.DefaultShutdownStrategy - Error occurred while shutting down route: Consumer[salesforce-102-STREAMING://myCompanyExtRoutPsr?sObjectClass=com.myCompany.sfgateway.api.dto.PendingServiceRouting&sObjectQuery=SELECT+Id%2C+QueueId%2C+WorkItemId%2C+IsPushed%2C+ServiceChannelId%2C+LastDeclinedAgentSession%2C+CreatedDate%2C+IsDeleted%2C+IsPushAttempted%2C+IsTransfer+from+PendingServiceRouting+WHERE+RoutingModel+%3D+%27ExternalRouting%27&synchronous=true]. This exception will be ignored. org.apache.camel.CamelException: Timeout error unsubscribing from topic myCompanyExtRoutPsr after 40 seconds at org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper.unsubscribe(SubscriptionHelper.java:519) ~[camel-salesforce-2.21.2.jar!/:2.21.2] at org.apache.camel.component.salesforce.SalesforceConsumer.doStop(SalesforceConsumer.java:139) ~[camel-salesforce-2.21.2.jar!/:2.21.2] at org.apache.camel.support.ServiceSupport.stop(ServiceSupport.java:102) ~[camel-core-2.21.2.jar!/:2.21.2] at org.apache.camel.util.ServiceHelper.stopService(ServiceHelper.java:142) ~[camel-core-2.21.2.jar!/:2.21.2] at org.apache.camel.impl.DefaultShutdownStrategy.shutdownNow(DefaultShutdownStrategy.java:381) [camel-core-2.21.2.jar!/:2.21.2] at org.apache.camel.impl.DefaultShutdownStrategy$ShutdownTask.run(DefaultShutdownStrategy.java:577) [camel-core-2.21.2.jar!/:2.21.2] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_102] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_102] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_102] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_102] at java.lang.Thread.run(Thread.java:745) [?:1.8.0_102] 2018-08-31 05:42:19.170 Camel (camel-1) thread #105 - ShutdownTask INFO org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper - Unsubscribing from channel /topic/myCompanyExtRoute... 2018-08-31 05:42:46.458 [SalesforceHttpClient@b9f06a7-293] ERROR org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper - Error restarting: Error during HANDSHAKE: 403::Handshake denied org.apache.camel.CamelException: Error during HANDSHAKE: 403::Handshake denied at org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper.doStart(SubscriptionHelper.java:215) ~[camel-salesforce-2.21.2.jar!/:2.21.2] at org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper$4.run(SubscriptionHelper.java:278) [camel-salesforce-2.21.2.jar!/:2.21.2] at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:762) [jetty-util-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:680) [jetty-util-9.4.11.v20180605.jar!/:9.4.11.v20180605] at java.lang.Thread.run(Thread.java:745) [?:1.8.0_102] 2018-08-31 05:42:59.170 Camel (camel-1) thread #105 - ShutdownTask WARN org.apache.camel.impl.DefaultShutdownStrategy - Error occurred while shutting down route: Consumer[salesforce-102-STREAMING://myCompanyExtRoute?notifyForFields=ALL&sObjectClass=com.myCompany.sfgateway.api.dto.AgentWork&sObjectQuery=SELECT+Id%2C+IsDeleted%2C+Status%2C+UserId%2C+WorkItemId%2C+ServiceChannelId%2C+DeclineReason%2C+PendingServiceRoutingId+FROM+AgentWork&synchronous=true]. This exception will be ignored. org.apache.camel.CamelException: Timeout error unsubscribing from topic myCompanyExtRoute after 40 seconds at org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper.unsubscribe(SubscriptionHelper.java:519) ~[camel-salesforce-2.21.2.jar!/:2.21.2] at org.apache.camel.component.salesforce.SalesforceConsumer.doStop(SalesforceConsumer.java:139) ~[camel-salesforce-2.21.2.jar!/:2.21.2] at org.apache.camel.support.ServiceSupport.stop(ServiceSupport.java:102) ~[camel-core-2.21.2.jar!/:2.21.2] at org.apache.camel.util.ServiceHelper.stopService(ServiceHelper.java:142) ~[camel-core-2.21.2.jar!/:2.21.2] at org.apache.camel.impl.DefaultShutdownStrategy.shutdownNow(DefaultShutdownStrategy.java:381) [camel-core-2.21.2.jar!/:2.21.2] at org.apache.camel.impl.DefaultShutdownStrategy$ShutdownTask.run(DefaultShutdownStrategy.java:577) [camel-core-2.21.2.jar!/:2.21.2] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_102] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_102] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_102] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_102] at java.lang.Thread.run(Thread.java:745) [?:1.8.0_102] 2018-08-31 05:45:56.519 [SalesforceHttpClient@b9f06a7-292] WARN org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper - Error while cleaning session: Logout request TIMEOUT! org.apache.camel.component.salesforce.api.SalesforceException: Logout request TIMEOUT! at org.apache.camel.component.salesforce.internal.SalesforceSession.logout(SalesforceSession.java:318) ~[camel-salesforce-2.21.2.jar!/:2.21.2] at org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper$1.onMessage(SubscriptionHelper.java:142) [camel-salesforce-2.21.2.jar!/:2.21.2] at org.cometd.common.AbstractClientSession$AbstractSessionChannel.notifyOnMessage(AbstractClientSession.java:594) [cometd-java-common-3.1.2.jar!/:?] at org.cometd.common.AbstractClientSession$AbstractSessionChannel.notifyMessageListeners(AbstractClientSession.java:579) [cometd-java-common-3.1.2.jar!/:?] at org.cometd.common.AbstractClientSession.notifyListeners(AbstractClientSession.java:291) [cometd-java-common-3.1.2.jar!/:?] at org.cometd.common.AbstractClientSession.receive(AbstractClientSession.java:257) [cometd-java-common-3.1.2.jar!/:?] at org.cometd.client.BayeuxClient.failHandshake(BayeuxClient.java:735) [cometd-java-client-3.1.2.jar!/:?] at org.cometd.client.BayeuxClient.processHandshake(BayeuxClient.java:721) [cometd-java-client-3.1.2.jar!/:?] at org.cometd.client.BayeuxClient.processMessages(BayeuxClient.java:606) [cometd-java-client-3.1.2.jar!/:?] at org.cometd.client.BayeuxClient.access$3100(BayeuxClient.java:100) [cometd-java-client-3.1.2.jar!/:?] at org.cometd.client.BayeuxClient$MessageTransportListener.onMessages(BayeuxClient.java:1189) [cometd-java-client-3.1.2.jar!/:?] at org.cometd.client.transport.LongPollingTransport$2.onComplete(LongPollingTransport.java:236) [cometd-java-client-3.1.2.jar!/:?] at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:216) [jetty-client-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:208) [jetty-client-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:470) [jetty-client-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.client.HttpReceiver.responseSuccess(HttpReceiver.java:416) [jetty-client-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.messageComplete(HttpReceiverOverHTTP.java:316) [jetty-client-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.http.HttpParser.handleContentMessage(HttpParser.java:605) [jetty-http-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.http.HttpParser.parseContent(HttpParser.java:1675) [jetty-http-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1523) [jetty-http-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.parse(HttpReceiverOverHTTP.java:172) [jetty-client-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:135) [jetty-client-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:73) [jetty-client-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:133) [jetty-client-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:155) [jetty-client-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:281) [jetty-io-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102) [jetty-io-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:291) [jetty-io-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.io.ssl.SslConnection$3.succeeded(SslConnection.java:151) [jetty-io-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102) [jetty-io-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118) [jetty-io-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333) [jetty-util-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310) [jetty-util-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168) [jetty-util-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126) [jetty-util-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366) [jetty-util-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:762) [jetty-util-9.4.11.v20180605.jar!/:9.4.11.v20180605] at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:680) [jetty-util-9.4.11.v20180605.jar!/:9.4.11.v20180605] at java.lang.Thread.run(Thread.java:745) [?:1.8.0_102]

 

Could you change SubscriptionHelper not to start again in restartClient when logout/unsubscribe is invoked (line 278 in

org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper v2.21.2)

 

and/or prevent reconnect in case of logout?