Environment
NetIQ Access Manager 3.1
NetIQ Access Manager 3.1 Support Pack 4 IR1 applied
Linux Access Gateway Appliance
Websphere back end Server
NetIQ Access Manager 3.1 Support Pack 4 IR1 applied
Linux Access Gateway Appliance
Websphere back end Server
Situation
Linux Access Gateway (LAG) setup and accelerating a Websphere back end server. Single sign on to Websphere established using formfill. The formfill policy masks the users credentials for security reasons. Very randomly (~0.01% of the time), the logged in users username that is sent to the back
end WS server via the formfill is not the actual username, but the nov-ss-ff-masked string. This is the string that should have been stripped out by the LAG formfill module after it is sent by the browser.
The WebSphere logs show the following output
[10/13/12 7:23:26:131 EST] 000000d8 LdapRegistryI E SECJ0361E: Authentication failed for nov-ss-ff-masked because user is not found in the registry.
[10/13/12 7:23:26:136 EST] 000000d8 LdapRegistryI E SECJ0336E: Authentication failed for user nov-ss-ff-masked because of the following exception {1}
[10/13/12 7:23:26:138 EST] 000000d8 LTPAServerObj E SECJ0369E: Authentication failed when using LTPA. The exception is No user nov-ss-ff-masked found.
[10/13/12 7:23:26:140 EST] 000000d8 Authenticatio E com.ibm.wps.auth.AuthenticationServlet doLoginWithExceptions WASAuthenticationFailedException occured: com.ibm.wps.services.authentication.exceptions.WASAuthenticationFailedException: EJPSD0001E: Authentication against WebSphere Application Server failed for user nov-ss-ff-masked.
One can track the user request down to the ics_dyn log file but there is nothing in the log file that indicates any error. Even with the laghtpheaders, you cannot see what data is being POSTed by the proxy, but just the POST URL and HTTP headers. For example, the user experiencing the issue is 'cn=avia207,ou=users,ou=eg'.
// User hits the protected resource for the first time
Oct 13 07:22:52 dmznamag1 : AM#504520000: AMDEVICEID#ag-0163A473C70A27EA-0: AMAUTHID#I: AMEVENTID#40939: status:302 /0 clen:0/0 cache GET www.mystream.com/ pr:- [188.115.8.223:44917->134.216.27.212:80 - -] [-] srv:0x9256a7d4->0x9256a7d4/0 type:0 pr:(nil) co:(nil) og:(nil) 0 (redir:0) (0x98e85020.0x9c2f7370) (con:770/r:1 @:0)
// After the user authenticates and hits wps, we see the following POST that is triggered by the FF policy
// Note that we only add nov-ss-ff-post to URL and no mask!
Oct 13 07:23:23 dmznamag1 : AM#504507000: AMDEVICEID#ag-0163A473C70A27EA-0: AMAUTHID#0: AMEVENTID#0: HtmlForm:0xa1ebbac4:getFormTag(): policy:0x923 7e890 data:<form method="POST" action="/wps/portal/!ut/p/c1/04_SB8K8xLLM9MSSzPy8xBz9CP0os3g_f6NQNxNPQ0MLM1dDAyMzDxMnnzBPA39_U30_j_zcVP2CbEdFAD4vw4A !/dl2/d1/L0lDUWtpQ1NTUW9LVVFBISEvb0lvZ0FFQ1FRREdJUXBURE9DNEpuQSEhL1lBeEpKNDUwLTRrc3V5bHcvN19OTzJVRjRJMTE4NkUxMDI2SDRCTFZJME80Mi93cHMucG9ydGxldHMubG 9naW4!/?nov-ss-ff-post=0" name="LoginForm"> : :
Feb 13 07:23:23 dmznamag1 : AM#504520000: AMDEVICEID#ag-0163A473C70A27EA-0: AMAUTHID#F595DE43355EEDDD0307ED4758B377F5: AMEVENTID#41023: status:200 /200 clen:11876/0 rw GET www.mystream.com/wps/portal/!ut/p/c0/04_SB8K8xLLM9MSSzPy8xBz9CP0os3g_f6NQNxNPQ0MLM1dDAyMzDxMnnzBPA39_U_2CbEdFAMNst 2E!/ pr:pr_login_wps [188.115.8.223:44724->134.216.27.212:443 reuse 134.216.27.200:43146->134.216.176.204:88] [usr2:0x9d853790.1(cn=avia207,ou=use rs,ou=eg,)(now:35802) 2: '2-x -l:0/0 u:0 +e:0 (0/0)', 'C17 -l:0/0 u:0 +e:3480 (0/1)',] srv:0x925c4020->0x925a67d4/2 type:401000 pr:0x91ae4ca0 co :0xa5a82020 og:0x90ffd820 newAnon 0 (FinishTransmit:0) (0x9f81e020.0x9c2f76c0) (con:772/r:6 @:1d)
// After the formfill credentials are populated and sent back to browser, browser sends subsequent POST with user info
Oct 13 07:23:25 dmznamag1 : AM#504503000: AMDEVICEID#ag-0163A473C70A27EA-0: AMAUTHID#0: AMEVENTID#41057: Requ:3:0x9f81e020:0xa2408d60:0x925a67d4: ' www.mystream.com:/wps/portal/!ut/p/c1/04_SB8K8xLLM9MSSzPy8xBz9CP0os3g_f6NQNxNPQ0MLM1dDAyMzDxMnnzBPA39_U30_j_zcVP2CbEdFAD4vw4A!/dl2/d1/L0lDUWtpQ 1NTUW9LVVFBISEvb0lvZ0FFQ1FRREdJUXBURE9DNEpuQSEhL1lBeEpKNDUwLTRrc3V5bHcvN19OTzJVRjRJMTE4NkUxMDI2SDRCTFZJME80Mi93cHMucG9ydGxldHMubG9naW4!/?nov-ss-ff- post=0'279 [188.115.8.223:44729 -> 134.216.27.212:443]
// After the app gets the login credetials, the subsequent POST requests is made to the App
Oct 13 07:23:25 dmznamag1 : AM#504520000: AMDEVICEID#ag-0163A473C70A27EA-0: AMAUTHID#F595DE43355EEDDD0307ED4758B377F5: AMEVENTID#41057: status:200 /200 upload:155 clen:14257/0 rw POST www.mystream/wps/portal/!ut/p/c1/04_SB8K8xLLM9MSSzPy8xBz9CP0os3g_f6NQNxNPQ0MLM1dDAyMzDxMnnzBPA39_U30_j _zcVP2CbEdFAD4vw4A!/dl2/d1/L0lDUWtpQ1NTUW9LVVFBISEvb0lvZ0FFQ1FRREdJUXBURE9DNEpuQSEhL1lBeEpKNDUwLTRr pr:pr_login_wps [188.115.8.223:44729->134.216.2 7.212:443 reuse 134.216.27.200:43159->134.216.176.204:88] [usr2:0x9f8de5b4.1(cn=avia207,ou=users,ou=eg,)(now:35804) 2: '2-x -l:0/0 u:0 +e:0 (0/0) ', 'C17 -l:2/0 u:2 +e:3478 (0/1)',] srv:0x925c4020->0x925a67d4/2 type:401000 pr:0x91ae4ca0 co:0xa440b020 og:0x90ffdda0 newAnon 0 (FinishTransmit: 0) (0x9f81e020.0xa2408d60) (con:808/r:2 @:1)
// App returns login failure
Oct 13 07:23:25 dmznamag1 : AM#504503000: AMDEVICEID#ag-0163A473C70A27EA-0: AMAUTHID#0: AMEVENTID#41065: Requ:1:0xab887020:0xa2408d60:0x925a67d4: ' www.mystream.com:/login_failure.html'19 [188.115.8.223:44729 -> 134.216.27.212:443]
The WebSphere logs show the following output
[10/13/12 7:23:26:131 EST] 000000d8 LdapRegistryI E SECJ0361E: Authentication failed for nov-ss-ff-masked because user is not found in the registry.
[10/13/12 7:23:26:136 EST] 000000d8 LdapRegistryI E SECJ0336E: Authentication failed for user nov-ss-ff-masked because of the following exception {1}
[10/13/12 7:23:26:138 EST] 000000d8 LTPAServerObj E SECJ0369E: Authentication failed when using LTPA. The exception is No user nov-ss-ff-masked found.
[10/13/12 7:23:26:140 EST] 000000d8 Authenticatio E com.ibm.wps.auth.AuthenticationServlet doLoginWithExceptions WASAuthenticationFailedException occured: com.ibm.wps.services.authentication.exceptions.WASAuthenticationFailedException: EJPSD0001E: Authentication against WebSphere Application Server failed for user nov-ss-ff-masked.
One can track the user request down to the ics_dyn log file but there is nothing in the log file that indicates any error. Even with the laghtpheaders, you cannot see what data is being POSTed by the proxy, but just the POST URL and HTTP headers. For example, the user experiencing the issue is 'cn=avia207,ou=users,ou=eg'.
// User hits the protected resource for the first time
Oct 13 07:22:52 dmznamag1 : AM#504520000: AMDEVICEID#ag-0163A473C70A27EA-0: AMAUTHID#I: AMEVENTID#40939: status:302 /0 clen:0/0 cache GET www.mystream.com/ pr:- [188.115.8.223:44917->134.216.27.212:80 - -] [-] srv:0x9256a7d4->0x9256a7d4/0 type:0 pr:(nil) co:(nil) og:(nil) 0 (redir:0) (0x98e85020.0x9c2f7370) (con:770/r:1 @:0)
// After the user authenticates and hits wps, we see the following POST that is triggered by the FF policy
// Note that we only add nov-ss-ff-post to URL and no mask!
Oct 13 07:23:23 dmznamag1 : AM#504507000: AMDEVICEID#ag-0163A473C70A27EA-0: AMAUTHID#0: AMEVENTID#0: HtmlForm:0xa1ebbac4:getFormTag(): policy:0x923 7e890 data:<form method="POST" action="/wps/portal/!ut/p/c1/04_SB8K8xLLM9MSSzPy8xBz9CP0os3g_f6NQNxNPQ0MLM1dDAyMzDxMnnzBPA39_U30_j_zcVP2CbEdFAD4vw4A !/dl2/d1/L0lDUWtpQ1NTUW9LVVFBISEvb0lvZ0FFQ1FRREdJUXBURE9DNEpuQSEhL1lBeEpKNDUwLTRrc3V5bHcvN19OTzJVRjRJMTE4NkUxMDI2SDRCTFZJME80Mi93cHMucG9ydGxldHMubG 9naW4!/?nov-ss-ff-post=0" name="LoginForm"> : :
Feb 13 07:23:23 dmznamag1 : AM#504520000: AMDEVICEID#ag-0163A473C70A27EA-0: AMAUTHID#F595DE43355EEDDD0307ED4758B377F5: AMEVENTID#41023: status:200 /200 clen:11876/0 rw GET www.mystream.com/wps/portal/!ut/p/c0/04_SB8K8xLLM9MSSzPy8xBz9CP0os3g_f6NQNxNPQ0MLM1dDAyMzDxMnnzBPA39_U_2CbEdFAMNst 2E!/ pr:pr_login_wps [188.115.8.223:44724->134.216.27.212:443 reuse 134.216.27.200:43146->134.216.176.204:88] [usr2:0x9d853790.1(cn=avia207,ou=use rs,ou=eg,)(now:35802) 2: '2-x -l:0/0 u:0 +e:0 (0/0)', 'C17 -l:0/0 u:0 +e:3480 (0/1)',] srv:0x925c4020->0x925a67d4/2 type:401000 pr:0x91ae4ca0 co :0xa5a82020 og:0x90ffd820 newAnon 0 (FinishTransmit:0) (0x9f81e020.0x9c2f76c0) (con:772/r:6 @:1d)
// After the formfill credentials are populated and sent back to browser, browser sends subsequent POST with user info
Oct 13 07:23:25 dmznamag1 : AM#504503000: AMDEVICEID#ag-0163A473C70A27EA-0: AMAUTHID#0: AMEVENTID#41057: Requ:3:0x9f81e020:0xa2408d60:0x925a67d4: ' www.mystream.com:/wps/portal/!ut/p/c1/04_SB8K8xLLM9MSSzPy8xBz9CP0os3g_f6NQNxNPQ0MLM1dDAyMzDxMnnzBPA39_U30_j_zcVP2CbEdFAD4vw4A!/dl2/d1/L0lDUWtpQ 1NTUW9LVVFBISEvb0lvZ0FFQ1FRREdJUXBURE9DNEpuQSEhL1lBeEpKNDUwLTRrc3V5bHcvN19OTzJVRjRJMTE4NkUxMDI2SDRCTFZJME80Mi93cHMucG9ydGxldHMubG9naW4!/?nov-ss-ff- post=0'279 [188.115.8.223:44729 -> 134.216.27.212:443]
// After the app gets the login credetials, the subsequent POST requests is made to the App
Oct 13 07:23:25 dmznamag1 : AM#504520000: AMDEVICEID#ag-0163A473C70A27EA-0: AMAUTHID#F595DE43355EEDDD0307ED4758B377F5: AMEVENTID#41057: status:200 /200 upload:155 clen:14257/0 rw POST www.mystream/wps/portal/!ut/p/c1/04_SB8K8xLLM9MSSzPy8xBz9CP0os3g_f6NQNxNPQ0MLM1dDAyMzDxMnnzBPA39_U30_j _zcVP2CbEdFAD4vw4A!/dl2/d1/L0lDUWtpQ1NTUW9LVVFBISEvb0lvZ0FFQ1FRREdJUXBURE9DNEpuQSEhL1lBeEpKNDUwLTRr pr:pr_login_wps [188.115.8.223:44729->134.216.2 7.212:443 reuse 134.216.27.200:43159->134.216.176.204:88] [usr2:0x9f8de5b4.1(cn=avia207,ou=users,ou=eg,)(now:35804) 2: '2-x -l:0/0 u:0 +e:0 (0/0) ', 'C17 -l:2/0 u:2 +e:3478 (0/1)',] srv:0x925c4020->0x925a67d4/2 type:401000 pr:0x91ae4ca0 co:0xa440b020 og:0x90ffdda0 newAnon 0 (FinishTransmit: 0) (0x9f81e020.0xa2408d60) (con:808/r:2 @:1)
// App returns login failure
Oct 13 07:23:25 dmznamag1 : AM#504503000: AMDEVICEID#ag-0163A473C70A27EA-0: AMAUTHID#0: AMEVENTID#41065: Requ:1:0xab887020:0xa2408d60:0x925a67d4: ' www.mystream.com:/login_failure.html'19 [188.115.8.223:44729 -> 134.216.27.212:443]
Resolution
Fixed with LAG update in Access Manager 3.1 Support Pack 5.