SSL renegotiations triggered by AG when renegotiation is disabled causing problems with applications

Upgrading Access Manager from 3.1 to 4.0. The upgrade went well and all users could authenticate successfully to the NAM Identity Server. Within the AG cluster however, there were a few 4.0 Access Gateway servers and a few 3.1 Access Gateway servers with users successfully hitting most applications on the 4.0 servers and a handful on the 3.1 servers.

One of the key internal applications was moved from the 3.1 AG to the 4.0 AG and as soon as users started hitting the application on the 4.0 AG server, reports came in of problems such as users seeing broken links or not being able to access certain functions on the page. Looking at the Fiddler logs on the workstation when the problem occured, we could see that certain requests made into the AG would not get a response (no HTTP status code back and a network level error).

Looking at the corresponding server side logs, we tracked down one such request:

// Here's the request that the AG gets from the browser

Aug 25 16:41:26 kogmaginp03 httpd[2789]: ID:725902:604:creq [10.154.245.118:62593->10.157.18.98:443] POST /genisys/A/MDSRate.asmx?mn=GetPostCodeSecurity
Aug 25 16:41:26 kogmaginp03 httpd[2789]: ID:725902:604:creq Accept: */*
Aug 25 16:41:26 kogmaginp03 httpd[2789]: ID:725902:604:creq Accept-Language: en-au
Aug 25 16:41:26 kogmaginp03 httpd[2789]: ID:725902:604:creq Referer: https://genisys.netiq.com/genisys/A/ChangeQ.aspx?b=035905&c=N&br=2&g=262&n=Shp+64%2c+Mall+Level%2c+WestEnd%2c+Cnr+Henry
Aug 25 16:41:26 kogmaginp03 httpd[2789]: ID:725902:604:creq Accept-Encoding: gzip, deflate
Aug 25 16:41:26 kogmaginp03 httpd[2789]: ID:725902:604:creq User-Agent: Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.1; WOW64; Trident/7.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729; .NET4.0C; .NET4.0E; InfoPath.3)
Aug 25 16:41:26 kogmaginp03 httpd[2789]: ID:725902:604:creq Host: genisys.netiq.com
Aug 25 16:41:26 kogmaginp03 httpd[2789]: ID:725902:604:creq Content-Length: 36
Aug 25 16:41:26 kogmaginp03 httpd[2789]: ID:725902:604:creq Connection: Keep-Alive
Aug 25 16:41:26 kogmaginp03 httpd[2789]: ID:725902:604:creq Cache-Control: no-cache
Aug 25 16:41:26 kogmaginp03 httpd[2789]: ID:725902:604:creq Cookie:
ignOnDefault=E08082; IPCZQX03a36c6c0a=030116030a9602c9d1f3190137303c4f015fbd00;NPCQ003-33393400=8f88df0c; ZNPCQ003-39343900=58b1fc8d; PS_TOKENEXPIRE=25_Aug_2015_06:02:19_GMT; ZNPCQ003-33383900=3b21754b; ASP.NET_SessionId=smmzc145uabjibaaukjcdn55
Aug 25 16:41:26 kogmaginp03 httpd[2789]: ID:725902:604:cres status:409 409 Conflict
Aug 25 16:41:26 kogmaginp03 httpd[2789]: ID:725902:604:cres X-Mag: 1CCE13A3CAB7D43E;f1edebe2;725902;usrLkup->0;usrBase->0;LocUsr;getPRBefFind->0;getPRBefFind->0;PRAfterFind->0;Genisys;Contract-none->0;SendSoapStart->0;SendSoapExit->3;CheckSB->3;3-checkSB:ERR;FPE->3;
Aug 25 16:41:26 kogmaginp03 httpd[2789]: ID:725902:604:cres Via: 1.1 genisys.netiq.com (Access Gateway-ag-1CCE13A3CAB7D43E-725902)
Aug 25 16:41:26 kogmaginp03 httpd[2789]: ID:725902:604:cres Content-Length: 0
Aug 25 16:41:26 kogmaginp03 httpd[2789]: ID:725902:604:cres Connection: close
Aug 25 16:41:26 kogmaginp03 httpd[2789]: ID:725902:604:cres Content-Type: text/html; charset=iso-8859-1

 // Here's the corresponding error_log

Aug 25 16:41:26 kogmaginp03 httpd[2789]: [info] AM#504600000 AMDEVICEID#ag-1CCE13A3CAB7D43E: AMAUTHID#: AMEVENTID#725902: validateCookie:local user.
Aug 25 16:41:26 kogmaginp03 httpd[2789]: [info] AM#504600100 AMDEVICEID#ag-1CCE13A3CAB7D43E: AMAUTHID#: AMEVENTID#725902: Restricted URL
Aug 25 16:41:26 kogmaginp03 httpd[2789]: [info] AM#504600000 AMDEVICEID#ag-1CCE13A3CAB7D43E: AMAUTHID#: AMEVENTID#725902: matched PR:Genisys
Aug 25 16:41:26 kogmaginp03 httpd[2789]: [info] AM#504600000 AMDEVICEID#ag-1CCE13A3CAB7D43E: AMAUTHID#: AMEVENTID#725902: Contract-none contract(intranet/netidentity/uri ->  )
Aug 25 16:41:26 kogmaginp03 httpd[2789]: [info] AMEVENTID#725902: Requesting connection re-negotiation, referer: https://genisys.netiq.com/genisys/A/ChangeQ.aspx?b=035905&c=N&br=2&g=262&n=Shp+64%2c+Mall+Level%2c+WestEnd%2c+Cnr+Henry
Aug 25 16:41:26 kogmaginp03 httpd[2789]: [error] AMEVENTID#725902: insecure SSL re-negotiation required, but a pipelined request is present; keepalive disabled, referer: https://genisys.netiq.com/genisys/A/ChangeQ.aspx?b=035905&c=N&br=2&g=262&n=Shp+64%2c+Mall+Level%2c+WestEnd%2c+Cnr+Henry
Aug 25 16:41:26 kogmaginp03 httpd[2789]: [info] AMEVENTID#725902: Awaiting re-negotiation handshake, referer: https://genisys.netiq.com/genisys/A/ChangeQ.aspx?b=035905&c=N&br=2&g=262&n=Shp+64%2c+Mall+Level%2c+WestEnd%2c+Cnr+Henry
Aug 25 16:41:26 kogmaginp03 httpd[2789]: [error] AMEVENTID#725902: Re-negotiation handshake failed: Not accepted by client!?, referer: https://genisys.netiq.com/genisys/A/ChangeQ.aspx?b=035905&c=N&br=2&g=262&n=Shp+64%2c+Mall+Level%2c+WestEnd%2c+Cnr+Henry
Aug 25 16:41:26 kogmaginp03 httpd[2789]: [info] AM#504600404 AMDEVICEID#ag-1CCE13A3CAB7D43E: AMAUTHID#: AMEVENTID#725902: subreq esp.netiq.com:/nesp/app/cookiebroker
Aug 25 16:41:26 kogmaginp03 httpd[2789]: [info] AMEVENTID#725902: Cache miss
Aug 25 16:41:26 kogmaginp03 httpd[2789]: [info] AM#504600000 AMDEVICEID#ag-1CCE13A3CAB7D43E: AMAUTHID#: AMEVENTID#725902: error in sending SBGet
Aug 25 16:41:26 kogmaginp03 httpd[2789]: [warn] AM#304600404 AMDEVICEID#ag-1CCE13A3CAB7D43E: AMAUTHID#: AMEVENTID#725902: error in storing POST data:no content-type

The AG server appears to generate a 409 response, but this is never seen on the Fiddler logs. Looking at the corresponding LAN trace however, we see that the AG was triggering an SSL renegotiate with the browser as soon a POST request was transmitted (even though the connection to the secure web server initially completed the SSL handshake successfully). Because the browser fails to respond to the renegotiation request (because it is disabled), the AG tears down the connection and the user just gets the standard browser network error.

Go to the reverse proxy -> TCP Listen Options and enable Enforce 128-Bit Encryption between Browser and Access Gateway.

Apache triggered the auto-renegotiation due a mismatch between the openssl ciphers negotiated with the initial TCP connection 
on the secure server, and those tied to the Apache services.