[CAMEL-12871] Camel-salesforce component drops the streaming topic

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.21.1, 3.7.0
• Fix Version/s: 3.7.1, 3.8.0
• Component/s: camel-salesforce
• Estimated Complexity: Moderate
• Assignee: Zoran Regvart
• Reporter: Hemang Ajmera
• Created: 09/Oct/18 06:56
• Updated: 18/Dec/20 12:11
• Resolved: 18/Dec/20 12:11

Description

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.

Observation

Here is the logs which show good reconnect. We can see that camel attempts to subscribe to topic /topic/AccountOwner

2018-09-12 02:54:23.530 DEBUG 1 — [ent@2362f559-20] o.a.c.c.s.i.s.SubscriptionHelper$5 : Received messages [{advice=

Unknown macro: {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=

, 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=

Unknown macro: {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=

Unknown macro: {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=

, 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=

Unknown macro: {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=

, 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 [

Unknown macro: {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]:

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 ....

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.

2018-09-22 05:26:17.121 WARN 1 — [ent@2362f559-23] o.a.c.c.s.i.s.SubscriptionHelper : Connect failure: {advice=

Unknown macro: {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=

Unknown macro: {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=

, 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=

Unknown macro: {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=

, 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 [

Unknown macro: {channel=/meta/disconnect}

, {clientId=5vgmiblu8etx0q3typo6d5tgn, advice=

Unknown macro: {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=

, 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=

Unknown macro: {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=

, 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=

Unknown macro: {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=

Unknown macro: {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=

, 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=

Unknown macro: {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=

, 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!

Here are the logs afterward, where on getting 403 error camel tries to reconnect, but does not subscribe to topic

2018-09-22 08:27:54.440 WARN 1 — [ent@2362f559-24] o.a.c.c.s.i.s.SubscriptionHelper : Connect failure: {advice=

Unknown macro: {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=

Unknown macro: {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=

, 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=

Unknown macro: {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=

, 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 [

Unknown macro: {clientId=8318v3qm6whrb71uj5d6w2qv97q, channel=/meta/connect, id=8879, successful=true}

]

Desired functionality

Salesforce component to continue to try reconnect without dropping the topic

Issue Links

• links to: GitHub Pull Request #4778