Environment
NetIQ Access Manager 4.0
NetIQ Access Manager 4.1
Initial installation done on NetIQ Access Manager 3.2
SSL enabled on all platforms
NetIQ Access Manager 4.1
Initial installation done on NetIQ Access Manager 3.2
SSL enabled on all platforms
Situation
Access Manager setup upgraded to 4.0.1 from 3.2 platform. Everything appears to be working fine after the upgrade although there are some reports of problems accessing a secure web server applicatio accelerated by the Acecss Gateway. While trying to debug the issue, several SSL related errors were visible in the logs causing concern. These errors are visible in all 3 NAM environments in production and show the following messages indicating that
a) it is trying to do an SSL re-negotiation when re-negotiation is disabled at the server level (openssl test with R command confirms SSL re-negotiation is disabled) and
b) the client is failing to finish the SSL re-negotiation, causing the TCP connection to be reset.
// log file snippet of error condition
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://gensys.trusted.com/gensys/A/ChangeQ.aspx?b=035905&c=N&br=2&g=262&n=Shp+64%2c+Mall+Level%2c+Westfield%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://gensys.trusted.com/gensys/A/ChangeQ.aspx?b=035905&c=N&br=2&g=262&n=Shp+64%2c+Mall+Level%2c+field%2c+Cnr+Henry
Aug 25 16:41:26 kogmaginp03 httpd[2789]: [info] AMEVENTID#725902: Awaiting re-negotiation handshake, referer: https://gensys.trusted.com/genisys/A/ChangeQ.aspx?b=035905&c=N&br=2&g=262&n=Shp+64%2c+Mall+Level%2c+field%2c+Cnr+Henry
Aug 25 16:41:26 kogmaginp03 httpd[2789]: [error] AMEVENTID#725902: Re-negotiation handshake failed: Not accepted by client!?, referer: https://gensys.trusted.com/gensys/A/ChangeQ.aspx?b=035905&c=N&br=2&g=262&n=Shp+64%2c+Mall+Level%2c+field%2c+Cnr+Henry
Aug 25 16:41:26 kogmaginp03 httpd[2789]: [info] AM#504600404 AMDEVICEID#ag-1CCE13A3CAB7D43E: AMAUTHID#: AMEVENTID#725902: subreq intranet.trusted.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 end result is that the TCP connection to the browser is reset, and no HTTP status is returned.
These messages appear numerous times across about 60% of all proxy services - and 0 times across the remaining 40% of proxy services.
The LAN traces also confirmed that the SSL re-negotiation request from AG to browser was transmitted as soon as the GET/POST request came in from the browser.
a) it is trying to do an SSL re-negotiation when re-negotiation is disabled at the server level (openssl test with R command confirms SSL re-negotiation is disabled) and
b) the client is failing to finish the SSL re-negotiation, causing the TCP connection to be reset.
// log file snippet of error condition
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://gensys.trusted.com/gensys/A/ChangeQ.aspx?b=035905&c=N&br=2&g=262&n=Shp+64%2c+Mall+Level%2c+Westfield%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://gensys.trusted.com/gensys/A/ChangeQ.aspx?b=035905&c=N&br=2&g=262&n=Shp+64%2c+Mall+Level%2c+field%2c+Cnr+Henry
Aug 25 16:41:26 kogmaginp03 httpd[2789]: [info] AMEVENTID#725902: Awaiting re-negotiation handshake, referer: https://gensys.trusted.com/genisys/A/ChangeQ.aspx?b=035905&c=N&br=2&g=262&n=Shp+64%2c+Mall+Level%2c+field%2c+Cnr+Henry
Aug 25 16:41:26 kogmaginp03 httpd[2789]: [error] AMEVENTID#725902: Re-negotiation handshake failed: Not accepted by client!?, referer: https://gensys.trusted.com/gensys/A/ChangeQ.aspx?b=035905&c=N&br=2&g=262&n=Shp+64%2c+Mall+Level%2c+field%2c+Cnr+Henry
Aug 25 16:41:26 kogmaginp03 httpd[2789]: [info] AM#504600404 AMDEVICEID#ag-1CCE13A3CAB7D43E: AMAUTHID#: AMEVENTID#725902: subreq intranet.trusted.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 end result is that the TCP connection to the browser is reset, and no HTTP status is returned.
These messages appear numerous times across about 60% of all proxy services - and 0 times across the remaining 40% of proxy services.
The LAN traces also confirmed that the SSL re-negotiation request from AG to browser was transmitted as soon as the GET/POST request came in from the browser.
Resolution
a) Enable RP -> TCP Listen Options -> Enforce
128-Bit Encryption between Browser and Access Gateway flag on all reverse proxies - flag is enabled by default with the new AG releases, but not on older setups that have been upgraded.
b) Add the SSL ciphers from the global advanced options to the Proxy service advanced options via the UI
The SSLCipherSuites never seemed to get set in the individual vhost config files of each proxy service. Setting the ciphersuite as a global advanced option or as a proxy advanced option also doesn’t make it to the actual vhost config file either. Comparing the TCPListenOptions profiles from the working and non working proxies showed that the SSLListenOptions EnableStrongServerSecurity is set to 0 on the proxies that do not get the ciphersuite settings.
b) Add the SSL ciphers from the global advanced options to the Proxy service advanced options via the UI
The SSLCipherSuites never seemed to get set in the individual vhost config files of each proxy service. Setting the ciphersuite as a global advanced option or as a proxy advanced option also doesn’t make it to the actual vhost config file either. Comparing the TCPListenOptions profiles from the working and non working proxies showed that the SSLListenOptions EnableStrongServerSecurity is set to 0 on the proxies that do not get the ciphersuite settings.
Cause
This is an Apache issue with Ciphers. Despite the openssl having re-negotiation disabled, Apache seems to triggers re-negotiations under the following conditions:
1) Client established tcp connection, starts SSL negotiation and sends the list of cipher suites
2) server(open ssl) chooses one of the cipher suite then they will finish ssl handshake
3) apache ssl hook handler then checks whether the configured vhost ssl cipher suite matches with the negotiated one.
4) if not then renegotiate using the vhost cipher suite to underlying ssl connection
In our case, every vhost proxy configuration file was missing the SSLCipher directive, causing us to try and re-negotiate with different cipher suites. In the case where 40% of the proxy services failed to log the issue, it turns out that these proxy services all had SSLCIpher directives in these. This is because they were created with the Reverse Proxy -> TCP Listen Options -> Enforce 128-Bit Encryption between Browser and Access Gateway setting enable.
1) Client established tcp connection, starts SSL negotiation and sends the list of cipher suites
2) server(open ssl) chooses one of the cipher suite then they will finish ssl handshake
3) apache ssl hook handler then checks whether the configured vhost ssl cipher suite matches with the negotiated one.
4) if not then renegotiate using the vhost cipher suite to underlying ssl connection
In our case, every vhost proxy configuration file was missing the SSLCipher directive, causing us to try and re-negotiate with different cipher suites. In the case where 40% of the proxy services failed to log the issue, it turns out that these proxy services all had SSLCIpher directives in these. This is because they were created with the Reverse Proxy -> TCP Listen Options -> Enforce 128-Bit Encryption between Browser and Access Gateway setting enable.