1

We have a requirement that when an Experience API invokes a Process API it needs to timeout within 5 seconds if the Process API is down.

So we configured the HTTP Request componet to use the connectionTimeout property in HTTP_Request_configuration:

<http:request-connection host="${http.process.api.host}" port="${http.process.api.port}"
   maxConnections="${http.process.api.maxConnections}" connectionIdleTimeout="${http.process.api.timeout}"
   responseBufferSize="${http.process.api.bufferSize}">

  <http:client-socket-properties >

    <sockets:tcp-client-socket-properties connectionTimeout="${http.process.api.client.timeout}"/>

  </http:client-socket-properties>
</http:request-connection>

And when testing in Studio it works okay (API is executed locally and configured to hit the Process API in CloudHub) and times out in around 5 seconds as set in the http.process.api.client.timeout property (5000).

But when the Experience API is deployed to CloudHub and we test it, the timeout occurs after 15 seconds.

If we drop the timeout to 4000ms, it takes around 12 seconds, 2000ms, it takes around 6 seconds etc.

Any ideas why and how we can fix it in CloudHub?

Cheers, Steve

Extra details (16/05/2021):

The two network use cases:

  1. Postman (Local) > Exp API (Cloud Hub) > Process API (Cloud Hub)
  2. Postman (Local) > Exp API (Local (Studio)) > Process API (Cloud Hub)

When (1) is tested where the Process API is down, the time out occurs after 15 seconds. When (2) is tesed where the Process API is down, the time out occurs after 5 seconds.

We are using Mule Runtime 4.3 and the HTTP connector is version 1.5.6.

Here is the HTTP Request config in full:

  <http:request-config name="process-api-HTTPS_Request_configuration" doc:name="HTTP Request configuration" doc:id="6532744b-8be1-4443-b441-f95a66148de3" basePath="${http.process.api.basepath}" responseTimeout="${http.process.api.response.timeout}">
    <http:request-connection host="${http.process.api.host}" port="${http.process.api.port}"
      maxConnections="${http.process.api.maxConnections}" connectionIdleTimeout="${http.process.api.timeout}"
      responseBufferSize="${http.process.api.bufferSize}" protocol="HTTPS">
      <tls:context >
        <tls:trust-store insecure="true" />
      </tls:context>
      <http:client-socket-properties >
        <sockets:tcp-client-socket-properties connectionTimeout="${http.process.api.client.timeout}" />
      </http:client-socket-properties>
    </http:request-connection>
  </http:request-config>

And the HTTP Request:

    <http:request method="POST" doc:name="Process API Request" doc:id="fa1f1a2f-ea97-4829-8f84-677477b7ddfd" config-ref="process-api-HTTPS_Request_configuration" path="${http.process.api.path}">
      <http:headers ><![CDATA[#[output application/java
---
{
    "source" : p('constant.header.source'),
    "correlationId" : correlationId,
    "Content-Type" : "application/json",
    "X-Client-Secret" : p('secure::process.api.clientsecret'),
    "X-Client-Id" : p('secure::process.api.clientid')
}]]]></http:headers>
    </http:request>

Properties:

http.process.api.protocol=HTTPS
http.process.api.host=mule-worker-internal-xxxx-process-api-dev.au-s1.cloudhub.io
http.process.api.port=8092
http.process.api.basepath=/api/v1/
http.process.api.timeout=5000
http.process.api.client.timeout=5000
http.process.api.response.timeout=5000
http.process.api.maxConnections=-1
http.process.api.bufferSize=1024
http.process.api.path.general=/leads/product

Experience API Logs:

09:49:13.891     05/16/2021     Worker-0     [MuleRuntime].uber.509: [xxxx-exp-api-1a-tst].post:\enquiries\general:application\json:experience-api-config.CPU_LITE @b8fba0c     INFO
event:57bfc3f0-b5dc-11eb-9e1f-061654e69fc6 Send Enquiries flow START
09:49:13.892     05/16/2021     Worker-0     [MuleRuntime].uber.509: [xxxx-exp-api-1a-tst].post:\enquiries\general:application\json:experience-api-config.CPU_LITE @b8fba0c     INFO
event:57bfc3f0-b5dc-11eb-9e1f-061654e69fc6 Start Process API General Enquiry Request
09:49:26.772     05/16/2021     Worker-0     connection-pool-delays-thread-pool(1)     ERROR
event:57bfc3f0-b5dc-11eb-9e1f-061654e69fc6 Error sending HTTP request to https://mule-worker-internal-xxxx-proc-api-1a-tst.au-s1.cloudhub.io:8092/api/v1/leads/product
09:49:26.784     05/16/2021     Worker-0     connection-pool-delays-thread-pool(1)     ERROR
event:57bfc3f0-b5dc-11eb-9e1f-061654e69fc6 
********************************************************************************
Message               : HTTP POST on resource 'https://mule-worker-internal-xxxx-proc-api-1a-tst.au-s1.cloudhub.io:8092/api/v1/leads/product' failed: Connect timeout.
Element               : xxxx-managementFlow:post:general/processors/1 @ xxxx-exp-api-1a-tst:process/xxxx-management.xml:10 (Lead Management Process API General Enquiry)
Element DSL           : <http:request method="POST" doc:name="Process API General Enquiry" doc:id="fa1f1a2f-ea97-4829-8f84-677477b7ddfd" config-ref="process-api-HTTPS_Request_configuration" path="${http.process.api.path.general}">
                        <http:headers>#[output application/java
                        ---
                        {
                            "source" : p('constant.header.source'),
                            "correlationId" : correlationId,
                            "Content-Type" : "application/json",
                            "X-Client-Secret" : p('secure::process.api.clientsecret'),
                            "X-Client-Id" : p('secure::process.api.clientid')
                        }]</http:headers>
                        </http:request>
Error type            : HTTP:CONNECTIVITY
FlowStack             : at xxxx-managementFlow:post:general(xxxx-managementFlow:post:general/processors/1 @ xxxx-exp-api-1a-tst:process/xxxx-management.xml:10 (Process API General Enquiry))
                        at impl-experience-main:enquiries-general:subFlow(impl-experience-main:enquiries-general:subFlow/processors/1 @ xxxx-exp-api-1a-tst:implementation/impl-experience-main.xml:9 (xxxx-managementFlow:post:general))
                        at post:\enquiries\general:application\json:experience-api-config(post:\enquiries\general:application\json:experience-api-config/processors/0 @ xxxx-exp-api-1a-tst:experience-api.xml:56 (impl-experience-main:send-feedback:subFlow))
                        at experience-api-main(experience-api-main/processors/1 @ xxxx-exp-api-1a-tst:experience-api.xml:28 (Request Router))
Payload Type          : org.mule.runtime.core.internal.streaming.bytes.ManagedCursorStreamProvider
--------------------------------------------------------------------------------
Root Exception stack trace:
java.net.ConnectException: Connect timeout
    at org.glassfish.grizzly.connectionpool.SingleEndpointPool$ConnectCompletionHandler.cancelled(SingleEndpointPool.java:1290)
    at org.glassfish.grizzly.impl.SafeFutureImpl.notifyCompletionHandlers(SafeFutureImpl.java:185)
    at org.glassfish.grizzly.impl.SafeFutureImpl.done(SafeFutureImpl.java:277)
    at org.glassfish.grizzly.impl.SafeFutureImpl$Sync.innerCancel(SafeFutureImpl.java:389)
    at org.glassfish.grizzly.impl.SafeFutureImpl.cancel(SafeFutureImpl.java:247)
    at org.glassfish.grizzly.connectionpool.SingleEndpointPool$ConnectTimeoutWorker.doWork(SingleEndpointPool.java:1365)
    at org.glassfish.grizzly.connectionpool.SingleEndpointPool$ConnectTimeoutWorker.doWork(SingleEndpointPool.java:1357)
    at org.glassfish.grizzly.utils.DelayedExecutor$DelayedRunnable.run(DelayedExecutor.java:171)
    at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:593)
    at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:573)
    at java.lang.Thread.run(Thread.java:748)

********************************************************************************
09:49:26.798     05/16/2021     Worker-0     connection-pool-delays-thread-pool(1)     ERROR
event:57bfc3f0-b5dc-11eb-9e1f-061654e69fc6 
********************************************************************************
Message               : HTTP POST on resource 'https://mule-worker-internal-xxxx-proc-api-1a-tst.au-s1.cloudhub.io:8092/api/v1/leads/product' failed: Connect timeout.
Error type            : HTTP:CONNECTIVITY
Payload Type          : org.mule.runtime.core.internal.streaming.bytes.ManagedCursorStreamProvider
--------------------------------------------------------------------------------
Root Exception stack trace:
java.net.ConnectException: Connect timeout
    at org.glassfish.grizzly.connectionpool.SingleEndpointPool$ConnectCompletionHandler.cancelled(SingleEndpointPool.java:1290)
    at org.glassfish.grizzly.impl.SafeFutureImpl.notifyCompletionHandlers(SafeFutureImpl.java:185)
    at org.glassfish.grizzly.impl.SafeFutureImpl.done(SafeFutureImpl.java:277)
    at org.glassfish.grizzly.impl.SafeFutureImpl$Sync.innerCancel(SafeFutureImpl.java:389)
    at org.glassfish.grizzly.impl.SafeFutureImpl.cancel(SafeFutureImpl.java:247)
    at org.glassfish.grizzly.connectionpool.SingleEndpointPool$ConnectTimeoutWorker.doWork(SingleEndpointPool.java:1365)
    at org.glassfish.grizzly.connectionpool.SingleEndpointPool$ConnectTimeoutWorker.doWork(SingleEndpointPool.java:1357)
    at org.glassfish.grizzly.utils.DelayedExecutor$DelayedRunnable.run(DelayedExecutor.java:171)
    at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:593)
    at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:573)
    at java.lang.Thread.run(Thread.java:748)

********************************************************************************
09:49:26.838     05/16/2021     Worker-0     [MuleRuntime].uber.509: [xxxx-exp-api-1a-tst].experience-api-main.CPU_INTENSIVE @223e1c0     ERROR
event:57bfc3f0-b5dc-11eb-9e1f-061654e69fc6 Unhandled Error
09:49:26.863     05/16/2021     Worker-0     [MuleRuntime].uber.509: [xxxx-exp-api-1a-tst].experience-api-main.CPU_INTENSIVE @223e1c0     ERROR
event:57bfc3f0-b5dc-11eb-9e1f-061654e69fc6 
********************************************************************************
Message               : HTTP POST on resource 'https://mule-worker-internal-xxxx-proc-api-1a-tst.au-s1.cloudhub.io:8092/api/v1/leads/product' failed: Connect timeout.
Error type            : HTTP:CONNECTIVITY
Payload Type          : org.mule.runtime.core.internal.streaming.bytes.ManagedCursorStreamProvider
--------------------------------------------------------------------------------
Root Exception stack trace:
java.net.ConnectException: Connect timeout
    at org.glassfish.grizzly.connectionpool.SingleEndpointPool$ConnectCompletionHandler.cancelled(SingleEndpointPool.java:1290)
    at org.glassfish.grizzly.impl.SafeFutureImpl.notifyCompletionHandlers(SafeFutureImpl.java:185)
    at org.glassfish.grizzly.impl.SafeFutureImpl.done(SafeFutureImpl.java:277)
    at org.glassfish.grizzly.impl.SafeFutureImpl$Sync.innerCancel(SafeFutureImpl.java:389)
    at org.glassfish.grizzly.impl.SafeFutureImpl.cancel(SafeFutureImpl.java:247)
    at org.glassfish.grizzly.connectionpool.SingleEndpointPool$ConnectTimeoutWorker.doWork(SingleEndpointPool.java:1365)
    at org.glassfish.grizzly.connectionpool.SingleEndpointPool$ConnectTimeoutWorker.doWork(SingleEndpointPool.java:1357)
    at org.glassfish.grizzly.utils.DelayedExecutor$DelayedRunnable.run(DelayedExecutor.java:171)
    at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:593)
    at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:573)
    at java.lang.Thread.run(Thread.java:748)

********************************************************************************

Enabled more logging:

org.mule.service.http.impl.service.HttpMessageLogger
org.mule.service.http
org.mule.extension.http
org.mule.runtime.core.internal.processor.LoggerMessageProcessor

and I can see the timeout internal occurs around 4 seconds (I decreased the time to 4000ms): https://pastebin.com/PaM3vEGF

But the exception handling is adding a lot of time, so the client response is 12 seconds.

Steve
  • 445
  • 1
  • 8
  • 18
  • Which version of Mule and the HTTP connector are you using in CloudHub? Kindly add the complete HTTP Request configuration. Please also add the complete error message you get on timeout, with all the lines. – aled May 15 '21 at 13:53
  • Thanks Aled for replying, I have added the extra details. – Steve May 16 '21 at 00:23
  • I don't see a reason for the issue however the HTTP connector version is fairly old (almost two years) and has a lot of known issues fixed in later releases. Can you test with the latest available version of the connector? See https://docs.mulesoft.com/release-notes/connector/connector-http to find the last release. It might at least provide some better error reporting. – aled May 17 '21 at 12:18
  • Thanks for looking Aled. Yep I've updated all the dependencies and still have the error. When I enabled more logging though (even using the old versions), I can see on CloudHub only it looks like there is a retry strategy kicking in. I can see the timeout stack trace 3 times, each 4 seconds after each other. This doesnt happen locally within Studio. So that explains why it is 3 times longer on CloudHub... but I need a way so I can configure it, so it doesnt happen. Any ideas? – Steve May 17 '21 at 22:34

0 Answers0