Several HttpclientPost Bp may go to I/O wait or active states, CloseCode.HANDSHAKE_FAILURE

Symptom

This issue was one of the issue with a customer having database cpu spiking, GIS node going down and memory issues.

Hence symptoms of this perimeter handshake failure issue may have been clouded by other symptoms for couple more issues occurring at the same time.

Here are few observations that may be related to only handshake failures,

HttpclientPost Bps goes to an IO wait or active state
http client handshake failure exceptions in httpclient.log.

[2008-05-28 04:15:47.981] DEBUG <24263627> 000000000000 GLOBAL_SCOPE CustomConnectAgent.closed(CC) was closed from the perimeter side: CloseCode.HANDSHAKE_FAILURE
[2008-05-28 04:15:47.981] DEBUG <24263627> 000000000000 GLOBAL_SCOPE CustomConnectAgent.handleFailure() - Starting with failure message [Connection was closed from the perimeter side with error: CloseCode.HANDSHAKE_FAILURE]
[2008-05-28 04:15:47.981] ERROR <24263627> 000000000000 GLOBAL_SCOPE CustomConnectAgent.closed(CC)encountered error due to [Connection was closed from the perimeter side with error: CloseCode.HANDSHAKE_FAILURE]
[2008-05-28 04:15:47.981] DEBUG <24998214> 000000000000 GLOBAL_SCOPE HttpSession.waitForResults(l) - results obtained
[2008-05-28 04:15:47.981] DEBUG <24998214> 000000000000 GLOBAL_SCOPE HttpClient.sendRequest() - Verifying if any Session failure after sending ...
[2008-05-28 04:15:47.982] DEBUG <24998214> 000000000000 GLOBAL_SCOPE HttpClient.checkForFailures() - checking for errors...
[2008-05-28 04:15:47.982] DEBUG <24998214> 000000000000 GLOBAL_SCOPE HttpClient.checkForFailures() - session currently in state of [Waiting]
[2008-05-28 04:15:47.982] DEBUG <24998214> 000000000000 GLOBAL_SCOPE HttpClient.checkForFailures() - ...none found; state machine and session are ready.
[2008-05-28 04:15:47.982] DEBUG <24998214> 000000000000 GLOBAL_SCOPE HttpClient.sendRequest() - Completed.
[2008-05-28 04:15:48.036] DEBUG <WFE.412636.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.processData() - Start processing ...
[2008-05-28 04:15:48.036] DEBUG <WFE.412636.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.primitiveProcessData() - Starting ..
[2008-05-28 04:15:48.042] DEBUG <HAR.412636.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.findLittleAdapter() - ServicesControllerImpl found an adapter of type class com.sterlingcommerce.woodstock.services.httpclient.HttpClientAdapterImpl_Stub given service name [GWW_HTTP_CLIENT_GRP]
[2008-05-28 04:15:47.981] DEBUG <24263627> 000000000000 GLOBAL_SCOPE HttpSession.handleHttpCommand(S) - received command [FAILURE].
[2008-05-28 04:15:48.055] DEBUG <WFE.412633.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.processData() - Start processing ...
[2008-05-28 04:15:48.06] DEBUG <WFE.412633.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.primitiveProcessData() - Starting ..
[2008-05-28 04:15:48.064] DEBUG <24263627> 000000000000 GLOBAL_SCOPE HttpSession.handleHttpCommand(S,HCR) - received request [null]
[2008-05-28 04:15:48.065] DEBUG <HAR.412633.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.findLittleAdapter() - ServicesControllerImpl found an adapter of type class com.sterlingcommerce.woodstock.services.httpclient.HttpClientAdapterImpl_Stub given service name [GWW_HTTP_CLIENT_GRP]
[2008-05-28 04:15:48.065] DEBUG <HAR.412636.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.extractDocStorageType() - Starting ...
[2008-05-28 04:15:48.065] DEBUG <HAR.412633.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.extractDocStorageType() - Starting ...
[2008-05-28 04:15:48.065] DEBUG <HAR.412633.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.extractDocStorageType() - Set storage type as [4]
[2008-05-28 04:15:48.065] DEBUG <HAR.412633.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.extractProfileId() - profile ID is NOT available.
[2008-05-28 04:15:48.066] DEBUG <HAR.412633.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.extractHostAndPort() - - Configured remote URL is not specified, extracting RemoteHost and RemotePort params ...
[2008-05-28 04:15:48.066] DEBUG <HAR.412633.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.extractHostAndPort() - - Configured remote host from WFC [prpyap01.sap.grainger.com]
[2008-05-28 04:15:48.066] DEBUG <HAR.412633.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.extractHostAndPort() - - Configured remote port from WFC [443]
[2008-05-28 04:15:48.066] DEBUG <HAR.412633.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.extractBasicAuth() - Username specified in BP [null]
[2008-05-28 04:15:48.066] DEBUG <HAR.412633.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.extractSSL() - SSL specified in WFC is [Must]
[2008-05-28 04:15:48.066] DEBUG <HAR.412633.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.extractSSL() - SSL is required and BP specifies CA certificate Id [prsbn043:fe64b9:114ff5b7556:7937] and cipher strength [Strong]
[2008-05-28 04:15:48.066] DEBUG <HAR.412633.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.extractSSL() - SSL is required and Client Key certificate Id from BP [null]
[2008-05-28 04:15:48.067] DEBUG <HAR.412636.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.extractDocStorageType() - Set storage type as [4]
[2008-05-28 04:15:48.067] DEBUG <HAR.412636.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.extractProfileId() - profile ID is NOT available.
[2008-05-28 04:15:48.067] DEBUG <HAR.412636.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.extractHostAndPort() - - Configured remote URL is not specified, extracting RemoteHost and RemotePort params ...
[2008-05-28 04:15:48.067] DEBUG <14209356> 000000000000 GLOBAL_SCOPE HttpClient.createSession() - Starting ...
[2008-05-28 04:15:48.067] DEBUG <24263627> 000000000000 GLOBAL_SCOPE HttpSession.handleHttpCommand(S,HCR) - parsed [FAILURE] to [FAILURE].
[2008-05-28 04:15:48.067] DEBUG <24263627> 000000000000 GLOBAL_SCOPE psclientcommon.Session.handleCommand(C,O) received command [FAILURE].
[2008-05-28 04:15:48.067] DEBUG <24263627> 000000000000 GLOBAL_SCOPE StateMachine.handleCommand(IS,C,O) entering with state [Waiting], command [FAILURE], and argument [null].
[2008-05-28 04:15:48.067] WARN <24263627> 000000000000 GLOBAL_SCOPE StateMachine.handleCommand(IS,C,O) handling [FAILURE] with undefined transitions, executing unaccepted handler and not transitioning state.
[2008-05-28 04:15:48.068] DEBUG <24263627 SGWW_HTTP_CLIENT_ADAPTER_1_HTTPClientAdapter_node1_1211966138032166:63715> 000000000000 GLOBAL_SCOPE Command.execute(IS,b,O) starting on command [FAILURE], accepted = [false], implemented = [true].
[2008-05-28 04:15:48.068] DEBUG <24263627 SGWW_HTTP_CLIENT_ADAPTER_1_HTTPClientAdapter_node1_1211966138032166:63715> 000000000000 GLOBAL_SCOPE Command.execute(IS,b,O) ...Entering handleFAILURECommand
[2008-05-28 04:15:48.068] DEBUG <24263627 SGWW_HTTP_CLIENT_ADAPTER_1_HTTPClientAdapter_node1_1211966138032166:63715> 000000000000 GLOBAL_SCOPE HttpCommand.handleFAILURECommand(IS,b,O) - starting on command [FAILURE], accepted = [false]
[2008-05-28 04:15:48.069] DEBUG <24263627 SGWW_HTTP_CLIENT_ADAPTER_1_HTTPClientAdapter_node1_1211966138032166:63715> 000000000000 GLOBAL_SCOPE HttpCommand.handleFAILURECommand(IS,b,O) - calling performCallback on session [com.sterlingcommerce.woodstock.services.httpclient.session.HttpSession@181f460] with response HttpClientResponse: HTTP status [-1] HTTP reason phrase [Internal Error: Connection was closed from the perimeter side with error: CloseCode.HANDSHAKE_FAILURE] Primary Document [null]
[2008-05-28 04:15:48.069] DEBUG <24263627 SGWW_HTTP_CLIENT_ADAPTER_1_HTTPClientAdapter_node1_1211966138032166:63715> 000000000000 GLOBAL_SCOPE HttpSession.performCallback() - Final response document is [null/empty]. Performing workflow resume...
[2008-05-28 04:15:48.069] DEBUG <24263627 SGWW_HTTP_CLIENT_ADAPTER_1_HTTPClientAdapter_node1_1211966138032166:63715> 000000000000 GLOBAL_SCOPE HttpClient.resumeWorkFlow() - Starting ...
[2008-05-28 04:15:48.069] DEBUG <24263627 SGWW_HTTP_CLIENT_ADAPTER_1_HTTPClientAdapter_node1_1211966138032166:63715> 000000000000 GLOBAL_SCOPE HttpClient.resumeWorkFlow() - Received response: HttpClientResponse: HTTP status [-1] HTTP reason phrase [Internal Error: Connection was closed from the perimeter side with error: CloseCode.HANDSHAKE_FAILURE] Primary Document [null]
[2008-05-28 04:15:48.067] DEBUG <HAR.412636.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.extractHostAndPort() - - Configured remote host from WFC [prpyap01.sap.grainger.com]
[2008-05-28 04:15:48.069] DEBUG <HAR.412636.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.extractHostAndPort() - - Configured remote port from WFC [443]
[2008-05-28 04:15:48.069] DEBUG <HAR.412636.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.extractBasicAuth() - Username specified in BP [null]
[2008-05-28 04:15:48.07] DEBUG <HAR.412636.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.extractSSL() - SSL specified in WFC is [Must]
[2008-05-28 04:15:48.07] DEBUG <HAR.412636.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.extractSSL() - SSL is required and BP specifies CA certificate Id [prsbn043:fe64b9:114ff5b7556:7937] and cipher strength [Strong]
[2008-05-28 04:15:48.07] DEBUG <HAR.412636.Thread> 000000000000 GLOBAL_SCOPE HTTPClientBeginService.extractSSL() - SSL is required and Client Key certificate Id from BP [null]
......................

.....................

[2008-05-28 04:16:01.438] DEBUG <10134690> 000000000000 GLOBAL_SCOPE CustomConnectAgent.closed(CC) was closed from the perimeter side: CloseCode.HANDSHAKE_FAILURE
[2008-05-28 04:16:01.438] DEBUG <10134690> 000000000000 GLOBAL_SCOPE CustomConnectAgent.handleFailure() - Starting with failure message [Connection was closed from the perimeter side with error: CloseCode.HANDSHAKE_FAILURE]
[2008-05-28 04:16:01.438] DEBUG <28895335> 000000000000 GLOBAL_SCOPE HttpSession.waitForResults(l) - results obtained
[2008-05-28 04:16:01.439] DEBUG <28895335> 000000000000 GLOBAL_SCOPE HttpClient.sendRequest() - Verifying if any Session failure after sending ...
[2008-05-28 04:16:01.439] DEBUG <28895335> 000000000000 GLOBAL_SCOPE HttpClient.checkForFailures() - checking for errors...
[2008-05-28 04:16:01.439] DEBUG <28895335> 000000000000 GLOBAL_SCOPE HttpClient.checkForFailures() - session currently in state of [Waiting]
[2008-05-28 04:16:01.439] DEBUG <28895335> 000000000000 GLOBAL_SCOPE HttpClient.checkForFailures() - ...none found; state machine and session are ready.
[2008-05-28 04:16:01.439] DEBUG <28895335> 000000000000 GLOBAL_SCOPE HttpClient.sendRequest() - Completed.
[2008-05-28 04:16:01.459] ERROR <10134690> 000000000000 GLOBAL_SCOPE CustomConnectAgent.closed(CC)encountered error due to [Connection was closed from the perimeter side with error: CloseCode.HANDSHAKE_FAILURE]
[2008-05-28 04:16:01.46] DEBUG <10134690> 000000000000 GLOBAL_SCOPE HttpSession.handleHttpCommand(S) - received command [FAILURE].
[2008-05-28 04:16:01.46] DEBUG <10134690> 000000000000 GLOBAL_SCOPE HttpSession.handleHttpCommand(S,HCR) - received request [null]
[2008-05-28 04:16:01.46] DEBUG <10134690> 000000000000 GLOBAL_SCOPE HttpSession.handleHttpCommand(S,HCR) - parsed [FAILURE] to [FAILURE].
[2008-05-28 04:16:01.46] DEBUG <10134690> 000000000000 GLOBAL_SCOPE psclientcommon.Session.handleCommand(C,O) received command [FAILURE].
[2008-05-28 04:16:01.46] DEBUG <10134690> 000000000000 GLOBAL_SCOPE StateMachine.handleCommand(IS,C,O) entering with state [Waiting], command [FAILURE], and argument [null].
[2008-05-28 04:16:01.46] WARN <10134690> 000000000000 GLOBAL_SCOPE StateMachine.handleCommand(IS,C,O) handling [FAILURE] with undefined transitions, executing unaccepted handler and not transitioning state.