You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@camel.apache.org by "Jeremy Ross (Jira)" <ji...@apache.org> on 2021/01/06 03:45:00 UTC
[jira] [Commented] (CAMEL-14138) Salesforce: a synchronous call
that follow an asynchronous call will always result in a TimeoutException
[ https://issues.apache.org/jira/browse/CAMEL-14138?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17259389#comment-17259389 ]
Jeremy Ross commented on CAMEL-14138:
-------------------------------------
I've dug into this a little more, but I don't have the camel-core chops to know how to fix. Here's what I think is happening:
* AbstractClientBase#doHttpRequest calls salesforce, passing a Listener instance to the HttpClient.
* Jetty client calls the Listener's [onComplete|https://github.com/apache/camel/blob/f735261d75a296b1ed6baf5b947e9d2710fda368/components/camel-salesforce/camel-salesforce-component/src/main/java/org/apache/camel/component/salesforce/internal/client/AbstractClientBase.java#L193]. A key point here is that onComplete gets blocked [here|https://github.com/apache/camel/blob/f735261d75a296b1ed6baf5b947e9d2710fda368/components/camel-salesforce/camel-salesforce-component/src/main/java/org/apache/camel/component/salesforce/internal/client/AbstractClientBase.java#L248] and never returns (#1 in screen shot).
* Camel continues to the second (synchronous) query. I've confirmed via debugging proxy that this query returns successfully, however HttpClient uses a *single* thread [for all listeners|https://www.eclipse.org/jetty/documentation/jetty-9/index.html#http-client]:
{quote}The implementation invokes these listeners in the same thread that is used to process the request or response. Therefore,* if the application code in these listeners takes a long time to execute, the request or response processing is delayed until the listener returns*.
{quote}
* Because the first call Listener#onComplete is blocked, HttpClient never calls the second query's Listener, and things get stuck at #2 in screen shot.
* Then IdleTimeout exception happens.
* [Invoking|https://github.com/apache/camel/blob/f735261d75a296b1ed6baf5b947e9d2710fda368/components/camel-salesforce/camel-salesforce-component/src/main/java/org/apache/camel/component/salesforce/internal/client/AbstractClientBase.java#L248] the Camel callback in a new thread "solves" the problem, however this probably is not playing nice with the camel threading/reactive system:
{code:java}
new Thread() {
@Override
public void run() {
callback.onResponse(getContentAsInputStream(), headers, null);
}
}.start();
{code}
Paging [~zregvart] and [~davsclaus] for help.
!Call stack.png!
> Salesforce: a synchronous call that follow an asynchronous call will always result in a TimeoutException
> --------------------------------------------------------------------------------------------------------
>
> Key: CAMEL-14138
> URL: https://issues.apache.org/jira/browse/CAMEL-14138
> Project: Camel
> Issue Type: Bug
> Components: camel-salesforce
> Affects Versions: 3.0.0.RC3
> Reporter: Jeremy Ross
> Priority: Major
> Fix For: 3.x
>
> Attachments: Call stack.png, thread-dump.txt
>
>
> Using the {{synchronous}} URL option, a synchronous operation following an asynchronous operation will result in a {{java.util.concurrent.TimeoutException}}. Subsequent synchronous operations will succeed. Despite the {{TimeoutException}}, the operation can still be successful on the salesforce side. I've yet to determine why Camel thinks the operation is timing out.
> Repro:
> {code:java}
> from("direct:synchronousTest")
> .setBody(() -> {
> Contact c = new Contact();
> c.setLastName("Test");
> return c;
> })
> .to("salesforce:createSObject?synchronous=false") // no issues
> .setBody(() -> {
> Contact c = new Contact();
> c.setLastName("Test");
> return c;
> })
> .to("salesforce:createSObject?synchronous=true"); // TimeoutException
> {code}
> stack trace:
> {noformat}
> org.apache.camel.component.salesforce.api.SalesforceException: Unexpected error {0:null} executing {POST:https://cs44.salesforce.com/services/data/v45.0/sobjects/Contact}
> at org.apache.camel.component.salesforce.internal.client.AbstractClientBase$1.onComplete(AbstractClientBase.java:206) ~[camel-salesforce-3.0.0-SNAPSHOT.jar:3.0.0-SNAPSHOT]
> at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:196) ~[jetty-client-9.4.19.v20190610.jar:9.4.19.v20190610]
> at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:188) ~[jetty-client-9.4.19.v20190610.jar:9.4.19.v20190610]
> at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:441) ~[jetty-client-9.4.19.v20190610.jar:9.4.19.v20190610]
> at org.eclipse.jetty.client.HttpReceiver.abort(HttpReceiver.java:523) ~[jetty-client-9.4.19.v20190610.jar:9.4.19.v20190610]
> at org.eclipse.jetty.client.HttpChannel.abortResponse(HttpChannel.java:156) ~[jetty-client-9.4.19.v20190610.jar:9.4.19.v20190610]
> at org.eclipse.jetty.client.HttpChannel.abort(HttpChannel.java:149) ~[jetty-client-9.4.19.v20190610.jar:9.4.19.v20190610]
> at org.eclipse.jetty.client.HttpExchange.abort(HttpExchange.java:257) ~[jetty-client-9.4.19.v20190610.jar:9.4.19.v20190610]
> at org.eclipse.jetty.client.HttpConversation.abort(HttpConversation.java:149) ~[jetty-client-9.4.19.v20190610.jar:9.4.19.v20190610]
> at org.eclipse.jetty.client.HttpRequest.abort(HttpRequest.java:766) ~[jetty-client-9.4.19.v20190610.jar:9.4.19.v20190610]
> at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.abort(HttpConnectionOverHTTP.java:204) ~[jetty-client-9.4.19.v20190610.jar:9.4.19.v20190610]
> at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.close(HttpConnectionOverHTTP.java:190) ~[jetty-client-9.4.19.v20190610.jar:9.4.19.v20190610]
> at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onIdleExpired(HttpConnectionOverHTTP.java:145) ~[jetty-client-9.4.19.v20190610.jar:9.4.19.v20190610]
> at org.eclipse.jetty.io.ssl.SslConnection.onIdleExpired(SslConnection.java:302) ~[jetty-io-9.4.19.v20190610.jar:9.4.19.v20190610]
> at org.eclipse.jetty.io.AbstractEndPoint.onIdleExpired(AbstractEndPoint.java:401) ~[jetty-io-9.4.19.v20190610.jar:9.4.19.v20190610]
> at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:171) ~[jetty-io-9.4.19.v20190610.jar:9.4.19.v20190610]
> at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:113) ~[jetty-io-9.4.19.v20190610.jar:9.4.19.v20190610]
> at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[na:na]
> at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[na:na]
> at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[na:na]
> at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
> at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]
> at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
> Caused by: java.util.concurrent.TimeoutException: Idle timeout 10000 ms
> {noformat}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)