By: Minhyung Kim user 03 Nov 2020 at 4:10 a.m. CST

5 Responses
Minhyung Kim gravatar
## Test Case When we call the "/oxauth/restv1/token" endpoint 2 quick consecutive times (approx 0.5s between each call) using grant_type=password ## Expected Result access_token, scope, token_type, expires_in, id_token is returned both times ## Actual Result The second call does not contain an id_token.

By Yuriy Zabrovarnyy staff 03 Nov 2020 at 11 a.m. CST

Yuriy Zabrovarnyy gravatar
Do you have LDAP as persistence layer ? It would be nice if you can provide `oxauth.log` file in TRACE log level. It would make is clear whether we got this already reported bug or not: https://github.com/GluuFederation/oxAuth/issues/1481

By Sungho Park user 03 Nov 2020 at 8:53 p.m. CST

Sungho Park gravatar
There is no 500 error. The return value is http 200 OK. The id_token is missing in the returned json content. In Gluu 4.2 version, since id_token is not returned for "grant_type=password" method, I set "openidScopeBackwardCompatibility=true" in Configuration> JSON Configuration> OxAuth Configuration. In this case, if you call the "token endpoint" quickly, id_token may or may not be returned. id_token returned case { "access_token": "4324cb4d-9bbc-423d-b53a-ef6eb4903b0a", "scope": "openid", "id_token": "eyJraWQiOiI5YjgwM.......", "token_type": "bearer", "expires_in": 35999 } id_token not returned case { "access_token": "2c5ed773-9634-4488-8b62-ef883ba9b651", "scope": "openid", "token_type": "bearer", "expires_in": 35999 }

By Yuriy Zabrovarnyy staff 03 Nov 2020 at 11:29 p.m. CST

Yuriy Zabrovarnyy gravatar
Full `òxauth.log` file in TRACE log level is still welcome. Its not clear what is the reason. Re-assigning to Alex for reproducing.

By Sungho Park user 04 Nov 2020 at 10:44 a.m. CST

Sungho Park gravatar
If you run the "curl" command below several times in quick succession, you will see that the id_token is not returned. curl --location --request POST 'https://{hostname}/oxauth/restv1/token' --header 'Authorization: Basic ODNmZTBmYjQtNGRjMC00Y...' --header 'Content-Type: application/x-www-form-urlencoded' --data-urlencode 'grant_type=password' --data-urlencode 'username={id}' --data-urlencode 'password={pw}' --data-urlencode 'scope=openid offline_access'

By Sungho Park user 04 Nov 2020 at 8:26 p.m. CST

Sungho Park gravatar
In case of id_token missing , error logs 2020-11-05 02:24:23,641 ERROR [qtp1978869058-14] [org.gluu.oxauth.model.common.AuthorizationGrant] (AuthorizationGrant.java:300) - Failed to persist entry: tknCde=9b8dc90d8d63e3dc6652ecad49d56bb9ebb1ecde9c458cdc8d33fbf8b65ac64b,ou=tokens,o=gluu org.gluu.persist.exception.EntryPersistenceException: Failed to persist entry: tknCde=9b8dc90d8d63e3dc6652ecad49d56bb9ebb1ecde9c458cdc8d33fbf8b65ac64b,ou=tokens,o=gluu at org.gluu.persist.ldap.impl.LdapEntryManager.persist(LdapEntryManager.java:192) ~[oxcore-persistence-ldap-4.2.1.Final.jar:?] at org.gluu.persist.impl.BaseEntryManager.persist(BaseEntryManager.java:126) ~[oxcore-persistence-core-4.2.1.Final.jar:?] at jdk.internal.reflect.GeneratedMethodAccessor104.invoke(Unknown Source) ~[?:?] at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:?] at java.lang.reflect.Method.invoke(Unknown Source) ~[?:?] at org.jboss.weld.bean.proxy.AbstractBeanInstance.invoke(AbstractBeanInstance.java:38) ~[weld-core-impl-3.1.4.Final.jar:3.1.4.Final] at org.jboss.weld.bean.proxy.ProxyMethodHandler.invoke(ProxyMethodHandler.java:106) ~[weld-core-impl-3.1.4.Final.jar:3.1.4.Final] at org.gluu.persist.EntityManager$PersistenceEntryManager$1948487569$Proxy$_$$_WeldClientProxy.persist(Unknown Source) ~[weld-core-impl-3.1.4.Final.jar:?] at org.gluu.oxauth.service.GrantService.persist(GrantService.java:153) ~[classes/:?] at org.gluu.oxauth.model.common.AuthorizationGrant.persist(AuthorizationGrant.java:306) ~[classes/:?] at org.gluu.oxauth.model.common.AuthorizationGrant.createIdToken(AuthorizationGrant.java:290) ~[classes/:?] at org.gluu.oxauth.token.ws.rs.TokenRestWebServiceImpl.requestAccessToken(TokenRestWebServiceImpl.java:389) ~[classes/:?] at org.gluu.oxauth.token.ws.rs.TokenRestWebServiceImpl$Proxy$_$$_WeldClientProxy.requestAccessToken(Unknown Source) ~[classes/:?] at jdk.internal.reflect.GeneratedMethodAccessor209.invoke(Unknown Source) ~[?:?] at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:?] at java.lang.reflect.Method.invoke(Unknown Source) ~[?:?] at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:138) ~[resteasy-jaxrs-3.13.0.Final.jar:3.13.0.Final] at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:543) ~[resteasy-jaxrs-3.13.0.Final.jar:3.13.0.Final] at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:432) ~[resteasy-jaxrs-3.13.0.Final.jar:3.13.0.Final] at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$0(ResourceMethodInvoker.java:393) ~[resteasy-jaxrs-3.13.0.Final.jar:3.13.0.Final] at org.jboss.resteasy.core.interception.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:358) ~[resteasy-jaxrs-3.13.0.Final.jar:3.13.0.Final] at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:395) ~[resteasy-jaxrs-3.13.0.Final.jar:3.13.0.Final] at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:364) ~[resteasy-jaxrs-3.13.0.Final.jar:3.13.0.Final] at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:337) ~[resteasy-jaxrs-3.13.0.Final.jar:3.13.0.Final] at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:440) ~[resteasy-jaxrs-3.13.0.Final.jar:3.13.0.Final] at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:229) ~[resteasy-jaxrs-3.13.0.Final.jar:3.13.0.Final] at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:135) ~[resteasy-jaxrs-3.13.0.Final.jar:3.13.0.Final] at org.jboss.resteasy.core.interception.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:358) ~[resteasy-jaxrs-3.13.0.Final.jar:3.13.0.Final] at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:138) ~[resteasy-jaxrs-3.13.0.Final.jar:3.13.0.Final] at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:215) ~[resteasy-jaxrs-3.13.0.Final.jar:3.13.0.Final] at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:245) ~[resteasy-jaxrs-3.13.0.Final.jar:3.13.0.Final] at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:61) ~[resteasy-jaxrs-3.13.0.Final.jar:3.13.0.Final] at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56) ~[resteasy-jaxrs-3.13.0.Final.jar:3.13.0.Final] at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) ~[servlet-api-3.1.jar:3.1.0] at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:755) ~[jetty-servlet-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1617) ~[jetty-servlet-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter.doFilter(WebSocketUpgradeFilter.java:226) ~[websocket-server-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604) ~[jetty-servlet-9.4.26.v20200117.jar:9.4.26.v20200117] at org.gluu.oxauth.auth.AuthenticationFilter.processBasicAuth(AuthenticationFilter.java:339) ~[classes/:?] at org.gluu.oxauth.auth.AuthenticationFilter.doFilter(AuthenticationFilter.java:158) ~[classes/:?] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604) ~[jetty-servlet-9.4.26.v20200117.jar:9.4.26.v20200117] at org.gluu.server.filters.AbstractCorsFilter.handleNonCORS(AbstractCorsFilter.java:362) ~[oxcore-server-4.2.1.Final.jar:?] at org.gluu.server.filters.AbstractCorsFilter.doFilter(AbstractCorsFilter.java:139) ~[oxcore-server-4.2.1.Final.jar:?] at org.gluu.oxauth.filter.CorsFilter.doFilter(CorsFilter.java:118) ~[classes/:?] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1604) ~[jetty-servlet-9.4.26.v20200117.jar:9.4.26.v20200117] at org.gluu.oxauth.audit.debug.ServletLoggingFilter.doFilter(ServletLoggingFilter.java:67) ~[classes/:?] at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1596) ~[jetty-servlet-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:545) ~[jetty-servlet-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) ~[jetty-server-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:590) ~[jetty-security-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[jetty-server-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[jetty-server-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1607) ~[jetty-server-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[jetty-server-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1297) ~[jetty-server-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[jetty-server-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485) ~[jetty-servlet-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1577) ~[jetty-server-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[jetty-server-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1212) ~[jetty-server-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[jetty-server-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:221) ~[jetty-server-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146) ~[jetty-server-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[jetty-server-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.server.Server.handle(Server.java:500) ~[jetty-server-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383) ~[jetty-server-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:547) [jetty-server-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375) [jetty-server-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:270) [jetty-server-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [jetty-io-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) [jetty-io-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) [jetty-io-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) [jetty-util-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) [jetty-util-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) [jetty-util-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) [jetty-util-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:388) [jetty-util-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806) [jetty-util-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938) [jetty-util-9.4.26.v20200117.jar:9.4.26.v20200117] at java.lang.Thread.run(Unknown Source) [?:?] Caused by: org.gluu.persist.exception.operation.DuplicateEntryException: Entry already exists at org.gluu.persist.ldap.operation.impl.LdapOperationServiceImpl.addEntryImpl(LdapOperationServiceImpl.java:733) ~[oxcore-persistence-ldap-4.2.1.Final.jar:?] at org.gluu.persist.ldap.operation.impl.LdapOperationServiceImpl.addEntry(LdapOperationServiceImpl.java:712) ~[oxcore-persistence-ldap-4.2.1.Final.jar:?] at org.gluu.persist.ldap.impl.LdapEntryManager.persist(LdapEntryManager.java:185) ~[oxcore-persistence-ldap-4.2.1.Final.jar:?] ... 79 more 2020-11-05 02:24:31,654 DEBUG [qtp1978869058-19] [org.gluu.oxauth.service.common.UserService] (UserService.java:77) - Getting user information from LDAP: userId = null 2020-11-05 02:24:31,654 DEBUG [qtp1978869058-19] [org.gluu.oxauth.service.ClientService] (ClientService.java:135) - Found 1 entries for client id = 1501.5ca774fa-6f00-44e8-abbc-8578c6110258 2020-11-05 02:24:31,665 DEBUG [qtp1978869058-19] [org.gluu.oxauth.service.ClientService] (ClientService.java:135) - Found 1 entries for client id = 1502.b1b0a27a-7709-46ab-afe2-fbfae178c44a 2020-11-05 02:24:34,328 DEBUG [oxAuthScheduler_Worker-3] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:53) - Bound request started 2020-11-05 02:24:34,328 DEBUG [oxAuthScheduler_Worker-3] [org.gluu.service.timer.TimerJob] (TimerJob.java:36) - Fire timer event [org.gluu.service.cdi.event.LoggerUpdateEvent] with qualifiers [@org.gluu.service.cdi.event.Scheduled()] from instance 1488402405 2020-11-05 02:24:34,328 DEBUG [oxAuthScheduler_Worker-3] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:63) - Bound request ended 2020-11-05 02:24:34,358 INFO [ForkJoinPool.commonPool-worker-3] [org.gluu.service.logger.LoggerService] (LoggerService.java:165) - Updated log level of '130' loggers to DEBUG