[
https://issues.apache.org/jira/browse/CAMEL-12871?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16645250#comment-16645250
]
Hemang Ajmera commented on CAMEL-12871:
---------------------------------------
One more point
I have just extracted relevant part of logs...
For e.g. every 2-3 hours camel gets disconnection, so the first type of logs is
seen every 2-3 hours. Then there was issue ( 2nd type of log). After that 3rd
type of log is seen to be repeating every 2-3 hours.
> Camel-salesforce component drops the streaming topic
> ----------------------------------------------------
>
> Key: CAMEL-12871
> URL: https://issues.apache.org/jira/browse/CAMEL-12871
> Project: Camel
> Issue Type: Bug
> Components: camel-salesforce
> Affects Versions: 2.21.1
> Reporter: Hemang Ajmera
> Priority: Blocker
>
> h1. Summary
> Salesforce component tries to reconnect to salesforce, if it gets disconnect.
> Most of the time it is succeeded. However, there is case when re-connect does
> not work. At that time salesforce component drops the topic which is
> subscribe and reconnects back. Everything looks normal again, however, no new
> streaming messages are received, as the component has dropped the topic.
> h1. Observation
> Here is the logs which show good reconnect. We can see that camel attempts to
> subscribe to topic /topic/AccountOwner
> {quote}
> 2018-09-12 02:54:23.530 DEBUG 1 --- [ent@2362f559-20]
> o.a.c.c.s.i.s.SubscriptionHelper$5 : Received messages
> [{advice={reconnect=handshake, interval=0}, channel=/meta/connect, id=410,
> error=403::Unknown client, successful=false}]
> 2018-09-12 02:54:23.531 DEBUG 1 --- [ent@2362f559-20]
> o.a.c.c.s.i.s.SubscriptionHelper : [CHANNEL:META_CONNECT]:
> {advice={reconnect=handshake, interval=0}, channel=/meta/connect, id=410,
> error=403::Unknown client, successful=false}
> 2018-09-12 02:54:23.531 WARN 1 --- [ent@2362f559-20]
> o.a.c.c.s.i.s.SubscriptionHelper : Connect failure:
> {advice={reconnect=handshake, interval=0}, channel=/meta/connect, id=410,
> error=403::Unknown client, successful=false}
> 2018-09-12 02:54:23.588 DEBUG 1 --- [ent@2362f559-21]
> o.a.c.c.s.i.s.SubscriptionHelper$5 : Received messages
> [{ext={replay=true, payload.format=true}, minimumVersion=1.0,
> clientId=p1t17l7111gqk4p6eff60893qeev,
> supportedConnectionTypes=[Ljava.lang.Object;@471ebac8,
> channel=/meta/handshake, id=411, version=1.0, successful=true}]
> 2018-09-12 02:54:23.589 DEBUG 1 --- [ent@2362f559-21]
> o.a.c.c.s.i.s.SubscriptionHelper : [CHANNEL:META_HANDSHAKE]:
> {ext={replay=true, payload.format=true}, minimumVersion=1.0,
> clientId=p1t17l7111gqk4p6eff60893qeev,
> supportedConnectionTypes=[Ljava.lang.Object;@471ebac8,
> channel=/meta/handshake, id=411, version=1.0, successful=true}
> 2018-09-12 02:54:23.625 DEBUG 1 --- [ent@2362f559-20]
> o.a.c.c.s.i.s.SubscriptionHelper$5 : Received messages
> [{clientId=p1t17l7111gqk4p6eff60893qeev, advice={reconnect=retry, interval=0,
> timeout=110000}, channel=/meta/connect, id=412, successful=true}]
> 2018-09-12 02:54:23.625 DEBUG 1 --- [ent@2362f559-20]
> o.a.c.c.s.i.s.SubscriptionHelper : [CHANNEL:META_CONNECT]:
> {clientId=p1t17l7111gqk4p6eff60893qeev, advice={reconnect=retry, interval=0,
> timeout=110000}, channel=/meta/connect, id=412, successful=true}
> 2018-09-12 02:54:23.625 DEBUG 1 --- [ent@2362f559-20]
> o.a.c.c.s.i.s.SubscriptionHelper : Refreshing subscriptions to 1
> channels on reconnect
> 2018-09-12 02:54:23.626 INFO 1 --- [ent@2362f559-20]
> o.a.c.c.s.i.s.SubscriptionHelper : Set Replay extension to replay
> from `-2` for channel `/topic/AccountOwners`
> 2018-09-12 02:54:23.626 INFO 1 --- [ent@2362f559-20]
> o.a.c.c.s.i.s.SubscriptionHelper : Subscribing to channel
> /topic/AccountOwners...
> 2018-09-12 02:54:23.693 DEBUG 1 --- [ent@2362f559-21]
> o.a.c.c.s.i.s.SubscriptionHelper$5 : Received messages
> [{clientId=p1t17l7111gqk4p6eff60893qeev, channel=/meta/subscribe, id=413,
> subscription=/topic/AccountOwners, successful=true}]
> 2018-09-12 02:54:23.693 DEBUG 1 --- [ent@2362f559-21]
> o.a.c.c.s.i.s.SubscriptionHelper : [CHANNEL:META_SUBSCRIBE]:
> {clientId=p1t17l7111gqk4p6eff60893qeev, channel=/meta/subscribe, id=413,
> subscription=/topic/AccountOwners, successful=true}
> 2018-09-12 02:54:23.693 INFO 1 --- [ent@2362f559-21]
> o.a.c.c.s.i.s.SubscriptionHelper : Subscribed to channel
> /topic/AccountOwners
> 2018-09-12 02:54:25.453 DEBUG 1 --- [ent@2362f559-20]
> o.a.c.c.s.i.s.SubscriptionHelper$5 : Received messages ....
> {quote}
> Here is the logs which shows connection fails. Camel tries to reconnect, but
> fails. Then camel reconnects after dropping the topic. After this incident,
> no new messages are received.
> {quote}
> 2018-09-22 05:26:17.121 WARN 1 --- [ent@2362f559-23]
> o.a.c.c.s.i.s.SubscriptionHelper : Connect failure:
> {advice={reconnect=handshake, interval=0}, channel=/meta/connect, id=8770,
> error=403::Unknown client, successful=false}
> 2018-09-22 05:26:18.738 DEBUG 1 --- [ent@2362f559-24]
> o.a.c.c.s.i.s.SubscriptionHelper$5 : Received messages
> [{ext={replay=true, payload.format=true}, minimumVersion=1.0,
> clientId=5vgmiblu8etx0q3typo6d5tgn,
> supportedConnectionTypes=[Ljava.lang.Object;@5814852c,
> channel=/meta/handshake, id=8771, version=1.0, successful=true}]
> 2018-09-22 05:26:18.738 DEBUG 1 --- [ent@2362f559-24]
> o.a.c.c.s.i.s.SubscriptionHelper : [CHANNEL:META_HANDSHAKE]:
> {ext={replay=true, payload.format=true}, minimumVersion=1.0,
> clientId=5vgmiblu8etx0q3typo6d5tgn,
> supportedConnectionTypes=[Ljava.lang.Object;@5814852c,
> channel=/meta/handshake, id=8771, version=1.0, successful=true}
> 2018-09-22 05:26:18.775 DEBUG 1 --- [ent@2362f559-24]
> o.a.c.c.s.i.s.SubscriptionHelper$5 : Received messages
> [{clientId=5vgmiblu8etx0q3typo6d5tgn, advice={reconnect=retry, interval=0,
> timeout=110000}, channel=/meta/connect, id=8772, successful=true}]
> 2018-09-22 05:26:18.776 DEBUG 1 --- [ent@2362f559-24]
> o.a.c.c.s.i.s.SubscriptionHelper : [CHANNEL:META_CONNECT]:
> {clientId=5vgmiblu8etx0q3typo6d5tgn, advice={reconnect=retry, interval=0,
> timeout=110000}, channel=/meta/connect, id=8772, successful=true}
> 2018-09-22 05:26:18.776 DEBUG 1 --- [ent@2362f559-24]
> o.a.c.c.s.i.s.SubscriptionHelper : Refreshing subscriptions to 1
> channels on reconnect
> 2018-09-22 05:26:18.776 INFO 1 --- [ent@2362f559-24]
> o.a.c.c.s.i.s.SubscriptionHelper : Set Replay extension to replay
> from `-2` for channel `/topic/AccountOwners`
> 2018-09-22 05:26:18.776 INFO 1 --- [ent@2362f559-24]
> o.a.c.c.s.i.s.SubscriptionHelper : Subscribing to channel
> /topic/AccountOwners...
> 2018-09-22 05:26:19.013 DEBUG 1 --- [ent@2362f559-24]
> o.a.c.c.s.i.s.SubscriptionHelper$5 : Received messages
> [{channel=/meta/disconnect}, {clientId=5vgmiblu8etx0q3typo6d5tgn,
> advice={reconnect=none, interval=0}, channel=/meta/connect, id=8774,
> error=403::Unknown client, successful=false}]
> 2018-09-22 05:26:19.014 INFO 1 --- [ent@2362f559-22]
> o.a.c.c.s.i.s.SubscriptionHelper : Restarting on unexpected
> disconnect from Salesforce...
> 2018-09-22 05:26:19.014 DEBUG 1 --- [ent@2362f559-24]
> o.a.c.c.s.i.s.SubscriptionHelper : [CHANNEL:META_CONNECT]:
> {clientId=5vgmiblu8etx0q3typo6d5tgn, advice={reconnect=none, interval=0},
> channel=/meta/connect, id=8774, error=403::Unknown client, successful=false}
> 2018-09-22 05:26:19.014 WARN 1 --- [ent@2362f559-24]
> o.a.c.c.s.i.s.SubscriptionHelper : Connect failure:
> {clientId=5vgmiblu8etx0q3typo6d5tgn, advice={reconnect=none, interval=0},
> channel=/meta/connect, id=8774, error=403::Unknown client, successful=false}
> 2018-09-22 05:26:19.014 DEBUG 1 --- [ent@2362f559-22]
> o.a.c.c.s.i.s.SubscriptionHelper : Waiting to disconnect...
> 2018-09-22 05:26:19.014 DEBUG 1 --- [ent@2362f559-22]
> o.a.c.c.s.i.s.SubscriptionHelper : Pausing for 1000 msecs before
> restart attempt
> 2018-09-22 05:26:19.043 DEBUG 1 --- [ent@2362f559-23]
> o.a.c.c.s.i.s.SubscriptionHelper$5 : Received messages
> [{clientId=5vgmiblu8etx0q3typo6d5tgn, advice={reconnect=handshake,
> interval=0}, channel=/meta/subscribe, id=8773,
> subscription=/topic/AccountOwners, error=403::Unknown client,
> successful=false}]
> 2018-09-22 05:26:19.043 DEBUG 1 --- [ent@2362f559-23]
> o.a.c.c.s.i.s.SubscriptionHelper : [CHANNEL:META_SUBSCRIBE]:
> {clientId=5vgmiblu8etx0q3typo6d5tgn, advice={reconnect=handshake,
> interval=0}, channel=/meta/subscribe, id=8773,
> subscription=/topic/AccountOwners, error=403::Unknown client,
> successful=false}
> 2018-09-22 05:26:19.054 WARN 1 --- [ent@2362f559-23]
> o.a.c.c.salesforce.SalesforceConsumer : Error subscribing to
> AccountOwners: 403::Unknown client. Caused by:
> [org.apache.camel.component.salesforce.api.SalesforceException - Error
> subscribing to AccountOwners: 403::Unknown client]
> org.apache.camel.component.salesforce.api.SalesforceException: Error
> subscribing to AccountOwners: 403::Unknown client
> at
> org.apache.camel.component.salesforce.internal.streaming.SubscriptionHelper$7.onMessage(SubscriptionHelper.java:404)
> [camel-salesforce-2.21.1.jar!/:2.21.1]
> at
> org.cometd.common.AbstractClientSession$AbstractSessionChannel.notifyOnMessage(AbstractClientSession.java:594)
> [cometd-java-common-3.1.2.jar!/:na]
> at
> org.cometd.common.AbstractClientSession$AbstractSessionChannel.notifyMessageListeners(AbstractClientSession.java:579)
> [cometd-java-common-3.1.2.jar!/:na]
> at
> org.cometd.common.AbstractClientSession.notifyListeners(AbstractClientSession.java:291)
> [cometd-java-common-3.1.2.jar!/:na]
> at
> org.cometd.common.AbstractClientSession.receive(AbstractClientSession.java:257)
> [cometd-java-common-3.1.2.jar!/:na]
> at org.cometd.client.BayeuxClient.processMessage(BayeuxClient.java:822)
> [cometd-java-client-3.1.2.jar!/:na]
> at
> org.cometd.client.BayeuxClient.processMessages(BayeuxClient.java:618)
> [cometd-java-client-3.1.2.jar!/:na]
> at org.cometd.client.BayeuxClient.access$3100(BayeuxClient.java:100)
> [cometd-java-client-3.1.2.jar!/:na]
> at
> org.cometd.client.BayeuxClient$MessageTransportListener.onMessages(BayeuxClient.java:1189)
> [cometd-java-client-3.1.2.jar!/:na]
> at
> org.cometd.client.transport.LongPollingTransport$2.onComplete(LongPollingTransport.java:236)
> [cometd-java-client-3.1.2.jar!/:na]
> at
> org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:193)
> [jetty-client-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at
> org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:185)
> [jetty-client-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at
> org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:464)
> [jetty-client-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at
> org.eclipse.jetty.client.HttpReceiver.responseSuccess(HttpReceiver.java:410)
> [jetty-client-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at
> org.eclipse.jetty.client.http.HttpReceiverOverHTTP.messageComplete(HttpReceiverOverHTTP.java:301)
> [jetty-client-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at
> org.eclipse.jetty.http.HttpParser.handleContentMessage(HttpParser.java:628)
> [jetty-http-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at org.eclipse.jetty.http.HttpParser.parseContent(HttpParser.java:1594)
> [jetty-http-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1442)
> [jetty-http-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at
> org.eclipse.jetty.client.http.HttpReceiverOverHTTP.parse(HttpReceiverOverHTTP.java:173)
> [jetty-client-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at
> org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:134)
> [jetty-client-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at
> org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:72)
> [jetty-client-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at
> org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:133)
> [jetty-client-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at
> org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:155)
> [jetty-client-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at
> org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:281)
> [jetty-io-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102)
> [jetty-io-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at
> org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:291)
> [jetty-io-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at
> org.eclipse.jetty.io.ssl.SslConnection$3.succeeded(SslConnection.java:151)
> [jetty-io-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102)
> [jetty-io-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118)
> [jetty-io-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:319)
> [jetty-util-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:175)
> [jetty-util-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:133)
> [jetty-util-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at
> org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)
> [jetty-util-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at
> org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:754)
> [jetty-util-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at
> org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:672)
> [jetty-util-9.4.9.v20180320.jar!/:9.4.9.v20180320]
> at java.lang.Thread.run(Thread.java:748) [na:1.8.0_171]
> 2018-09-22 05:26:20.070 DEBUG 1 --- [ent@2362f559-24]
> o.a.c.c.s.i.s.SubscriptionHelper$5 : Received messages
> [{ext={replay=true, payload.format=true}, minimumVersion=1.0,
> clientId=91ffaqyez0nsf71n1yganknag4o,
> supportedConnectionTypes=[Ljava.lang.Object;@249260ff,
> channel=/meta/handshake, id=8775, version=1.0, successful=true}]
> 2018-09-22 05:26:20.070 DEBUG 1 --- [ent@2362f559-24]
> o.a.c.c.s.i.s.SubscriptionHelper : [CHANNEL:META_HANDSHAKE]:
> {ext={replay=true, payload.format=true}, minimumVersion=1.0,
> clientId=91ffaqyez0nsf71n1yganknag4o,
> supportedConnectionTypes=[Ljava.lang.Object;@249260ff,
> channel=/meta/handshake, id=8775, version=1.0, successful=true}
> 2018-09-22 05:26:20.108 DEBUG 1 --- [ent@2362f559-23]
> o.a.c.c.s.i.s.SubscriptionHelper$5 : Received messages
> [{clientId=91ffaqyez0nsf71n1yganknag4o, advice={reconnect=retry, interval=0,
> timeout=110000}, channel=/meta/connect, id=8776, successful=true}]
> 2018-09-22 05:26:20.108 DEBUG 1 --- [ent@2362f559-23]
> o.a.c.c.s.i.s.SubscriptionHelper : [CHANNEL:META_CONNECT]:
> {clientId=91ffaqyez0nsf71n1yganknag4o, advice={reconnect=retry, interval=0,
> timeout=110000}, channel=/meta/connect, id=8776, successful=true}
> 2018-09-22 05:26:20.108 INFO 1 --- [ent@2362f559-22]
> o.a.c.c.s.i.s.SubscriptionHelper : Successfully restarted!
> {quote}
> Here are the logs afterward, where on getting 403 error camel tries to
> reconnect, but does not subscribe to topic
> {quote}
> 2018-09-22 08:27:54.440 WARN 1 --- [ent@2362f559-24]
> o.a.c.c.s.i.s.SubscriptionHelper : Connect failure:
> {advice={reconnect=handshake, interval=0}, channel=/meta/connect, id=8876,
> error=403::Unknown client, successful=false}
> 2018-09-22 08:27:54.489 DEBUG 1 --- [ent@2362f559-19]
> o.a.c.c.s.i.s.SubscriptionHelper$5 : Received messages
> [{ext={replay=true, payload.format=true}, minimumVersion=1.0,
> clientId=8318v3qm6whrb71uj5d6w2qv97q,
> supportedConnectionTypes=[Ljava.lang.Object;@1b0b2091,
> channel=/meta/handshake, id=8877, version=1.0, successful=true}]
> 2018-09-22 08:27:54.489 DEBUG 1 --- [ent@2362f559-19]
> o.a.c.c.s.i.s.SubscriptionHelper : [CHANNEL:META_HANDSHAKE]:
> {ext={replay=true, payload.format=true}, minimumVersion=1.0,
> clientId=8318v3qm6whrb71uj5d6w2qv97q,
> supportedConnectionTypes=[Ljava.lang.Object;@1b0b2091,
> channel=/meta/handshake, id=8877, version=1.0, successful=true}
> 2018-09-22 08:27:54.526 DEBUG 1 --- [ent@2362f559-24]
> o.a.c.c.s.i.s.SubscriptionHelper$5 : Received messages
> [{clientId=8318v3qm6whrb71uj5d6w2qv97q, advice={reconnect=retry, interval=0,
> timeout=110000}, channel=/meta/connect, id=8878, successful=true}]
> 2018-09-22 08:27:54.527 DEBUG 1 --- [ent@2362f559-24]
> o.a.c.c.s.i.s.SubscriptionHelper : [CHANNEL:META_CONNECT]:
> {clientId=8318v3qm6whrb71uj5d6w2qv97q, advice={reconnect=retry, interval=0,
> timeout=110000}, channel=/meta/connect, id=8878, successful=true}
> 2018-09-22 08:29:44.566 DEBUG 1 --- [ent@2362f559-19]
> o.a.c.c.s.i.s.SubscriptionHelper$5 : Received messages
> [{clientId=8318v3qm6whrb71uj5d6w2qv97q, channel=/meta/connect, id=8879,
> successful=true}]
> {quote}
> h1. Desired functionality
> Salesforce component to continue to try reconnect *without* dropping the topic
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
