Troubleshooting NetIQ Access Manager Formfill problems with NAM 3.2 and 4.0

  • 7015707
  • 29-Sep-2014
  • 29-Sep-2014

Environment

NetIQ Access Manager 3.2
NetIQ Access Manager 4.0

Situation

How to troubleshoot formfill problems with NAM 3.2 or 4.0 - what tools to use, what log settings to enable, what log files to review? All these questions are answered in the following troubleshooting cheat sheet.

Resolution

Functionality: Goal of formfill is simply to fill a login page on Web server with a <form> tag and <input> tags.

Formfill Log settings required to capture all relevant info:

1. IDP - need IDP logging enabled with following parameters. Update both the IDP and AG after this for changes to take effect.

- echo to console enabled
- Application, Liberty, Web Service Consumer and Web Service Provider components set to DEBUG


2. AG - need to add the following AG Advanced Options (AG -> Edit ->Advanced Options) and update the AG servers

LogLevel info
NAGGlobalOptions DebugHeaders=on


Make sure syslog level logging is enabled for Apache at https://support.microfocus.com/kb/doc.php?id=7011611


Log files to send in for formfill problems:

0. Make sure that all the log files referenced below are reset to 0 bytes before duplicating the issue. To do this, simply type echo > $filename e.g echo > /var/log/novell-apache2/error_log

1. Admin Console Server

- output of amdiagcfg.sh script (from /opt/novell/devman/bin directory). This will allow us to view the formfill policy and AG configuration details.

2. Identity (IDP) Server

- /opt/novell/nam/idp/logs/catalina.out. Will allow us view the SOAP requests for formfill attributes if ESP does not have them in cache, as well as retrieval of formfill policies.

3. Access Gateway (AG) Server

- /var/log/novell-ag-logs/maglogs/catalina.out
- /var/log/novell-apache2/error_log
- formfillprob.cap output file from 'tcpdump -i any -s 0 -w formfillprob.cap' command on web server


4. Browser Workstation

- Go to login page of back end application directly and not through the Access Gateway, view it and save the source as a text file.
- Run Fiddler, dup the issue and get the Fiddler output log. Make sure that the Tools -> Fiddler -> Decrypt HTTPS flag is enabled when using SSL between the browser and AG

5. (If secret store enabled) Verify whether the problem is specific to secret store by populating the input fields with LDAP credentials or string attributes instead for testing.


Available Formfill specific Advanced Options:

1. "NAGGlobalOptions debugFormfill=on"- When enabled, all responses from the AG will include an X-MAG HTTP header outlining details on how the form was parsed. An example output is included below, where an administrator can determine whether a matching form was indentified, which policy matched, whether the relevant parameters were uncovered, and if the form was POSTed.

X-Mag:    45B6586EB94FC2A7;ca59cdc4;11969;usrLkup->0;usrBase->0;LocUsr;isomorphic-ff-pr;Contract-valid->0;nam32vm-pxy-srvc;default;SH;FP2->35;WS=a1b14cc2;default;$custom_neil-ff-rewriter;setupFF-interested;mastercdnisamorphic-formfill-Pol3310;FF4GUD->1082;FillSilent;Match FormName;Match;username;Match;password;FF4End->1083;FP4->1083;

2. "NAGGlobalOptions InPlaceSilent" - With this file present, AG Formfill will not generate a new page when autosubmit is enabled, but will fill in the page that has been received from the webserver [similar to the way it does when autosubmit is disabled] and will also make the text/password/unspecified type fields hidden. However, a couple of options found in the formfill policy configuration will not work - (1)Debug Submit (2)Functions to Keep. With advanced login forms containing javascript, this is something we should be trying out regularly.

3. "NAGGlobalOptions InPlaceSilentPolicyDoesSubmit=on" - Very similar to option 2, but may be required for very complex login forms where many javascript references exist. If the data must be submited before an additional javascript operations on the form, this Advanced option may be used. If it is, the administrator must include the 'document.formfs[0].submit();' statement in the 'Statements to Execute' section of the formfill policy.


What to look for in log files:

- Look at Fiddler output and locate the URL of the login page. Note a unique event identifier in the HTTP response headers of the GET request by looking at the X-MAG header and identifying the 3rd field in (11 in case below)

X-Mag    45B6586EB94FC2A7;ca59cdc4;11;usrLkup->0;usrBase->0;LocUsr;isomorphic-ff-pr;Contract-valid->0;setupFF-interested;mastercdnisamorphic-formfill-Pol3310;FF4GUD->1309;FillSilent;Match FormName;Match;username;Match;password;FF4End->1309;FP4->1309;

- open the error_log file and using the event iddentifier from the Fiddler output above, search for EVENTID#<$event_identifier> eg. EVENTID#11
- walk through all events in error_log file for that event identifier and make sure you identify the following:

a) the browser has accessed the right protected resource - owa-ff-pr below - where the formfill policy was enabled

Jan 11 17:14:06 mag32app-vm httpd[16073]: [info] AM#504600000 AMDEVICEID#ag-45B6586EB94FC2A7: AMAUTHID#: AMEVENTID#11: Requ: GET https://nam32app-vm.lab.novell.com/formfill/login.html  service:nam32vm-pxy-srvc (147.2.47.163:2297->147.2.34.116:443)
Jan 11 17:14:06 mag32app-vm httpd[16073]: [info] AM#504600000 AMDEVICEID#ag-45B6586EB94FC2A7: AMAUTHID#B8327542C59F93D7014745607E271521: AMEVENTID#11:validateCookie:local user.
Jan 11 17:14:06 mag32app-vm httpd[16073]: [info] AM#504600100 AMDEVICEID#ag-45B6586EB94FC2A7: AMAUTHID#B8327542C59F93D7014745607E271521: AMEVENTID#11:Restricted URL
Jan 11 17:14:06 mag32app-vm httpd[16073]: [info] AM#504600000 AMDEVICEID#ag-45B6586EB94FC2A7: AMAUTHID#B8327542C59F93D7014745607E271521: AMEVENTID#11:matched PR:owa-ff-pr

b) the user generates a soap request to the ESP for the formfill policy values in the case where the attibutes required are not in cache

Jan 11 17:14:06 mag32app-vm httpd[16073]: [info] AM#504600404 AMDEVICEID#ag-45B6586EB94FC2A7: AMAUTHID#B8327542C59F93D7014745607E271521: AMEVENTID#11:subreq nam32app-vm.lab.novell.com:/nesp/app/soap
Jan 11 17:14:06 mag32app-vm httpd[16073]: [info] AMEVENTID#11: Cache miss

This means that the request was passed to the ESP (nesp/app/soap) where the policy evaluation is actually completed.

c) confirm that the form fields required in the login form are populate correctly with valid data. When we get back attribute values from the ESP, we should have "FF:" string entries in the error_log with the attribute names being filled (username and password in example below)

Jan 11 17:14:07 mag32app-vm httpd[16073]: [warn] AMEVENTID#11: FF:fillSilent: mastercdnisamorphic-formfill-Pol3310
Jan 11 17:14:07 mag32app-vm httpd[16073]: [warn] AMEVENTID#11: FF: <form action="/formfill/phpinfo.php?nov-ss-ff-silent&mastercdnisamorphic-formfill-Pol3310"
Jan 11 17:14:07 mag32app-vm httpd[16073]: [warn] AMEVENTID#11: FF:Filling: username
Jan 11 17:14:07 mag32app-vm httpd[16073]: [warn] AMEVENTID#11: FF:Filling: password

d) Confirm the status response for the HTTP request to the login page, and make sure that there are no errors reported. The X-MAG headers will show that the formfill policy is interested in this response from the web server ("setupFF-interested"), which formfill policy it is mapping to this request ("mastercdnisamorphic-formfill-Pol"), whether it is auto submitting the data ("FillSilent"), whether it matched all the attributes returned in the form ("Match FormName;Match;username;Match;password"), and how long it took to complete the formfill processing (time difference between "FF4GUD" and "FF4End"

Jan 11 17:14:07 mag32app-vm httpd[16073]: [warn] AM#304600001 AMDEVICEID#ag-45B6586EB94FC2A7: AMAUTHID#B8327542C59F93D7014745607E271521: AMEVENTID#11:
status:200 GET https://nam32app-vm.lab.novell.com/formfill/login.html <0100020093022fa3e198545b89510fd3ca59cdc4> X-Mag: <45B6586EB94FC2A7;ca59cdc4;11;u
srLkup->0;usrBase->0;LocUsr;isomorphic-ff-pr;Contract-valid->0;setupFF-interested;mastercdnisamorphic-formfill-Pol3310;FF4GUD->1309;FillSilent;Match FormName;Match;username;Match;password;FF4End->1309;FP4->1309;> [147.2.47.163:2297->147.2.34.116:443]service:nam32vm-pxy-srvc (13:3) -

e) in the case where we match the form but the data is not submitted back to the browser, one needs to look at the catalina output in more details and track the policy evaluation. Using the event identifier from the steps above to search the catalina logs, one will be able to see the policy evaluation request (search for 'CorrelationId="<$event_identifier>"'). In our example, we searched for 'correlationId="11"' and found the request for the formfill attributes we need

<amLogEntry> 2013-01-11T17:14:06Z DEBUG NIDS Application:
Method: BaseHandler.getSOAPDocument
Thread: ajp-bio-/127.0.0.1-9009-exec-4
SOAP EndpointRequest
   <SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/">
      <SOAP-ENV:Body>
         <GetAttrRequest correlationId="11" pId="{:=qS.-b01e8}{=0oW0T}:5:g" sessionId="B8327542C59F93D7014745607E271521" stringify="true">
            <Attribute id="NEPXurn~3Anovell~3Acredentialprofile~3A2005-03~2Fcp~3ASecrets~2Fcp~3ASecret~2Fcp~3AEntry~40~40~40~40WSCQSSToken~40~40~40~40~
2Fcp~3ASecrets~2Fcp~3ASecret~5Bcp~3AName~3D~22urs-secrets~22~5D~2Fcp~3AEntry~5Bcp~3AName~3D~22urs-user-info~22~5D"/>
            <Attribute id="NEPXurn~3Anovell~3Acredentialprofile~3A2005-03~2Fcp~3ASecrets~2Fcp~3ASecret~2Fcp~3AEntry~40~40~40~40WSCQSSToken~40~40~40~40~
2Fcp~3ASecrets~2Fcp~3ASecret~5Bcp~3AName~3D~22urs-secrets~22~5D~2Fcp~3AEntry~5Bcp~3AName~3D~22urs-user-password~22~5D"/>
         </GetAttrRequest>
      </SOAP-ENV:Body>
   </SOAP-ENV:Envelope>
 </amLogEntry>

Continuing the search for the correlationId should show the response, and whether it has the required data or an exception. When an XX is reported, it means that data has been located for that user session and returned to the Proxy formfill code.

<amLogEntry> 2013-01-11T17:14:07Z DEBUG NIDS Application:
Method: BaseHandler.sendSOAPResponse
Thread: ajp-bio-/127.0.0.1-9009-exec-4
SOAP EndpointResponse:
   <SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/">
      <SOAP-ENV:Body>
         <GetAttrResponse correlationId="11">
            <Attribute format="0" id="NEPXurn~3Anovell~3Acredentialprofile~3A2005-03~2Fcp~3ASecrets~2Fcp~3ASecret~2Fcp~3AEntry~40~40~40~40WSCQSSToken~4
0~40~40~40~2Fcp~3ASecrets~2Fcp~3ASecret~5Bcp~3AName~3D~22urs-secrets~22~5D~2Fcp~3AEntry~5Bcp~3AName~3D~22urs-user-info~22~5D" locationCookie="com.novel
l.nidp.liberty.wsc.WSCResourceOffering:hbtl5kppbcmz" maxCardinality="-1" minCardinality="0" status="OK" statusMessage="" syntax="3">
               <StringValue>
                XX
               </StringValue>
            </Attribute>
            <Attribute format="0" id="NEPXurn~3Anovell~3Acredentialprofile~3A2005-03~2Fcp~3ASecrets~2Fcp~3ASecret~2Fcp~3AEntry~40~40~40~40WSCQSSToken~4
0~40~40~40~2Fcp~3ASecrets~2Fcp~3ASecret~5Bcp~3AName~3D~22urs-secrets~22~5D~2Fcp~3AEntry~5Bcp~3AName~3D~22urs-user-password~22~5D" locationCookie="com.n
ovell.nidp.liberty.wsc.WSCResourceOffering:hbtl5kppbcmz" maxCardinality="-1" minCardinality="0" status="OK" statusMessage="" syntax="3">
               <StringValue>
                XX
               </StringValue>
            </Attribute>
         </GetAttrResponse>
      </SOAP-ENV:Body>
   </SOAP-ENV:Envelope>
 </amLogEntry>

f) When the formfill component has all it needs, it fills the form with the corresponding attributes, adds some javascript to auto submit the data and sends the responsse back to the browser. Using the Fiddler logs on the browser, it should be possible to search for the "NAGPostForm" string and find out what the AG has sent back to the browser. Here's an example of what is returned for event identifier 11 in the 200 OK response to the browser:

<html>
<body>
<form name="neil_login_form" action="/formfill/phpinfo.php?nov-ss-ff-silent&mastercdnisamorphic-formfill-Pol3310" method="POST">
<input value="ncashell" name="username" type="hidden"/>
<input value="novell" name="password" type="hidden"/>
<input value="Log In" type="hidden"/>

</form>
<noscript>Please enable scripting on your browser!</noscript>
<script language="JavaScript" type="text/javascript">
function executeJavaScript()
{
}

function NAGPostForm()
{
executeJavaScript();
document.forms[0].submit();
}
NAGPostForm();
</script>
</body>
</html>

g) browser processes this response, executes javascript and POSTs the form to the back end Web server via the AG. Fiddler output on browser will show the POST request to the form action tag above with corresponding parameters (username=ncashell&password=novell)

POST /formfill/phpinfo.php?nov-ss-ff-silent&mastercdnisamorphic-formfill-Pol3310 HTTP/1.1
:
:
username=ncashell&password=novell

There may be complex javascript in the login page, or referenced by the login page which causes the form parameters to fail to get submitted. In this case, it's important that the 'NAGGlobalOptions InPlaceSilent' Advanced Option is tested to see if it works around the issue.