Andrey Tyurin created CAMEL-12812:
-------------------------------------
Summary: Salesforce component tries to reconnect when
unsubscribing from topic in case of "403::Handshake denied" error
Key: CAMEL-12812
URL: https://issues.apache.org/jira/browse/CAMEL-12812
Project: Camel
Issue Type: Bug
Components: camel-salesforce
Affects Versions: 2.22.1
Reporter: Andrey Tyurin
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?
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
