Environment
- Access Manager 4.4.4
- Access Manager 4.5
- Advanced Authentication 6.2
Situation
- NAM 4.4.4 has been integrated with AAF 6.2 using OAuth
- AAF Generic Class, AAF Generic Method, AAF-Generic Contract has been configured
- Flow
- User logs in to IDP server using "Secure Name/Password - Form" contract
- User runs "AAF-Generic Contract" after successful login
- User gets redirected to AAF Authentication page and will be prompted for the "Username"
Note: due to the fact that the user has been already logged in the expectation is not getting prompted to provide the Username during the AAF authentication process
Resolution
make sure the "Sign Data URL" is "/osp/a/TOP/auth/oauth2/sign"
Cause
The "Sign Data URL" was set to the wrong endpoint.
It was set to "/osp/a/TOP/auth/oauth2/signs" instead to "/osp/a/TOP/auth/oauth2/sign"
Additional Information
NAM is
passing the user details over in a request which is out of the normal
OAuth Authorization Flow and done before sending the OAuth Authorization
code which gets visible in fiddler and in the debug AAF Web Auth logs
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
https://webauth.naaf.kgast.nam.com/osp/a/TOP/auth/oauth2/grant?
access_type=online&
approval_prompt=auto&
client_id=id-j9SQkHA2kLMxoJ4fy6hpQQptzhzYVx46&
redirect_uri=https://idpa.kgast.nam.com:8443/nidp/oauth/nam/callback&response_type=code&scope&
parameters=xst3_7hUfzFfgAsPavVnpQS-GGCV7-6sMYgzV05i9VnUVlD9YbUU9FpSQ8XV_naJvYxnLf-jd0ny0F3aoi5RwcThMjm1CdCFw_A5wlOnA0nfp0WcxB1pLj2A-8DW9-hkHAJ5_8KZJSBU_APm_b1VCA~~.bTQtqdTVHi0Otj5eyw_RUqrQde2zdMk5ttM6_24-oX4~
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
Log Data: IDP oauth2 handler to process request received for grant
Time: 2019-04-16T07:48:00.748+0000
Java: internal.osp.oidp.service.servlets.handler.AuthenticationServiceRequestHandler.resolveHandler() [192] thread=http-nio-0.0.0.0-10088-exec-22
Priority Level: FINEST
Preamble: [OIDP]
Override locale: de_DE
Element: grant
Element: oauth2
Path element count: 2
Service: For Advanced Authentication(id=auth)
Tenant: For Advanced Authentication
Request number: 2
Http request type: GET
HttpServletResponse exists.
Class: OSPRequestContext
Log Data:
Time: 2019-04-16T07:48:00.748+0000
Java: internal.osp.framework.servlet.OSPServlet.process() [198] thread=http-nio-0.0.0.0-10088-exec-22
Priority Level: FINEST
Preamble: [OSP]
OSPRequestContext
Attributes
parameters
scope
response_type
redirect_uri
client_id
approval_prompt
access_type
Parameters
Last Accessed Time: 2019-04-16T07:48:00.747Z (1555400880747)
Id: 5E185FD2B04CC4828EE8B768D254FED4
Session
dnt=1
accept-encoding=gzip, deflate
user-agent=Mozilla/5.0 (Windows NT 10.0; WOW64; Trident/7.0; rv:11.0) like Gecko
accept-language=de-DE
referer=https://idpa.kgast.nam.com:8443/nidp/jsp/main.jsp?id=AAF-Generic&sid=0
accept=text/html, application/xhtml+xml, image/jxr, */*
connection=close
x-forwarded-for=149.44.167.99
x-real-ip=149.44.167.99
host=127.0.0.1:10088
Headers
Remote Client IP Address: 127.0.0.1
Host IP Address: 127.0.0.1
Locale: de_DE
Server Port: 10088
Server Name: 127.0.0.1
Path Info: /TOP/auth/oauth2/grant
Servlet Path: /a
Context Path: /osp
Scheme: http
Query String: ?access_type=online&approval_prompt=auto&client_id=id-j9SQkHA2kLMxoJ4fy6hpQQptzhzYVx46&redirect_uri=https%3A//idpa.kgast.nam.com%3A8443/nidp/oauth/nam/callback&response_type=code&scope¶meters=xst3_7hUfzFfgAsPavVnpQS-GGCV7-6sMYgzV05i9VnUVlD9YbUU9FpSQ8XV_naJvYxnLf-jd0ny0F3aoi5RwcThMjm1CdCFw_A5wlOnA0nfp0WcxB1pLj2A-8DW9-hkHAJ5_8KZJSBU_APm_b1VCA~~.bTQtqdTVHi0Otj5eyw_RUqrQde2zdMk5ttM6_24-oX4~
Request URL: /osp/a/TOP/auth/oauth2/grant
Method: GET
Log Data: HttpServletRequest (Number 2)
Time: 2019-04-16T07:48:00.748+0000
Java: internal.osp.common.logging.HttpRequestLogger.log() [340] thread=http-nio-0.0.0.0-10088-exec-22
Priority Level: FINER
Preamble: [OSP]
Buffer size: 8192
Locale: en_US
Character encoding: UTF-8
Content type: application/json;charset=UTF-8
Duration (seconds): 0.66
Log Data: HttpServletResponse (Number 1)
Time: 2019-04-16T07:47:59.806+0000
Java: internal.osp.common.logging.HttpResponseLogger.log() [138] thread=http-nio-0.0.0.0-10088-exec-21
Priority Level: FINER
Preamble: [OSP]
Data size (characters): 208
Status: 200
Log Data: Response: JSON
Time: 2019-04-16T07:47:59.803+0000
Java: internal.osp.framework.UIResponder$Response.setResponse() [1418] thread=http-nio-0.0.0.0-10088-exec-21
Priority Level: FINEST
Preamble: [OSP]
Log Data: OAuthSignClientData
Time: 2019-04-16T07:47:59.798+0000
Java: internal.osp.framework.logging.OSPLoggingBase.buildAuditEvent() [130] thread=http-nio-0.0.0.0-10088-exec-21
Priority Level: FINEST
Preamble: [OIDP]
Creating new session data; id: 0
Log Data: Get session data based on request:
Elapsed time: 2.625 milliseconds
Time: 2019-04-16T07:47:59.779+0000
Java: internal.osp.oidp.service.session.NIDPSession.getSessionData() [776] thread=http-nio-0.0.0.0-10088-exec-21
Priority Level: FINER
Preamble: [OIDP]
Authenticated: false
Zero consumed authentications.
Identifier: fc92e1c7e3e14917be55b31a2301defd-cc98839ce1adb9b8a4
Log Data: Session authenticated?
Elapsed time: 781.179 microseconds
Time: 2019-04-16T07:47:59.776+0000
Java: internal.osp.oidp.service.session.NIDPSession.checkAuthenticated() [2576] thread=http-nio-0.0.0.0-10088-exec-21
Priority Level: FINEST
Preamble: [OIDP]
Log Data: Session will be created because the request is not a user request and no cookie accompanied the request.
Elapsed time: 11.47 milliseconds
Time: 2019-04-16T07:47:59.764+0000
Java: internal.osp.oidp.service.cluster.ClusterCookieContext.resolveSession() [147] thread=http-nio-0.0.0.0-10088-exec-21
Priority Level: FINER
Preamble: [OIDP]
Log Data: Created new Session: id: fc92e1c7e3e14917be55b31a2301defd-cc98839ce1adb9b8a4-CX, Type: TEMPORARY
Time: 2019-04-16T07:47:59.775+0000
Java: internal.osp.oidp.service.session.NIDPSession.<init>() [308] thread=http-nio-0.0.0.0-10088-exec-21
Priority Level: FINEST
Preamble: [OIDP]
Log Data: IDP oauth2 handler to process request received for sign
Time: 2019-04-16T07:47:59.757+0000
Java: internal.osp.oidp.service.servlets.handler.AuthenticationServiceRequestHandler.resolveHandler() [192] thread=http-nio-0.0.0.0-10088-exec-21
Priority Level: FINEST
Preamble: [OIDP]
Override locale: en_US
Element: sign
Element: oauth2
Path element count: 2
Service: For Advanced Authentication(id=auth)
Tenant: For Advanced Authentication
Request number: 1
Http request type: POST
HttpServletResponse exists.
Class: OSPRequestContext
Log Data:
Time: 2019-04-16T07:47:59.750+0000
Java: internal.osp.framework.servlet.OSPServlet.process() [198] thread=http-nio-0.0.0.0-10088-exec-21
Priority Level: FINEST
Preamble: [OSP]
OSPRequestContext
Attributes
data
Parameters
Last Accessed Time: 2019-04-16T07:47:59.746Z (1555400879746)
Id: 508911EFF63B755087357D7DAA2C15B7
Session
accept=text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2
user-agent=Java/1.8.0_192
pragma=no-cache
cache-control=no-cache
authorization=Basic ********
content-type=application/x-www-form-urlencoded
content-length=99
connection=close
x-forwarded-for=147.2.92.100
x-real-ip=147.2.92.100
host=127.0.0.1:10088
Headers
Remote Client IP Address: 127.0.0.1
Host IP Address: 127.0.0.1
Locale: en_US
Content Type: application/x-www-form-urlencoded
Content Length: 99
Server Port: 10088
Server Name: 127.0.0.1
Path Info: /TOP/auth/oauth2/sign
Servlet Path: /a
Context Path: /osp
Scheme: http
Request URL: /osp/a/TOP/auth/oauth2/sign
Method: POST
Log Data: HttpServletRequest (Number 1)
Time: 2019-04-16T07:47:59.747+0000
Java: internal.osp.common.logging.HttpRequestLogger.log() [340] thread=http-nio-0.0.0.0-10088-exec-21
Priority Level: FINER
Preamble: [OSP]
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
The parameters value includes the username but key is the request to the "/osp/a/TOP/auth/oauth2/sign" endpoint at the AAF server. This request will as well pass the user information over to the AAF server. There was a problem with an older version of NAM. I did not cjeck which version you are running but my setup is 4.4.4 and 4.5
2) Add the property "debug true" on the AAF method
3) On the AAF Server turn on debug logging
4) clear all log files
5) start fiddler and run a test
6) If you see something like "Got exception while getting the signed data:" in the NAM logs you are fighting the problem with the bug in the older NAM version.
Note: The AAF logs are revers order. You read them from the bottom to the top
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
https://webauth.naaf.kgast.nam.com/osp/a/TOP/auth/oauth2/grant?
access_type=online&
approval_prompt=auto&
client_id=id-j9SQkHA2kLMxoJ4fy6hpQQptzhzYVx46&
redirect_uri=https://idpa.kgast.nam.com:8443/nidp/oauth/nam/callback&response_type=code&scope&
parameters=xst3_7hUfzFfgAsPavVnpQS-GGCV7-6sMYgzV05i9VnUVlD9YbUU9FpSQ8XV_naJvYxnLf-jd0ny0F3aoi5RwcThMjm1CdCFw_A5wlOnA0nfp0WcxB1pLj2A-8DW9-hkHAJ5_8KZJSBU_APm_b1VCA~~.bTQtqdTVHi0Otj5eyw_RUqrQde2zdMk5ttM6_24-oX4~
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
Log Data: IDP oauth2 handler to process request received for grant
Time: 2019-04-16T07:48:00.748+0000
Java: internal.osp.oidp.service.servlets.handler.AuthenticationServiceRequestHandler.resolveHandler() [192] thread=http-nio-0.0.0.0-10088-exec-22
Priority Level: FINEST
Preamble: [OIDP]
Override locale: de_DE
Element: grant
Element: oauth2
Path element count: 2
Service: For Advanced Authentication(id=auth)
Tenant: For Advanced Authentication
Request number: 2
Http request type: GET
HttpServletResponse exists.
Class: OSPRequestContext
Log Data:
Time: 2019-04-16T07:48:00.748+0000
Java: internal.osp.framework.servlet.OSPServlet.process() [198] thread=http-nio-0.0.0.0-10088-exec-22
Priority Level: FINEST
Preamble: [OSP]
OSPRequestContext
Attributes
parameters
scope
response_type
redirect_uri
client_id
approval_prompt
access_type
Parameters
Last Accessed Time: 2019-04-16T07:48:00.747Z (1555400880747)
Id: 5E185FD2B04CC4828EE8B768D254FED4
Session
dnt=1
accept-encoding=gzip, deflate
user-agent=Mozilla/5.0 (Windows NT 10.0; WOW64; Trident/7.0; rv:11.0) like Gecko
accept-language=de-DE
referer=https://idpa.kgast.nam.com:8443/nidp/jsp/main.jsp?id=AAF-Generic&sid=0
accept=text/html, application/xhtml+xml, image/jxr, */*
connection=close
x-forwarded-for=149.44.167.99
x-real-ip=149.44.167.99
host=127.0.0.1:10088
Headers
Remote Client IP Address: 127.0.0.1
Host IP Address: 127.0.0.1
Locale: de_DE
Server Port: 10088
Server Name: 127.0.0.1
Path Info: /TOP/auth/oauth2/grant
Servlet Path: /a
Context Path: /osp
Scheme: http
Query String: ?access_type=online&approval_prompt=auto&client_id=id-j9SQkHA2kLMxoJ4fy6hpQQptzhzYVx46&redirect_uri=https%3A//idpa.kgast.nam.com%3A8443/nidp/oauth/nam/callback&response_type=code&scope¶meters=xst3_7hUfzFfgAsPavVnpQS-GGCV7-6sMYgzV05i9VnUVlD9YbUU9FpSQ8XV_naJvYxnLf-jd0ny0F3aoi5RwcThMjm1CdCFw_A5wlOnA0nfp0WcxB1pLj2A-8DW9-hkHAJ5_8KZJSBU_APm_b1VCA~~.bTQtqdTVHi0Otj5eyw_RUqrQde2zdMk5ttM6_24-oX4~
Request URL: /osp/a/TOP/auth/oauth2/grant
Method: GET
Log Data: HttpServletRequest (Number 2)
Time: 2019-04-16T07:48:00.748+0000
Java: internal.osp.common.logging.HttpRequestLogger.log() [340] thread=http-nio-0.0.0.0-10088-exec-22
Priority Level: FINER
Preamble: [OSP]
Buffer size: 8192
Locale: en_US
Character encoding: UTF-8
Content type: application/json;charset=UTF-8
Duration (seconds): 0.66
Log Data: HttpServletResponse (Number 1)
Time: 2019-04-16T07:47:59.806+0000
Java: internal.osp.common.logging.HttpResponseLogger.log() [138] thread=http-nio-0.0.0.0-10088-exec-21
Priority Level: FINER
Preamble: [OSP]
Data size (characters): 208
Status: 200
Log Data: Response: JSON
Time: 2019-04-16T07:47:59.803+0000
Java: internal.osp.framework.UIResponder$Response.setResponse() [1418] thread=http-nio-0.0.0.0-10088-exec-21
Priority Level: FINEST
Preamble: [OSP]
Log Data: OAuthSignClientData
Time: 2019-04-16T07:47:59.798+0000
Java: internal.osp.framework.logging.OSPLoggingBase.buildAuditEvent() [130] thread=http-nio-0.0.0.0-10088-exec-21
Priority Level: FINEST
Preamble: [OIDP]
Creating new session data; id: 0
Log Data: Get session data based on request:
Elapsed time: 2.625 milliseconds
Time: 2019-04-16T07:47:59.779+0000
Java: internal.osp.oidp.service.session.NIDPSession.getSessionData() [776] thread=http-nio-0.0.0.0-10088-exec-21
Priority Level: FINER
Preamble: [OIDP]
Authenticated: false
Zero consumed authentications.
Identifier: fc92e1c7e3e14917be55b31a2301defd-cc98839ce1adb9b8a4
Log Data: Session authenticated?
Elapsed time: 781.179 microseconds
Time: 2019-04-16T07:47:59.776+0000
Java: internal.osp.oidp.service.session.NIDPSession.checkAuthenticated() [2576] thread=http-nio-0.0.0.0-10088-exec-21
Priority Level: FINEST
Preamble: [OIDP]
Log Data: Session will be created because the request is not a user request and no cookie accompanied the request.
Elapsed time: 11.47 milliseconds
Time: 2019-04-16T07:47:59.764+0000
Java: internal.osp.oidp.service.cluster.ClusterCookieContext.resolveSession() [147] thread=http-nio-0.0.0.0-10088-exec-21
Priority Level: FINER
Preamble: [OIDP]
Log Data: Created new Session: id: fc92e1c7e3e14917be55b31a2301defd-cc98839ce1adb9b8a4-CX, Type: TEMPORARY
Time: 2019-04-16T07:47:59.775+0000
Java: internal.osp.oidp.service.session.NIDPSession.<init>() [308] thread=http-nio-0.0.0.0-10088-exec-21
Priority Level: FINEST
Preamble: [OIDP]
Log Data: IDP oauth2 handler to process request received for sign
Time: 2019-04-16T07:47:59.757+0000
Java: internal.osp.oidp.service.servlets.handler.AuthenticationServiceRequestHandler.resolveHandler() [192] thread=http-nio-0.0.0.0-10088-exec-21
Priority Level: FINEST
Preamble: [OIDP]
Override locale: en_US
Element: sign
Element: oauth2
Path element count: 2
Service: For Advanced Authentication(id=auth)
Tenant: For Advanced Authentication
Request number: 1
Http request type: POST
HttpServletResponse exists.
Class: OSPRequestContext
Log Data:
Time: 2019-04-16T07:47:59.750+0000
Java: internal.osp.framework.servlet.OSPServlet.process() [198] thread=http-nio-0.0.0.0-10088-exec-21
Priority Level: FINEST
Preamble: [OSP]
OSPRequestContext
Attributes
data
Parameters
Last Accessed Time: 2019-04-16T07:47:59.746Z (1555400879746)
Id: 508911EFF63B755087357D7DAA2C15B7
Session
accept=text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2
user-agent=Java/1.8.0_192
pragma=no-cache
cache-control=no-cache
authorization=Basic ********
content-type=application/x-www-form-urlencoded
content-length=99
connection=close
x-forwarded-for=147.2.92.100
x-real-ip=147.2.92.100
host=127.0.0.1:10088
Headers
Remote Client IP Address: 127.0.0.1
Host IP Address: 127.0.0.1
Locale: en_US
Content Type: application/x-www-form-urlencoded
Content Length: 99
Server Port: 10088
Server Name: 127.0.0.1
Path Info: /TOP/auth/oauth2/sign
Servlet Path: /a
Context Path: /osp
Scheme: http
Request URL: /osp/a/TOP/auth/oauth2/sign
Method: POST
Log Data: HttpServletRequest (Number 1)
Time: 2019-04-16T07:47:59.747+0000
Java: internal.osp.common.logging.HttpRequestLogger.log() [340] thread=http-nio-0.0.0.0-10088-exec-21
Priority Level: FINER
Preamble: [OSP]
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
The parameters value includes the username but key is the request to the "/osp/a/TOP/auth/oauth2/sign" endpoint at the AAF server. This request will as well pass the user information over to the AAF server. There was a problem with an older version of NAM. I did not cjeck which version you are running but my setup is 4.4.4 and 4.5
Troubleshooting:
In order to debug the request to the "/osp/a/TOP/auth/oauth2/sign" endpiont you need to - enable the following NIDP cluster logging options:
Enable File Logging
Echo To Console,
Component File logger Levels:
Application, Liberty, OAuth & OpenID Connect = debug"
2) Add the property "debug true" on the AAF method
3) On the AAF Server turn on debug logging
4) clear all log files
5) start fiddler and run a test
6) If you see something like "Got exception while getting the signed data:" in the NAM logs you are fighting the problem with the bug in the older NAM version.
Note: The AAF logs are revers order. You read them from the bottom to the top