Graceful Shutdown - Open TCP Connection Handling is not working properly - APIM 4.0.0

[Sumudu-Sahan]

Description

When there is a live traffic to the node and when performing a graceful shutdown while there is a load, the server will not properly close the active connection threads and throwing the Send Timeout error and the server shutdown process is getting hanged until the EP timeout is reached.

Steps to Reproduce

• Start the pack and go to the publisher portal.
• Create an API. (Endpoint Timeout should be around 60 seconds)
• Configure a mock backend which was a delay around 10 seconds to send the response.
• Invoke the API.
• Immediately after invoking the API, try to do a graceful shutdown. (after 2-3 seconds from the API invocation) and able to see that the server is waiting to cleanup the active connection on the 8243 port.

TID: [-1234] [] [2023-08-28 20:20:17,195]  INFO {org.wso2.carbon.core.init.CarbonServerManager} - Shutdown hook triggered....
TID: [-1234] [] [2023-08-28 20:20:17,197]  INFO {org.wso2.carbon.core.init.CarbonServerManager} - Gracefully shutting down WSO2 API Manager...
TID: [-1234] [] [2023-08-28 20:20:17,223]  INFO {org.wso2.carbon.core.ServerManagement} - Starting to switch to maintenance mode...
TID: [-1234] [] [2023-08-28 20:20:17,223]  INFO {org.apache.synapse.transport.passthru.PassThroughHttpListener} - Stopping Pass-through HTTP Listener..
TID: [-1234] [] [2023-08-28 20:20:17,224]  INFO {org.apache.synapse.transport.passthru.core.PassThroughListeningIOReactorManager} - Pausing  IO Reactor bind for port 8280
TID: [-1234] [] [2023-08-28 20:20:17,225]  INFO {org.apache.synapse.transport.passthru.core.PassThroughListeningIOReactorManager} - Shutting down IO Reactor bind for port 8280
TID: [-1234] [] [2023-08-28 20:20:17,226]  INFO {org.apache.synapse.transport.passthru.core.PassThroughListeningIOReactorManager} - HTTP-Listener I/O dispatcher Listener shutdown.
TID: [-1234] [] [2023-08-28 20:20:17,227]  INFO {org.apache.synapse.transport.passthru.PassThroughHttpMultiSSLListener} - Stopping Pass-through HTTPS Listener..
TID: [-1234] [] [2023-08-28 20:20:17,227]  INFO {org.apache.synapse.transport.passthru.core.PassThroughListeningIOReactorManager} - Pausing  IO Reactor bind for port 8243
TID: [-1234] [] [2023-08-28 20:20:17,228]  INFO {org.apache.synapse.transport.passthru.core.PassThroughListeningIOReactorManager} - Waiting to cleanup active connections on port 8243: 1

• When sending the response from the backend to the gateway after 10 seconds delay, be able notice the below exception.

TID: [-1234] [] [2023-08-28 20:20:25,828] DEBUG {org.apache.synapse.transport.http.headers} - http-outgoing-1 << HTTP/1.1 200 OK
TID: [-1234] [] [2023-08-28 20:20:25,829] DEBUG {org.apache.synapse.transport.http.headers} - http-outgoing-1 << Content-Type: application/json; charset=utf-8
TID: [-1234] [] [2023-08-28 20:20:25,829] DEBUG {org.apache.synapse.transport.http.headers} - http-outgoing-1 << Content-Length: 3874
TID: [-1234] [] [2023-08-28 20:20:25,830] DEBUG {org.apache.synapse.transport.http.headers} - http-outgoing-1 << Date: Mon, 28 Aug 2023 14:50:25 GMT
TID: [-1234] [] [2023-08-28 20:20:25,830] DEBUG {org.apache.synapse.transport.http.headers} - http-outgoing-1 << Connection: keep-alive
TID: [-1234] [] [2023-08-28 20:20:25,849] ERROR {org.apache.synapse.transport.passthru.TargetHandler} - Exception occurred while processing response java.util.concurrent.RejectedExecutionException: Task org.apache.axis2.transport.base.threads.NativeWorkerPool$1@5d5ed837 rejected from org.apache.axis2.transport.base.threads.Axis2ThreadPoolExecutor@694a2f7c[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 2]
	at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2063)
	at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:830)
	at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1379)
	at org.apache.axis2.transport.base.threads.NativeWorkerPool.execute(NativeWorkerPool.java:169)
	at org.apache.synapse.transport.passthru.TargetHandler.responseReceived(TargetHandler.java:536)
	at org.apache.http.impl.nio.DefaultNHttpClientConnection.consumeInput(DefaultNHttpClientConnection.java:255)
	at org.apache.synapse.transport.http.conn.LoggingNHttpClientConnection.consumeInput(LoggingNHttpClientConnection.java:115)
	at org.apache.synapse.transport.passthru.ClientIODispatch.onInputReady(ClientIODispatch.java:83)
	at org.apache.synapse.transport.passthru.ClientIODispatch.onInputReady(ClientIODispatch.java:41)
	at org.apache.http.impl.nio.reactor.AbstractIODispatch.inputReady(AbstractIODispatch.java:114)
	at org.apache.http.impl.nio.reactor.BaseIOReactor.readable(BaseIOReactor.java:162)
	at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvent(AbstractIOReactor.java:337)
	at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvents(AbstractIOReactor.java:315)
	at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:276)
	at org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:104)
	at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:591)
	at java.lang.Thread.run(Thread.java:750)
TID: [-1234] [] [2023-08-28 20:20:25,853] ERROR {org.apache.synapse.transport.passthru.TargetHandler} - Unexpected error.

• After this error, the gateway paused the shutdown process until the EP timeout (60 seconds) reach and after that, the server continue the shutdown process as below. In this step, the gateway returned the 500 Internal Server Error with the Send Timeout error to the client side even the backend returned the 200 response.

TID: [-1234] [] [2023-08-28 20:21:30,784]  WARN {org.apache.synapse.core.axis2.TimeoutHandler} - Expiring message ID : urn:uuid:14432c0d-b5a2-4b6b-bb4d-80b499d117b9; dropping message after ENDPOINT_TIMEOUT of : 60 seconds for Endpoint [TEST_API--v1.0.0_APIproductionEndpoint], URI : http://localhost:3000/users, Received through API : TEST_API:v1.0.0Correlation ID : 10c7b09f-0188-4ad2-804a-09391245f288
TID: [-1234] [] [2023-08-28 20:21:30,786]  INFO {org.apache.synapse.endpoints.EndpointContext} - Endpoint : TEST_API--v1.0.0_APIproductionEndpoint with address http://localhost:3000 has been marked for SUSPENSION, but no further retries remain. Thus it will be SUSPENDED.
TID: [-1234] [] [2023-08-28 20:21:30,787]  WARN {org.apache.synapse.endpoints.EndpointContext} - Suspending endpoint : TEST_API--v1.0.0_APIproductionEndpoint with address http://localhost:3000 - current suspend duration is : 30000ms - Next retry after : Mon Aug 28 20:22:00 IST 2023
TID: [-1234] [] [2023-08-28 20:21:30,788]  INFO {org.apache.synapse.mediators.builtin.LogMediator} - {api:TEST_API:v1.0.0} STATUS = Executing default 'fault' sequence, ERROR_CODE = 101504, ERROR_MESSAGE = Send timeout
TID: [-1234] [] [2023-08-28 20:21:30,791] DEBUG {org.apache.synapse.transport.http.headers} - http-incoming-2 << HTTP/1.1 500 Internal Server Error
TID: [-1234] [] [2023-08-28 20:21:30,792] DEBUG {org.apache.synapse.transport.http.headers} - http-incoming-2 << activityid: 10c7b09f-0188-4ad2-804a-09391245f288
TID: [-1234] [] [2023-08-28 20:21:30,792] DEBUG {org.apache.synapse.transport.http.headers} - http-incoming-2 << Access-Control-Expose-Headers: 
TID: [-1234] [] [2023-08-28 20:21:30,792] DEBUG {org.apache.synapse.transport.http.headers} - http-incoming-2 << Access-Control-Allow-Origin: *
TID: [-1234] [] [2023-08-28 20:21:30,792] DEBUG {org.apache.synapse.transport.http.headers} - http-incoming-2 << Access-Control-Allow-Methods: GET
TID: [-1234] [] [2023-08-28 20:21:30,792] DEBUG {org.apache.synapse.transport.http.headers} - http-incoming-2 << Access-Control-Allow-Headers: authorization,Access-Control-Allow-Origin,Content-Type,SOAPAction,apikey,Internal-Key,Authorization
TID: [-1234] [] [2023-08-28 20:21:30,792] DEBUG {org.apache.synapse.transport.http.headers} - http-incoming-2 << Content-Type: application/json; charset=UTF-8
TID: [-1234] [] [2023-08-28 20:21:30,792] DEBUG {org.apache.synapse.transport.http.headers} - http-incoming-2 << Date: Mon, 28 Aug 2023 14:51:30 GMT
TID: [-1234] [] [2023-08-28 20:21:30,792] DEBUG {org.apache.synapse.transport.http.headers} - http-incoming-2 << Transfer-Encoding: chunked
TID: [-1234] [] [2023-08-28 20:21:30,792] DEBUG {org.apache.synapse.transport.http.headers} - http-incoming-2 << Connection: close
TID: [-1234] [] [2023-08-28 20:21:31,242]  INFO {org.apache.synapse.transport.passthru.core.PassThroughListeningIOReactorManager} - Shutting down IO Reactor bind for port 8243
TID: [-1234] [] [2023-08-28 20:21:31,243]  INFO {org.apache.synapse.transport.passthru.core.PassThroughListeningIOReactorManager} - HTTPS-Listener I/O dispatcher Listener shutdown.
TID: [-1234] [] [2023-08-28 20:21:31,243]  INFO {org.wso2.carbon.core.ServerManagement} - Stopped all transport listeners
TID: [-1234] [] [2023-08-28 20:21:31,243]  INFO {org.wso2.carbon.core.ServerManagement} - Waiting for request service completion...
TID: [-1234] [] [2023-08-28 20:21:31,249]  INFO {org.wso2.carbon.core.ServerManagement} - All requests have been served.
TID: [-1234] [] [2023-08-28 20:21:31,249]  INFO {org.wso2.carbon.core.ServerManagement} - Waiting for deployment completion...
<SHUTDOWN LOGS WILL PRINT AFTER THIS>

Affected Component

APIM

Version

4.0.0

Environment Details (with versions)

No response

Relevant Log Output

No response

Related Issues

No response

Suggested Labels

No response

[SavinduDimal]

Closing this issue as it is fixed by wso2/carbon-kernel#3661.