Environment
Novell Access Manager 3.1 Linux based Access Gateway Service
Access Gateway Service Proxy running on SLES11 SP1 server
Auditing enabled for all Proxy events
Access Gateway Service Proxy running on SLES11 SP1 server
Auditing enabled for all Proxy events
Situation
Access Manager setup and working fine - all users can access protected resources on Access Gateway Service (AGS) after authenticating to the Identity Server. One one of the protected resources, a formfill policy was created to single sign on to a Web based application using HTML forms.
When users hit the formfill enabled protected resource, it takes 3 minutes before the HTML page is rendered from the back end Web server. The single sign on works fine but the delay is unacceptable.
From the catalina.out logs on the AGS server, we can see that the proxy generates a GetAttributeRequest to the ESP to obtain the info needed for formfill (two attributes, one LDAP and one credential profile). We get what we need within 3 seconds and the ESP sends the response back to the Apache proxy. The problem is that the AGS delays for another 190 seconds before sending the request to the back end web server.
By enabling the debug options on the AGS, the X-MAG header dumps very useful troubleshooting info. Looking at the HTTP headers file on the client, or the AGS debug logs, we can see this header as shown below:
When users hit the formfill enabled protected resource, it takes 3 minutes before the HTML page is rendered from the back end Web server. The single sign on works fine but the delay is unacceptable.
From the catalina.out logs on the AGS server, we can see that the proxy generates a GetAttributeRequest to the ESP to obtain the info needed for formfill (two attributes, one LDAP and one credential profile). We get what we need within 3 seconds and the ESP sends the response back to the Apache proxy. The problem is that the AGS delays for another 190 seconds before sending the request to the back end web server.
By enabling the debug options on the AGS, the X-MAG header dumps very useful troubleshooting info. Looking at the HTTP headers file on the client, or the AGS debug logs, we can see this header as shown below:
> // Login request where we hit protected resource
> 2011-05-10T10:30:45Z INFO AGSP: AM#504600000:
> AMDEVICEID#ag-8741547958712875: AMEVENTID#172: URL Request Processing: URL
> Accessed,
>
> %ttps://sasdemo.nam.com/ sourceIP=172.17.2.1,
> localIP=172.17.2.158
> :
> :
> :// Sending of request to Web server
> 2011-05-10T10:33:54Z DEBUG AGSP: AM#604600001:
> AMDEVICEID#ag-8741547958712875: AMAUTHID#13D6126500F73C9BB22911F99AF12693:
> AMEVENTID#169: URL Request Processing: Trace Summary, GET
> https://sasdemo.nam.com/<01001300ac110201a5a15cd55343d43f0c7bdeeb> X-Mag:
> 8741547958712875;0c7bdeeb;169;usrLkup->1;usrBase->1;LocUsr;base;sasdemo.nam.
> com/*;bypass;sasdemo;FP2->3;WS=1;default;6aygmikyysn7g5demoff-33310;FF4GUD->345
> 0;FF4End->192448;FP4->192448;C002; user=cn=bbat,ou=users,o=data,
> protectedResource=base, sourceIP=172.17.2.1, localIP=172.17.2.158
FF4GUD indicates the time needed to retrieve the attributes. This is defined in ms. The
FF4END header then includes the time taken to send the form info to the back end Web server.
In our case below is this is after 192 seconds.
Resolution
Make sure that the AGS can communicate with the Audit server if auditing is enabled for AGS events.
In the case above, auditing was enabled for formfill events, but the Audit server was down. The AGS would delay the request by 190+ seconds before sending it out, as it awaited feedback from the local audit platform agent. A defect has been opened on this to prevent this delay should auditing communications fail.
In the case above, auditing was enabled for formfill events, but the Audit server was down. The AGS would delay the request by 190+ seconds before sending it out, as it awaited feedback from the local audit platform agent. A defect has been opened on this to prevent this delay should auditing communications fail.