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:
- Postman (Local) > Exp API (Cloud Hub) > Process API (Cloud Hub)
- 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.