Express+nodejs app with passport OpenID Connect module fails to exchange the authorization_code with an access token.

By: Amitava Shee user 25 Feb 2016 at 9:38 a.m. CST

8 Responses
Amitava Shee gravatar
Is there a sample nodejs passport based application that you have for me to test the community edition of gluu? # Nodejs client application exception log ```bash express:router authenticate : /callback?session_state=3bc3151f-0faa-4613-9293-4322936b00cc&scope=openid&state&code=9c4e2009-576b-4482-b131-4d5151092186 +0ms ------> Url { protocol: 'https:', slashes: true, auth: null, host: '192.168.1.7.xip.io:9443', port: '9443', hostname: '192.168.1.7.xip.io', hash: null, search: null, query: null, pathname: '/callback', path: '/callback', href: 'https://192.168.1.7.xip.io:9443/callback' } +++++++++++++++++ IncomingMessage { _readableState: ReadableState { objectMode: false, highWaterMark: 16384, buffer: [], length: 0, pipes: null, pipesCount: 0, flowing: true, ended: true, endEmitted: true, reading: false, sync: false, needReadable: false, emittedReadable: false, readableListening: false, resumeScheduled: false, defaultEncoding: 'utf8', ranOut: false, awaitDrain: 0, readingMore: false, decoder: null, encoding: null }, readable: false, domain: null, _events: { end: [ [Function: responseOnEnd], [Function] ], data: [Function], close: [Function] }, _eventsCount: 3, _maxListeners: undefined, socket: TLSSocket { _tlsOptions: { pipe: null, secureContext: [Object], isServer: false, requestCert: true, rejectUnauthorized: false, session: undefined, NPNProtocols: undefined, ALPNProtocols: undefined, requestOCSP: undefined }, _secureEstablished: true, _securePending: false, _newSessionPending: false, _controlReleased: true, _SNICallback: null, servername: null, npnProtocol: undefined, alpnProtocol: false, authorized: false, authorizationError: 'DEPTH_ZERO_SELF_SIGNED_CERT', encrypted: true, _events: { close: [Object], end: [Object], finish: [Function: onSocketFinish], _socketEnd: [Function: onSocketEnd], secure: [Function], free: [Function: onFree], agentRemove: [Function: onRemove], drain: [Function: ondrain], error: [Function: socketErrorListener] }, _eventsCount: 9, _connecting: false, _hadError: false, _handle: null, _parent: null, _host: 'idp.pype.tech', _readableState: ReadableState { objectMode: false, highWaterMark: 16384, buffer: [], length: 0, pipes: null, pipesCount: 0, flowing: true, ended: false, endEmitted: false, reading: true, sync: false, needReadable: true, emittedReadable: false, readableListening: false, resumeScheduled: false, defaultEncoding: 'utf8', ranOut: false, awaitDrain: 0, readingMore: true, decoder: null, encoding: null }, readable: false, domain: null, _maxListeners: undefined, _writableState: WritableState { objectMode: false, highWaterMark: 16384, needDrain: false, ending: true, ended: true, finished: true, decodeStrings: false, defaultEncoding: 'utf8', length: 0, writing: false, corked: 0, sync: false, bufferProcessing: false, onwrite: [Function], writecb: null, writelen: 0, bufferedRequest: null, lastBufferedRequest: null, pendingcb: 0, prefinished: true, errorEmitted: false }, writable: false, allowHalfOpen: false, destroyed: true, bytesRead: 914, _bytesDispatched: 443, _sockname: null, _pendingData: null, _pendingEncoding: '', ssl: TLSWrap { _externalStream: {}, fd: -22, _parent: [Object], _parentWrap: undefined, _secureContext: [Object], reading: true, owner: [Circular], onread: [Function: noop], writeQueueSize: 1, onhandshakestart: [Function], onhandshakedone: [Function], onocspresponse: [Function], onerror: [Function] }, server: undefined, _requestCert: true, _rejectUnauthorized: false, parser: null, _httpMessage: ClientRequest { domain: null, _events: [Object], _eventsCount: 2, _maxListeners: undefined, output: [], outputEncodings: [], outputCallbacks: [], outputSize: 0, writable: true, _last: true, chunkedEncoding: false, shouldKeepAlive: false, useChunkedEncodingByDefault: true, sendDate: false, _removedHeader: [Object], _contentLength: null, _hasBody: true, _trailer: '', finished: true, _headerSent: true, socket: [Circular], connection: [Circular], _header: 'POST /oxauth/seam/resource/restv1/oxauth/token HTTP/1.1\r\nContent-Type: application/x-www-form-urlencoded\r\nHost: idp.pype.tech\r\nUser-Agent: Node-oauth\r\nContent-Length: 250\r\nConnection: close\r\n\r\n', _headers: [Object], _headerNames: [Object], _onPendingData: null, agent: [Object], socketPath: undefined, method: 'POST', path: '/oxauth/seam/resource/restv1/oxauth/token', parser: null, res: [Circular] }, read: [Function], _consuming: true, _idleNext: null, _idlePrev: null, _idleTimeout: -1 }, connection: TLSSocket { _tlsOptions: { pipe: null, secureContext: [Object], isServer: false, requestCert: true, rejectUnauthorized: false, session: undefined, NPNProtocols: undefined, ALPNProtocols: undefined, requestOCSP: undefined }, _secureEstablished: true, _securePending: false, _newSessionPending: false, _controlReleased: true, _SNICallback: null, servername: null, npnProtocol: undefined, alpnProtocol: false, authorized: false, authorizationError: 'DEPTH_ZERO_SELF_SIGNED_CERT', encrypted: true, _events: { close: [Object], end: [Object], finish: [Function: onSocketFinish], _socketEnd: [Function: onSocketEnd], secure: [Function], free: [Function: onFree], agentRemove: [Function: onRemove], drain: [Function: ondrain], error: [Function: socketErrorListener] }, _eventsCount: 9, _connecting: false, _hadError: false, _handle: null, _parent: null, _host: 'idp.pype.tech', _readableState: ReadableState { objectMode: false, highWaterMark: 16384, buffer: [], length: 0, pipes: null, pipesCount: 0, flowing: true, ended: false, endEmitted: false, reading: true, sync: false, needReadable: true, emittedReadable: false, readableListening: false, resumeScheduled: false, defaultEncoding: 'utf8', ranOut: false, awaitDrain: 0, readingMore: true, decoder: null, encoding: null }, readable: false, domain: null, _maxListeners: undefined, _writableState: WritableState { objectMode: false, highWaterMark: 16384, needDrain: false, ending: true, ended: true, finished: true, decodeStrings: false, defaultEncoding: 'utf8', length: 0, writing: false, corked: 0, sync: false, bufferProcessing: false, onwrite: [Function], writecb: null, writelen: 0, bufferedRequest: null, lastBufferedRequest: null, pendingcb: 0, prefinished: true, errorEmitted: false }, writable: false, allowHalfOpen: false, destroyed: true, bytesRead: 914, _bytesDispatched: 443, _sockname: null, _pendingData: null, _pendingEncoding: '', ssl: TLSWrap { _externalStream: {}, fd: -22, _parent: [Object], _parentWrap: undefined, _secureContext: [Object], reading: true, owner: [Circular], onread: [Function: noop], writeQueueSize: 1, onhandshakestart: [Function], onhandshakedone: [Function], onocspresponse: [Function], onerror: [Function] }, server: undefined, _requestCert: true, _rejectUnauthorized: false, parser: null, _httpMessage: ClientRequest { domain: null, _events: [Object], _eventsCount: 2, _maxListeners: undefined, output: [], outputEncodings: [], outputCallbacks: [], outputSize: 0, writable: true, _last: true, chunkedEncoding: false, shouldKeepAlive: false, useChunkedEncodingByDefault: true, sendDate: false, _removedHeader: [Object], _contentLength: null, _hasBody: true, _trailer: '', finished: true, _headerSent: true, socket: [Circular], connection: [Circular], _header: 'POST /oxauth/seam/resource/restv1/oxauth/token HTTP/1.1\r\nContent-Type: application/x-www-form-urlencoded\r\nHost: idp.pype.tech\r\nUser-Agent: Node-oauth\r\nContent-Length: 250\r\nConnection: close\r\n\r\n', _headers: [Object], _headerNames: [Object], _onPendingData: null, agent: [Object], socketPath: undefined, method: 'POST', path: '/oxauth/seam/resource/restv1/oxauth/token', parser: null, res: [Circular] }, read: [Function], _consuming: true, _idleNext: null, _idlePrev: null, _idleTimeout: -1 }, httpVersionMajor: 1, httpVersionMinor: 1, httpVersion: '1.1', complete: true, headers: { date: 'Wed, 24 Feb 2016 01:13:28 GMT', 'www-authenticate': 'Basic realm="oxAuth"', 'content-type': 'application/json;charset=ISO-8859-1', 'content-length': '586', 'set-cookie': [ 'JSESSIONID=9D1F76D9ED205479F3427CBC3E0BC2F5; Path=/oxauth/; Secure; HttpOnly;HttpOnly' ], 'access-control-allow-origin': '*', connection: 'close' }, rawHeaders: [ 'Date', 'Wed, 24 Feb 2016 01:13:28 GMT', 'WWW-Authenticate', 'Basic realm="oxAuth"', 'Content-Type', 'application/json;charset=ISO-8859-1', 'Content-Length', '586', 'Set-Cookie', 'JSESSIONID=9D1F76D9ED205479F3427CBC3E0BC2F5; Path=/oxauth/; Secure; HttpOnly;HttpOnly', 'Access-Control-Allow-Origin', '*', 'Connection', 'close' ], trailers: {}, rawTrailers: [], upgrade: false, url: '', method: null, statusCode: 401, statusMessage: 'Unauthorized', client: TLSSocket { _tlsOptions: { pipe: null, secureContext: [Object], isServer: false, requestCert: true, rejectUnauthorized: false, session: undefined, NPNProtocols: undefined, ALPNProtocols: undefined, requestOCSP: undefined }, _secureEstablished: true, _securePending: false, _newSessionPending: false, _controlReleased: true, _SNICallback: null, servername: null, npnProtocol: undefined, alpnProtocol: false, authorized: false, authorizationError: 'DEPTH_ZERO_SELF_SIGNED_CERT', encrypted: true, _events: { close: [Object], end: [Object], finish: [Function: onSocketFinish], _socketEnd: [Function: onSocketEnd], secure: [Function], free: [Function: onFree], agentRemove: [Function: onRemove], drain: [Function: ondrain], error: [Function: socketErrorListener] }, _eventsCount: 9, _connecting: false, _hadError: false, _handle: null, _parent: null, _host: 'idp.pype.tech', _readableState: ReadableState { objectMode: false, highWaterMark: 16384, buffer: [], length: 0, pipes: null, pipesCount: 0, flowing: true, ended: false, endEmitted: false, reading: true, sync: false, needReadable: true, emittedReadable: false, readableListening: false, resumeScheduled: false, defaultEncoding: 'utf8', ranOut: false, awaitDrain: 0, readingMore: true, decoder: null, encoding: null }, readable: false, domain: null, _maxListeners: undefined, _writableState: WritableState { objectMode: false, highWaterMark: 16384, needDrain: false, ending: true, ended: true, finished: true, decodeStrings: false, defaultEncoding: 'utf8', length: 0, writing: false, corked: 0, sync: false, bufferProcessing: false, onwrite: [Function], writecb: null, writelen: 0, bufferedRequest: null, lastBufferedRequest: null, pendingcb: 0, prefinished: true, errorEmitted: false }, writable: false, allowHalfOpen: false, destroyed: true, bytesRead: 914, _bytesDispatched: 443, _sockname: null, _pendingData: null, _pendingEncoding: '', ssl: TLSWrap { _externalStream: {}, fd: -22, _parent: [Object], _parentWrap: undefined, _secureContext: [Object], reading: true, owner: [Circular], onread: [Function: noop], writeQueueSize: 1, onhandshakestart: [Function], onhandshakedone: [Function], onocspresponse: [Function], onerror: [Function] }, server: undefined, _requestCert: true, _rejectUnauthorized: false, parser: null, _httpMessage: ClientRequest { domain: null, _events: [Object], _eventsCount: 2, _maxListeners: undefined, output: [], outputEncodings: [], outputCallbacks: [], outputSize: 0, writable: true, _last: true, chunkedEncoding: false, shouldKeepAlive: false, useChunkedEncodingByDefault: true, sendDate: false, _removedHeader: [Object], _contentLength: null, _hasBody: true, _trailer: '', finished: true, _headerSent: true, socket: [Circular], connection: [Circular], _header: 'POST /oxauth/seam/resource/restv1/oxauth/token HTTP/1.1\r\nContent-Type: application/x-www-form-urlencoded\r\nHost: idp.pype.tech\r\nUser-Agent: Node-oauth\r\nContent-Length: 250\r\nConnection: close\r\n\r\n', _headers: [Object], _headerNames: [Object], _onPendingData: null, agent: [Object], socketPath: undefined, method: 'POST', path: '/oxauth/seam/resource/restv1/oxauth/token', parser: null, res: [Circular] }, read: [Function], _consuming: true, _idleNext: null, _idlePrev: null, _idleTimeout: -1 }, _consuming: true, _dumped: false, req: ClientRequest { domain: null, _events: { response: [Function], error: [Function] }, _eventsCount: 2, _maxListeners: undefined, output: [], outputEncodings: [], outputCallbacks: [], outputSize: 0, writable: true, _last: true, chunkedEncoding: false, shouldKeepAlive: false, useChunkedEncodingByDefault: true, sendDate: false, _removedHeader: { 'content-length': false }, _contentLength: null, _hasBody: true, _trailer: '', finished: true, _headerSent: true, socket: TLSSocket { _tlsOptions: [Object], _secureEstablished: true, _securePending: false, _newSessionPending: false, _controlReleased: true, _SNICallback: null, servername: null, npnProtocol: undefined, alpnProtocol: false, authorized: false, authorizationError: 'DEPTH_ZERO_SELF_SIGNED_CERT', encrypted: true, _events: [Object], _eventsCount: 9, _connecting: false, _hadError: false, _handle: null, _parent: null, _host: 'idp.pype.tech', _readableState: [Object], readable: false, domain: null, _maxListeners: undefined, _writableState: [Object], writable: false, allowHalfOpen: false, destroyed: true, bytesRead: 914, _bytesDispatched: 443, _sockname: null, _pendingData: null, _pendingEncoding: '', ssl: [Object], server: undefined, _requestCert: true, _rejectUnauthorized: false, parser: null, _httpMessage: [Circular], read: [Function], _consuming: true, _idleNext: null, _idlePrev: null, _idleTimeout: -1 }, connection: TLSSocket { _tlsOptions: [Object], _secureEstablished: true, _securePending: false, _newSessionPending: false, _controlReleased: true, _SNICallback: null, servername: null, npnProtocol: undefined, alpnProtocol: false, authorized: false, authorizationError: 'DEPTH_ZERO_SELF_SIGNED_CERT', encrypted: true, _events: [Object], _eventsCount: 9, _connecting: false, _hadError: false, _handle: null, _parent: null, _host: 'idp.pype.tech', _readableState: [Object], readable: false, domain: null, _maxListeners: undefined, _writableState: [Object], writable: false, allowHalfOpen: false, destroyed: true, bytesRead: 914, _bytesDispatched: 443, _sockname: null, _pendingData: null, _pendingEncoding: '', ssl: [Object], server: undefined, _requestCert: true, _rejectUnauthorized: false, parser: null, _httpMessage: [Circular], read: [Function], _consuming: true, _idleNext: null, _idlePrev: null, _idleTimeout: -1 }, _header: 'POST /oxauth/seam/resource/restv1/oxauth/token HTTP/1.1\r\nContent-Type: application/x-www-form-urlencoded\r\nHost: idp.pype.tech\r\nUser-Agent: Node-oauth\r\nContent-Length: 250\r\nConnection: close\r\n\r\n', _headers: { 'content-type': 'application/x-www-form-urlencoded', host: 'idp.pype.tech', 'user-agent': 'Node-oauth', 'content-length': 250 }, _headerNames: { 'content-type': 'Content-Type', host: 'Host', 'user-agent': 'User-Agent', 'content-length': 'Content-Length' }, _onPendingData: null, agent: Agent { domain: null, _events: [Object], _eventsCount: 1, _maxListeners: undefined, defaultPort: 443, protocol: 'https:', options: [Object], requests: {}, sockets: [Object], freeSockets: {}, keepAliveMsecs: 1000, keepAlive: false, maxSockets: Infinity, maxFreeSockets: 256, maxCachedSessions: 100, _sessionCache: [Object] }, socketPath: undefined, method: 'POST', path: '/oxauth/seam/resource/restv1/oxauth/token', parser: null, res: [Circular] }, read: [Function] } finalhandler default 500 +418ms express-session saving zKxVl5f-iHsYBXAIZ5-9CNMTsc66-X-G +1ms express-session split response +0ms InternalOAuthError: failed to obtain access token at /Users/amitava/Projects/ps/express-4.x-openidconnect-example/node_modules/passport-openidconnect/lib/strategy.js:77:36 at /Users/amitava/Projects/ps/express-4.x-openidconnect-example/node_modules/oauth/lib/oauth2.js:182:18 at passBackControl (/Users/amitava/Projects/ps/express-4.x-openidconnect-example/node_modules/oauth/lib/oauth2.js:126:9) at IncomingMessage.<anonymous> (/Users/amitava/Projects/ps/express-4.x-openidconnect-example/node_modules/oauth/lib/oauth2.js:147:7) at emitNone (events.js:85:20) at IncomingMessage.emit (events.js:179:7) at endReadableNT (_stream_readable.js:906:12) at nextTickCallbackWith2Args (node.js:474:9) at process._tickCallback (node.js:388:17) morgan log request +1ms ::ffff:192.168.1.7 - - [24/Feb/2016:01:12:57 +0000] "GET /callback?session_state=3bc3151f-0faa-4613-9293-4322936b00cc&scope=openid&state&code=9c4e2009-576b-4482-b131-4d5151092186 HTTP/1.1" 500 894 "https://idp.pype.tech/oxauth/authorize?response_type=code&scope=openid&redirect_uri=https%3A%2F%2F192.168.1.7.xip.io%3A9443%2Fcallback&client_id=%40%21564F.8893.C2D4.207E%210001%21EFA3.3DDC%210008%21BE81.484F" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/48.0.2564.116 Safari/537.36" ``` # And the server logs are shown below ```bash 2016-02-24 01:19:09,409 TRACE [xdi.oxauth.authorize.ws.rs.AuthorizeAction] permissionGranted, redirectTo: seam/resource/restv1/oxauth/authorize?scope=openid+profile+email+user_name&response_type=code+id_token&redirect_uri=https%3A%2F%2Fidp.pype.tech%2Fidentity%2Fauthentication%2Fauthcode&nonce=nonce&client_id=%40%21564F.8893.C2D4.207E%210001%21EFA3.3DDC%210008%2151D5.6B35 2016-02-24 01:19:09,857 TRACE [org.xdi.oxauth.service.SessionStateService] Found session_state cookie: '3bc3151f-0faa-4613-9293-4322936b00cc' 2016-02-24 01:19:09,859 TRACE [org.xdi.oxauth.service.SessionStateService] Try to get session by id: 3bc3151f-0faa-4613-9293-4322936b00cc ... 2016-02-24 01:19:09,859 TRACE [org.xdi.oxauth.service.SessionStateService] Session dn: uniqueIdentifier=3bc3151f-0faa-4613-9293-4322936b00cc,ou=session,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu 2016-02-24 01:19:09,861 TRACE [org.xdi.oxauth.service.SessionStateService] Try to get session by id: 3bc3151f-0faa-4613-9293-4322936b00cc ... 2016-02-24 01:19:09,861 TRACE [org.xdi.oxauth.service.SessionStateService] Session dn: uniqueIdentifier=3bc3151f-0faa-4613-9293-4322936b00cc,ou=session,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu 2016-02-24 01:19:09,862 TRACE [org.xdi.oxauth.auth.Authenticator] authenticateBySessionState, sessionState = '3bc3151f-0faa-4613-9293-4322936b00cc', session = 'SessionState, dn='uniqueIdentifier=3bc3151f-0faa-4613-9293-4322936b00cc,ou=session,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu', id='3bc3151f-0faa-4613-9293-4322936b00cc', lastUsedAt=Wed Feb 24 01:19:09 UTC 2016, userDn='inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0000!A8F2.DE1E.D7FB,ou=people,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu', authenticationTime=Wed Feb 24 01:13:22 UTC 2016, state=authenticated, permissionGranted=null, permissionGrantedMap=org.xdi.oxauth.model.common.SessionIdAccessMap@679e757c, sessionAttributes={response_type=code id_token, scope=openid profile email user_name, nonce=nonce, redirect_uri=https://idp.pype.tech/identity/authentication/authcode, auth_step=1, client_id=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!51D5.6B35, acr=internal}, persisted=false}', state= 'authenticated' 2016-02-24 01:19:09,866 TRACE [org.xdi.oxauth.auth.AuthenticationFilter] Process Session Auth, sessionState = 3bc3151f-0faa-4613-9293-4322936b00cc, requireAuth = false 2016-02-24 01:19:09,868 DEBUG [xdi.oxauth.authorize.ws.rs.AuthorizeRestWebServiceImpl] Attempting to request authorization: responseType = code id_token, clientId = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!51D5.6B35, scope = openid profile email user_name, redirectUri = https://idp.pype.tech/identity/authentication/authcode, nonce = nonce, state = null, request = null, isSecure = true, requestSessionState = null, sessionState = null 2016-02-24 01:19:09,868 DEBUG [xdi.oxauth.authorize.ws.rs.AuthorizeRestWebServiceImpl] Attempting to request authorization: acrValues = null, amrValues = null, originHeaders = {4} 2016-02-24 01:19:09,869 TRACE [org.xdi.oxauth.service.ClientService] Get client from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!51D5.6B35,ou=clients,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:09,869 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!51D5.6B35 2016-02-24 01:19:09,869 DEBUG [org.xdi.oxauth.model.authorize.ScopeChecker] Checking scopes policy for: openid profile email user_name 2016-02-24 01:19:09,880 DEBUG [org.xdi.oxauth.model.authorize.ScopeChecker] Granted scopes: [user_name, email, openid, profile] 2016-02-24 01:19:09,880 TRACE [org.xdi.oxauth.service.ClientService] Get client from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!51D5.6B35,ou=clients,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:09,881 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!51D5.6B35 2016-02-24 01:19:09,881 DEBUG [org.xdi.oxauth.service.RedirectionUriService] Validating redirection URI: clientIdentifier = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!51D5.6B35, redirectionUri = https://idp.pype.tech/identity/authentication/authcode, found = 3 2016-02-24 01:19:09,881 DEBUG [org.xdi.oxauth.service.RedirectionUriService] Comparing https://idp.pype.tech/identity/scim/auth == https://idp.pype.tech/identity/authentication/authcode 2016-02-24 01:19:09,881 DEBUG [org.xdi.oxauth.service.RedirectionUriService] Comparing https://idp.pype.tech/identity/authentication/authcode == https://idp.pype.tech/identity/authentication/authcode 2016-02-24 01:19:09,920 DEBUG [org.xdi.oxauth.model.authorize.ScopeChecker] Checking scopes policy for: openid profile email user_name 2016-02-24 01:19:09,930 DEBUG [org.xdi.oxauth.model.authorize.ScopeChecker] Granted scopes: [user_name, email, openid, profile] 2016-02-24 01:19:11,368 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!51D5.6B35 2016-02-24 01:19:11,369 DEBUG [org.xdi.oxauth.service.ClientService] Authenticating Client with LDAP: clientId = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!51D5.6B35 2016-02-24 01:19:11,369 TRACE [org.xdi.oxauth.service.ClientService] Get client from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!51D5.6B35,ou=clients,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,369 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!51D5.6B35 2016-02-24 01:19:11,370 TRACE [org.xdi.oxauth.service.ClientService] Get client from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!51D5.6B35,ou=clients,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,370 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!51D5.6B35 2016-02-24 01:19:11,373 INFO [org.xdi.oxauth.auth.Authenticator] Authentication success for Client: '@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!51D5.6B35' 2016-02-24 01:19:11,373 TRACE [org.xdi.oxauth.auth.Authenticator] Authentication successfully for '@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!51D5.6B35' 2016-02-24 01:19:11,374 DEBUG [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] Attempting to request access token: grantType = authorization_code, code = 4c80ba7b-bc81-477a-a391-88bd81c49336, redirectUri = https://idp.pype.tech/identity/authentication/authcode, username = null, refreshToken = null, clientId = null, ExtraParams = {grant_type=[Ljava.lang.String;@44ad9e84, redirect_uri=[Ljava.lang.String;@62820f55, code=[Ljava.lang.String;@48bcc7f9}, isSecure = true 2016-02-24 01:19:11,376 DEBUG [org.xdi.oxauth.service.UserService] Getting user information from LDAP: userId = admin 2016-02-24 01:19:11,377 DEBUG [org.xdi.oxauth.service.UserService] Found 1 entries for user id = admin 2016-02-24 01:19:11,378 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!51D5.6B35 2016-02-24 01:19:11,381 DEBUG [xdi.oxauth.token.ws.rs.TokenRestWebServiceImpl] Issuing access token: 86c7db1e-2dde-4a2c-90ca-b290524ee495 2016-02-24 01:19:11,386 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!42E0,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,387 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!8F88,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,387 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!CAE3,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,388 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!29DA,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,389 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!2B29,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,390 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!0C85,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,390 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!B4B0,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,390 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!A0E8,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,390 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!5EC6,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,390 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!B52A,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,390 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!64A0,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,391 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!EC3A,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,391 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!3B47,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,391 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!3692,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,391 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!98FC,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,391 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!A901,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,392 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!36D9,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,392 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!BE64,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,392 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!6493,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,409 TRACE [org.xdi.oxauth.service.GrantService] Removed token, code: 4c80ba7b-bc81-477a-a391-88bd81c49336 2016-02-24 01:19:11,464 DEBUG [xdi.oxauth.token.ws.rs.ValidateTokenRestWebServiceImpl] Attempting to validate access token: 86c7db1e-2dde-4a2c-90ca-b290524ee495, Is Secure = true 2016-02-24 01:19:11,465 DEBUG [org.xdi.oxauth.service.UserService] Getting user information from LDAP: userId = admin 2016-02-24 01:19:11,466 DEBUG [org.xdi.oxauth.service.UserService] Found 1 entries for user id = admin 2016-02-24 01:19:11,466 TRACE [org.xdi.oxauth.service.ClientService] Get client from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!51D5.6B35,ou=clients,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,466 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!51D5.6B35 2016-02-24 01:19:11,522 DEBUG [xdi.oxauth.userinfo.ws.rs.UserInfoRestWebServiceImpl] Attempting to request User Info, Access token = 86c7db1e-2dde-4a2c-90ca-b290524ee495, Is Secure = true 2016-02-24 01:19:11,523 DEBUG [org.xdi.oxauth.service.UserService] Getting user information from LDAP: userId = admin 2016-02-24 01:19:11,524 DEBUG [org.xdi.oxauth.service.UserService] Found 1 entries for user id = admin 2016-02-24 01:19:11,524 TRACE [org.xdi.oxauth.service.ClientService] Get client from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!51D5.6B35,ou=clients,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,524 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!51D5.6B35 2016-02-24 01:19:11,527 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!42E0,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,528 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!8F88,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,528 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!CAE3,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,529 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!29DA,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,530 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!2B29,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,531 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!0C85,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,531 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!B4B0,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,531 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!A0E8,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,531 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!5EC6,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,531 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!B52A,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,531 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!64A0,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,532 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!EC3A,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,532 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!3B47,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,532 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!3692,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,532 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!98FC,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,532 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!A901,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,532 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!36D9,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,533 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!BE64,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-24 01:19:11,533 TRACE [org.xdi.oxauth.service.AttributeService] Get attribute from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0005!6493,ou=attributes,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' ```
None
closed

Answers

By Michael Schwartz Account Admin 25 Feb 2016 at 2:53 p.m. CST

Copy
Michael Schwartz gravatar
Can you post the ldif for the client? You can use /opt/opendj/bin/ldapsearch -h <localhost> -p 1636 -Z -X -D "cn=directory manager" \ -j ~/.pw -b "o=gluu" "inum=*51D5.6B35" Put the DM password in ~/.pw Remove it when you're done.

By Amitava Shee user 25 Feb 2016 at 3:04 p.m. CST

Copy
Amitava Shee gravatar
Here is the output # /opt/opendj/bin/ldapsearch -h localhost -p 1636 -Z -X -D "cn=directory manager" \ -j ~/.pw -b "o=gluu" "inum=*51D5.6B35" dn: inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!51D5.6B35,ou=clients,o=@!564F .8893.C2D4.207E!0001!EFA3.3DDC,o=gluu oxAuthScope: inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0009!F0C4,ou=scopes,o=@!5 64F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu oxAuthScope: inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0009!10B2,ou=scopes,o=@!5 64F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu oxAuthScope: inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0009!764C,ou=scopes,o=@!5 64F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu oxAuthScope: inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0009!43F1,ou=scopes,o=@!5 64F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu oxAuthAppType: web oxAuthResponseType: code oxAuthResponseType: id_token oxAuthResponseType: token oxLastAccessTime: 20160225201414.633Z oxAuthClientSecret: d2nruu+yB/sEm1Ao9i1Fpg== oxAuthPostLogoutRedirectURI: https://idp.pype.tech/identity/authentication/finis hlogout objectClass: oxAuthClient objectClass: top oxAuthTokenEndpointAuthMethod: client_secret_basic oxAuthRedirectURI: https://idp.pype.tech/identity/scim/auth oxAuthRedirectURI: https://idp.pype.tech/identity/authentication/authcode oxAuthRedirectURI: https://idp.pype.tech/idp/auth-code.jsp oxLastLogonTime: 20160225201414.633Z oxAuthTrustedClient: true oxAuthIdTokenSignedResponseAlg: HS256 displayName: oxTrust Admin GUI inum: @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!51D5.6B35

By Michael Schwartz Account Admin 25 Feb 2016 at 3:22 p.m. CST

Copy
Michael Schwartz gravatar
If you look at [Response Type Values](http://openid.net/specs/openid-connect-core-1_0.html#Authentication) for implicit flow, it does not include "code". A few things I notice: 1. In the log from your node applicaiton, it states: `statusCode: 401, statusMessage: 'Unauthorized', client` 2. I also see `response_type=code` in your request. 3. If its a javascript client using implicit flow, why is your client configured for `oxAuthResponseType: code` ? We are not experts on configuring every OpenID Connect client with the Gluu Server. Are you sure your using this client correctly?

By Amitava Shee user 25 Feb 2016 at 3:34 p.m. CST

Copy
Amitava Shee gravatar
This is not client side javascript but server side javascript running inside nodejs. The client (or rather server side web-app client) is not requesting implicit. However, I dig some digging on what the client is doing - it is sending the authorization_code over an https post. Does it matter if the token endpoint is invoked via get or post?

By Michael Schwartz Account Admin 25 Feb 2016 at 4:05 p.m. CST

Copy
Michael Schwartz gravatar
ok, then if your using authorization code flow, (which is better for security!) why is the client configured for responseType `token` and `id_token` ? I also see Attempting to request authorization: responseType = code id_token, I don't think this is correct.... the request should just be for `code`

By Amitava Shee user 25 Feb 2016 at 4:41 p.m. CST

Copy
Amitava Shee gravatar
Ok. I registered a new client using oxauth-rp/home.seam and this time just picked code CODE and AUTHORIZATION_CODE. Same outcome. Here's the new client_id @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C The strange thing is that I can't find this new record in the ldap query but I can see it in oxTrust UI. ```bash GLUU.[root@idp ~]# /opt/opendj/bin/ldapsearch -h localhost -p 1636 -Z -X -D "cn=directory manager" -j ~/.pw -b "o=gluu" "inum=*564F" GLUU.[root@idp ~]# ```

By Amitava Shee user 25 Feb 2016 at 4:48 p.m. CST

Copy
Amitava Shee gravatar
Here is the server log ```bash 2016-02-25 22:28:57,954 DEBUG [xdi.oxauth.register.ws.rs.RegisterRestWebServiceImpl] Attempting to register client: applicationType = web, clientName = , redirectUris = [https://192.168.1.7.xip.io:9443/callback], isSecure = true, sectorIdentifierUri = , params = { "redirect_uris": ["https:\/\/192.168.1.7.xip.io:9443\/callback"], "response_types": ["code"], "grant_types": ["authorization_code"], "application_type": "web", "token_endpoint_auth_method": "client_secret_basic", "subject_type": "pairwise", "request_object_signing_alg": "none", "userinfo_signed_response_alg": "none", "userinfo_encrypted_response_alg": "RSA1_5", "userinfo_encrypted_response_enc": "A128CBC+HS256", "id_token_signed_response_alg": "none", "id_token_encrypted_response_alg": "RSA1_5", "id_token_encrypted_response_enc": "A128CBC+HS256", "require_auth_time": false } 2016-02-25 22:28:57,956 TRACE [xdi.oxauth.idgen.ws.rs.InumGenerator] Generated inum: @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C 2016-02-25 22:30:06,243 DEBUG [xdi.oxauth.authorize.ws.rs.AuthorizeRestWebServiceImpl] Attempting to request authorization: responseType = code, clientId = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C, scope = openid, redirectUri = https://192.168.1.7.xip.io:9443/callback, nonce = null, state = null, request = null, isSecure = true, requestSessionState = null, sessionState = null 2016-02-25 22:30:06,243 DEBUG [xdi.oxauth.authorize.ws.rs.AuthorizeRestWebServiceImpl] Attempting to request authorization: acrValues = null, amrValues = null, originHeaders = {4} 2016-02-25 22:30:06,245 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C 2016-02-25 22:30:06,245 DEBUG [org.xdi.oxauth.model.authorize.ScopeChecker] Checking scopes policy for: openid 2016-02-25 22:30:06,245 DEBUG [org.xdi.oxauth.model.authorize.ScopeChecker] Granted scopes: [openid] 2016-02-25 22:30:06,246 TRACE [org.xdi.oxauth.service.ClientService] Get client from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C,ou=clients,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-25 22:30:06,246 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C 2016-02-25 22:30:06,246 DEBUG [org.xdi.oxauth.service.RedirectionUriService] Validating redirection URI: clientIdentifier = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C, redirectionUri = https://192.168.1.7.xip.io:9443/callback, found = 1 2016-02-25 22:30:06,246 DEBUG [org.xdi.oxauth.service.RedirectionUriService] Comparing https://192.168.1.7.xip.io:9443/callback == https://192.168.1.7.xip.io:9443/callback 2016-02-25 22:30:06,690 DEBUG [org.xdi.oxauth.service.external.ExternalAuthenticationService] Executing python 'getPageForStep' authenticator method 2016-02-25 22:30:06,691 TRACE [org.xdi.oxauth.service.SessionStateService] Generated new session, id = '00415c40-6878-4306-9241-c1e5676c8273', state = 'unauthenticated', persisted = 'false' 2016-02-25 22:30:06,693 TRACE [xdi.oxauth.authorize.ws.rs.AuthorizeAction] Session '00415c40-6878-4306-9241-c1e5676c8273' persisted to LDAP 2016-02-25 22:30:07,135 TRACE [org.xdi.oxauth.service.SessionStateService] Found session_state cookie: '00415c40-6878-4306-9241-c1e5676c8273' 2016-02-25 22:30:07,137 TRACE [org.xdi.oxauth.service.SessionStateService] Try to get session by id: 00415c40-6878-4306-9241-c1e5676c8273 ... 2016-02-25 22:30:07,137 TRACE [org.xdi.oxauth.service.SessionStateService] Session dn: uniqueIdentifier=00415c40-6878-4306-9241-c1e5676c8273,ou=session,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu 2016-02-25 22:30:07,137 DEBUG [org.xdi.oxauth.service.external.ExternalAuthenticationService] Validating auth_mode: 'internal' 2016-02-25 22:30:07,137 DEBUG [org.xdi.oxauth.service.external.ExternalAuthenticationService] Executing python 'isValidAuthenticationMethod' authenticator method 2016-02-25 22:30:07,137 DEBUG [org.xdi.oxauth.service.external.ExternalAuthenticationService] Executing python 'prepareForStep' authenticator method 2016-02-25 22:30:07,141 TRACE [org.xdi.oxauth.service.ClientService] Get client from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C,ou=clients,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-25 22:30:07,141 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C 2016-02-25 22:30:07,143 TRACE [org.xdi.oxauth.service.ClientService] Get client from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C,ou=clients,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-25 22:30:07,143 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C 2016-02-25 22:30:07,143 TRACE [org.xdi.oxauth.service.ClientService] Get client from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C,ou=clients,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-25 22:30:07,143 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C 2016-02-25 22:30:25,049 TRACE [org.xdi.oxauth.service.SessionStateService] Found session_state cookie: '00415c40-6878-4306-9241-c1e5676c8273' 2016-02-25 22:30:25,051 TRACE [org.xdi.oxauth.service.SessionStateService] Try to get session by id: 00415c40-6878-4306-9241-c1e5676c8273 ... 2016-02-25 22:30:25,051 TRACE [org.xdi.oxauth.service.SessionStateService] Session dn: uniqueIdentifier=00415c40-6878-4306-9241-c1e5676c8273,ou=session,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu 2016-02-25 22:30:25,051 DEBUG [org.xdi.oxauth.service.external.ExternalAuthenticationService] Executing python 'authenticate' authenticator method 2016-02-25 22:30:25,051 DEBUG [org.xdi.oxauth.service.AuthenticationService] Authenticating user with LDAP: username: admin 2016-02-25 22:30:25,052 DEBUG [org.xdi.oxauth.service.AuthenticationService] Attempting to find userDN by primary key: 'uid' and key value: 'admin' 2016-02-25 22:30:25,052 DEBUG [org.xdi.oxauth.service.AuthenticationService] Getting user information from LDAP: attributeName = 'uid', attributeValue = 'admin' 2016-02-25 22:30:25,053 DEBUG [org.xdi.oxauth.service.AuthenticationService] Found '1' entries 2016-02-25 22:30:25,053 DEBUG [org.xdi.oxauth.service.AuthenticationService] Attempting to authenticate userDN: inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0000!A8F2.DE1E.D7FB,ou=people,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu 2016-02-25 22:30:25,054 DEBUG [org.xdi.oxauth.service.AuthenticationService] User authenticated: inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0000!A8F2.DE1E.D7FB,ou=people,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu 2016-02-25 22:30:25,054 DEBUG [org.xdi.oxauth.service.AuthenticationService] Attempting to find userDN by local primary key: uid 2016-02-25 22:30:25,054 DEBUG [org.xdi.oxauth.service.UserService] Getting user information from LDAP: attributeName = 'uid', attributeValue = 'admin' 2016-02-25 22:30:25,055 DEBUG [org.xdi.oxauth.service.UserService] Found '1' entries 2016-02-25 22:30:25,058 DEBUG [org.xdi.oxauth.auth.Authenticator] Authentication result for user 'admin'. auth_step: '1', result: 'true' 2016-02-25 22:30:25,058 DEBUG [org.xdi.oxauth.service.external.ExternalAuthenticationService] Executing python 'getCountAuthenticationSteps' authenticator method 2016-02-25 22:30:25,061 TRACE [org.xdi.oxauth.service.SessionStateService] Authenticated session, id = '00415c40-6878-4306-9241-c1e5676c8273', state = 'authenticated', persisted = 'true' 2016-02-25 22:30:25,062 DEBUG [org.xdi.oxauth.auth.Authenticator] Sending event to trigger user redirection: 'admin' 2016-02-25 22:30:25,062 INFO [org.xdi.oxauth.service.AuthenticationService] Attempting to redirect user. SessionUser: SessionState, dn='uniqueIdentifier=00415c40-6878-4306-9241-c1e5676c8273,ou=session,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu', id='00415c40-6878-4306-9241-c1e5676c8273', lastUsedAt=Thu Feb 25 22:30:25 UTC 2016, userDn='inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0000!A8F2.DE1E.D7FB,ou=people,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu', authenticationTime=Thu Feb 25 22:30:25 UTC 2016, state=authenticated, permissionGranted=null, permissionGrantedMap=null, sessionAttributes={scope=openid, response_type=code, redirect_uri=https://192.168.1.7.xip.io:9443/callback, auth_step=1, client_id=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C, acr=internal}, persisted=true} 2016-02-25 22:30:25,063 INFO [org.xdi.oxauth.service.AuthenticationService] Attempting to redirect user. User: org.xdi.oxauth.model.common.User@74e5ef8b 2016-02-25 22:30:25,063 TRACE [org.xdi.oxauth.service.AuthenticationService] Logged in successfully! User: org.xdi.oxauth.model.common.User@74e5ef8b, page: /authorize.xhtml, map: {response_type=code, scope=openid, redirect_uri=https://192.168.1.7.xip.io:9443/callback, client_id=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C} 2016-02-25 22:30:25,065 INFO [org.xdi.oxauth.auth.Authenticator] Authentication success for User: 'admin' 2016-02-25 22:30:25,066 TRACE [org.xdi.oxauth.auth.Authenticator] Authentication successfully for 'admin' 2016-02-25 22:30:25,553 TRACE [org.xdi.oxauth.service.SessionStateService] Found session_state cookie: '00415c40-6878-4306-9241-c1e5676c8273' 2016-02-25 22:30:25,555 TRACE [org.xdi.oxauth.service.SessionStateService] Try to get session by id: 00415c40-6878-4306-9241-c1e5676c8273 ... 2016-02-25 22:30:25,555 TRACE [org.xdi.oxauth.service.SessionStateService] Session dn: uniqueIdentifier=00415c40-6878-4306-9241-c1e5676c8273,ou=session,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu 2016-02-25 22:30:25,556 TRACE [org.xdi.oxauth.service.ClientService] Get client from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C,ou=clients,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-25 22:30:25,556 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C 2016-02-25 22:30:25,556 TRACE [org.xdi.oxauth.service.ClientService] Get client from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C,ou=clients,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-25 22:30:25,556 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C 2016-02-25 22:30:25,556 DEBUG [org.xdi.oxauth.service.RedirectionUriService] Validating redirection URI: clientIdentifier = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C, redirectionUri = https://192.168.1.7.xip.io:9443/callback, found = 1 2016-02-25 22:30:25,556 DEBUG [org.xdi.oxauth.service.RedirectionUriService] Comparing https://192.168.1.7.xip.io:9443/callback == https://192.168.1.7.xip.io:9443/callback 2016-02-25 22:30:25,557 TRACE [xdi.oxauth.authorize.ws.rs.AuthorizeAction] checkPermissionGranted, user = org.xdi.oxauth.model.common.User@5d8599a 2016-02-25 22:30:25,563 TRACE [org.xdi.oxauth.service.ClientService] Get client from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C,ou=clients,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-25 22:30:25,563 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C 2016-02-25 22:30:25,563 TRACE [org.xdi.oxauth.service.ClientService] Get client from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C,ou=clients,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-25 22:30:25,563 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C 2016-02-25 22:30:25,565 TRACE [org.xdi.oxauth.service.ClientService] Get client from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C,ou=clients,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-25 22:30:25,565 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C 2016-02-25 22:30:25,565 TRACE [org.xdi.oxauth.service.ClientService] Get client from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C,ou=clients,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-25 22:30:25,565 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C 2016-02-25 22:30:30,793 TRACE [org.xdi.oxauth.service.SessionStateService] Try to get session by id: 00415c40-6878-4306-9241-c1e5676c8273 ... 2016-02-25 22:30:30,793 TRACE [org.xdi.oxauth.service.SessionStateService] Session dn: uniqueIdentifier=00415c40-6878-4306-9241-c1e5676c8273,ou=session,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu 2016-02-25 22:30:30,794 TRACE [org.xdi.oxauth.service.ClientService] Get client from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C,ou=clients,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-25 22:30:30,794 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C 2016-02-25 22:30:30,801 TRACE [xdi.oxauth.authorize.ws.rs.AuthorizeAction] permissionGranted, redirectTo: seam/resource/restv1/oxauth/authorize?response_type=code&scope=openid&redirect_uri=https%3A%2F%2F192.168.1.7.xip.io%3A9443%2Fcallback&client_id=%40%21564F.8893.C2D4.207E%210001%21EFA3.3DDC%210008%21AEF9.8C8C 2016-02-25 22:30:31,287 TRACE [org.xdi.oxauth.service.SessionStateService] Found session_state cookie: '00415c40-6878-4306-9241-c1e5676c8273' 2016-02-25 22:30:31,289 TRACE [org.xdi.oxauth.service.SessionStateService] Try to get session by id: 00415c40-6878-4306-9241-c1e5676c8273 ... 2016-02-25 22:30:31,289 TRACE [org.xdi.oxauth.service.SessionStateService] Session dn: uniqueIdentifier=00415c40-6878-4306-9241-c1e5676c8273,ou=session,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu 2016-02-25 22:30:31,291 TRACE [org.xdi.oxauth.service.SessionStateService] Try to get session by id: 00415c40-6878-4306-9241-c1e5676c8273 ... 2016-02-25 22:30:31,291 TRACE [org.xdi.oxauth.service.SessionStateService] Session dn: uniqueIdentifier=00415c40-6878-4306-9241-c1e5676c8273,ou=session,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu 2016-02-25 22:30:31,292 TRACE [org.xdi.oxauth.auth.Authenticator] authenticateBySessionState, sessionState = '00415c40-6878-4306-9241-c1e5676c8273', session = 'SessionState, dn='uniqueIdentifier=00415c40-6878-4306-9241-c1e5676c8273,ou=session,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu', id='00415c40-6878-4306-9241-c1e5676c8273', lastUsedAt=Thu Feb 25 22:30:30 UTC 2016, userDn='inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0000!A8F2.DE1E.D7FB,ou=people,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu', authenticationTime=Thu Feb 25 22:30:25 UTC 2016, state=authenticated, permissionGranted=null, permissionGrantedMap=org.xdi.oxauth.model.common.SessionIdAccessMap@7b2bd3ee, sessionAttributes={scope=openid, response_type=code, redirect_uri=https://192.168.1.7.xip.io:9443/callback, auth_step=1, client_id=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C, acr=internal}, persisted=false}', state= 'authenticated' 2016-02-25 22:30:31,296 TRACE [org.xdi.oxauth.auth.AuthenticationFilter] Process Session Auth, sessionState = 00415c40-6878-4306-9241-c1e5676c8273, requireAuth = false 2016-02-25 22:30:31,297 DEBUG [xdi.oxauth.authorize.ws.rs.AuthorizeRestWebServiceImpl] Attempting to request authorization: responseType = code, clientId = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C, scope = openid, redirectUri = https://192.168.1.7.xip.io:9443/callback, nonce = null, state = null, request = null, isSecure = true, requestSessionState = null, sessionState = null 2016-02-25 22:30:31,297 DEBUG [xdi.oxauth.authorize.ws.rs.AuthorizeRestWebServiceImpl] Attempting to request authorization: acrValues = null, amrValues = null, originHeaders = {4} 2016-02-25 22:30:31,298 TRACE [org.xdi.oxauth.service.ClientService] Get client from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C,ou=clients,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-25 22:30:31,298 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C 2016-02-25 22:30:31,298 DEBUG [org.xdi.oxauth.model.authorize.ScopeChecker] Checking scopes policy for: openid 2016-02-25 22:30:31,299 DEBUG [org.xdi.oxauth.model.authorize.ScopeChecker] Granted scopes: [openid] 2016-02-25 22:30:31,299 TRACE [org.xdi.oxauth.service.ClientService] Get client from cache by Dn 'inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C,ou=clients,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu' 2016-02-25 22:30:31,299 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C 2016-02-25 22:30:31,299 DEBUG [org.xdi.oxauth.service.RedirectionUriService] Validating redirection URI: clientIdentifier = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C, redirectionUri = https://192.168.1.7.xip.io:9443/callback, found = 1 2016-02-25 22:30:31,299 DEBUG [org.xdi.oxauth.service.RedirectionUriService] Comparing https://192.168.1.7.xip.io:9443/callback == https://192.168.1.7.xip.io:9443/callback 2016-02-25 22:30:31,309 DEBUG [org.xdi.oxauth.model.authorize.ScopeChecker] Checking scopes policy for: openid 2016-02-25 22:30:31,310 DEBUG [org.xdi.oxauth.model.authorize.ScopeChecker] Granted scopes: [openid] 2016-02-25 22:30:32,091 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!AEF9.8C8C 2016-02-25 22:30:32,091 DEBUG [org.xdi.oxauth.model.error.ErrorResponseFactory] Looking for the error with id: invalid_client 2016-02-25 22:30:32,092 DEBUG [org.xdi.oxauth.model.error.ErrorResponseFactory] Found error, id: invalid_client 2016-02-25 22:32:47,462 DEBUG [org.xdi.oxauth.service.CleanerTimer] Start AuthorizationGrant clean up 2016-02-25 22:32:47,467 TRACE [org.xdi.oxauth.service.GrantService] Removed token, code: 89f0f823-0b46-4db6-b5eb-c8cdb7202f1b 2016-02-25 22:32:47,469 TRACE [org.xdi.oxauth.service.GrantService] Removed token, code: 49fffe59-0b1e-471d-92a2-75e2d77d3198 2016-02-25 22:32:47,469 DEBUG [org.xdi.oxauth.service.CleanerTimer] End AuthorizationGrant clean up 2016-02-25 22:32:47,469 DEBUG [org.xdi.oxauth.service.CleanerTimer] Start Client clean up 2016-02-25 22:32:47,476 DEBUG [org.xdi.oxauth.service.CleanerTimer] End Client clean up 2016-02-25 22:32:47,479 DEBUG [org.xdi.oxauth.service.CleanerTimer] Start U2F request clean up 2016-02-25 22:32:47,479 DEBUG [org.xdi.oxauth.service.CleanerTimer] End U2F request clean up 2016-02-25 22:32:47,479 DEBUG [org.xdi.oxauth.service.CleanerTimer] Start metric entries clean up 2016-02-25 22:32:47,494 DEBUG [org.xdi.oxauth.service.CleanerTimer] End metric entries clean up 2016-02-25 22:42:47,463 DEBUG [org.xdi.oxauth.service.CleanerTimer] Start AuthorizationGrant clean up 2016-02-25 22:42:47,464 DEBUG [org.xdi.oxauth.service.CleanerTimer] End AuthorizationGrant clean up 2016-02-25 22:42:47,464 DEBUG [org.xdi.oxauth.service.CleanerTimer] Start Client clean up 2016-02-25 22:42:47,472 DEBUG [org.xdi.oxauth.service.CleanerTimer] End Client clean up 2016-02-25 22:42:47,475 DEBUG [org.xdi.oxauth.service.CleanerTimer] Start U2F request clean up 2016-02-25 22:42:47,476 DEBUG [org.xdi.oxauth.service.CleanerTimer] End U2F request clean up 2016-02-25 22:42:47,476 DEBUG [org.xdi.oxauth.service.CleanerTimer] Start metric entries clean up 2016-02-25 22:42:47,497 DEBUG [org.xdi.oxauth.service.CleanerTimer] End metric entries clean up ```

By Amitava Shee user 26 Feb 2016 at 8 a.m. CST

Copy
Amitava Shee gravatar
Some more information - I have regenerated new client id's and removed everything at client except oauth2. The server side redirects back with Callback url ```bash https://idp.pype.tech//oxauth/seam/resource/restv1/oxauth/authorize?redirect_uri=https%3A%2F%2F192.168.1.7.xip.io%3A9443%2Fcode%2F&scope=openid&client_id=%40!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!ADFD.32B0 ``` Client app displays the following page ```json {"error":"invalid_request","error_description":"The request is missing a required parameter, includes an unsupported parameter or parameter value, or is otherwise malformed."} ``` And the server log has ```bash 2016-02-26 13:55:40,229 TRACE [org.xdi.oxauth.service.SessionStateService] Found session_state cookie: '304b29f8-31d0-4cd6-9e7e-96eb0d1c20db' 2016-02-26 13:55:40,232 TRACE [org.xdi.oxauth.service.SessionStateService] Try to get session by id: 304b29f8-31d0-4cd6-9e7e-96eb0d1c20db ... 2016-02-26 13:55:40,232 TRACE [org.xdi.oxauth.service.SessionStateService] Session dn: uniqueIdentifier=304b29f8-31d0-4cd6-9e7e-96eb0d1c20db,ou=session,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu 2016-02-26 13:55:40,234 TRACE [org.xdi.oxauth.service.SessionStateService] Try to get session by id: 304b29f8-31d0-4cd6-9e7e-96eb0d1c20db ... 2016-02-26 13:55:40,234 TRACE [org.xdi.oxauth.service.SessionStateService] Session dn: uniqueIdentifier=304b29f8-31d0-4cd6-9e7e-96eb0d1c20db,ou=session,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu 2016-02-26 13:55:40,235 TRACE [org.xdi.oxauth.auth.Authenticator] authenticateBySessionState, sessionState = '304b29f8-31d0-4cd6-9e7e-96eb0d1c20db', session = 'SessionState, dn='uniqueIdentifier=304b29f8-31d0-4cd6-9e7e-96eb0d1c20db,ou=session,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu', id='304b29f8-31d0-4cd6-9e7e-96eb0d1c20db', lastUsedAt=Fri Feb 26 13:50:30 UTC 2016, userDn='inum=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0000!A8F2.DE1E.D7FB,ou=people,o=@!564F.8893.C2D4.207E!0001!EFA3.3DDC,o=gluu', authenticationTime=Thu Feb 25 21:46:01 UTC 2016, state=authenticated, permissionGranted=null, permissionGrantedMap=org.xdi.oxauth.model.common.SessionIdAccessMap@601ca503, sessionAttributes={scope=openid profile email user_name, response_type=code id_token, nonce=nonce, redirect_uri=https://idp.pype.tech/identity/authentication/authcode, auth_step=1, client_id=@!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!51D5.6B35, acr=internal}, persisted=false}', state= 'authenticated' 2016-02-26 13:55:40,239 TRACE [org.xdi.oxauth.auth.AuthenticationFilter] Process Session Auth, sessionState = 304b29f8-31d0-4cd6-9e7e-96eb0d1c20db, requireAuth = false 2016-02-26 13:55:40,241 DEBUG [xdi.oxauth.authorize.ws.rs.AuthorizeRestWebServiceImpl] Attempting to request authorization: responseType = null, clientId = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!ADFD.32B0, scope = openid, redirectUri = https://192.168.1.7.xip.io:9443/code/, nonce = null, state = null, request = null, isSecure = true, requestSessionState = null, sessionState = null 2016-02-26 13:55:40,241 DEBUG [xdi.oxauth.authorize.ws.rs.AuthorizeRestWebServiceImpl] Attempting to request authorization: acrValues = null, amrValues = null, originHeaders = {4} 2016-02-26 13:55:40,243 DEBUG [org.xdi.oxauth.service.ClientService] Found 1 entries for client id = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!ADFD.32B0 2016-02-26 13:55:40,243 DEBUG [org.xdi.oxauth.service.RedirectionUriService] Validating redirection URI: clientIdentifier = @!564F.8893.C2D4.207E!0001!EFA3.3DDC!0008!ADFD.32B0, redirectionUri = https://192.168.1.7.xip.io:9443/code/, found = 1 2016-02-26 13:55:40,243 DEBUG [org.xdi.oxauth.service.RedirectionUriService] Comparing https://192.168.1.7.xip.io:8080/code/ == https://192.168.1.7.xip.io:9443/code/ 2016-02-26 13:55:40,243 DEBUG [org.xdi.oxauth.model.error.ErrorResponseFactory] Looking for the error with id: invalid_request 2016-02-26 13:55:40,244 DEBUG [org.xdi.oxauth.model.error.ErrorResponseFactory] Found error, id: invalid_request ``` Any ideas as to troubleshoot why the server reports invalid_request?

Post an answer