During most SP-initiated authentication, users are redirected to our Gluu Server install to authenticate as we are the IDP and this flow happens without issue. Occasionally, a user will be sent to our login and after logging in they will receive the error "Oops. An unexpected error has occured at null". If they close this window and return to the SP to attempt authentication again they can complete authentication without a problem. Below is the log from oxauth.log you can see a failed attempt with the error starting with "Failed to get attributes from session" and "javax.faces.FacesException: Committed". Then one minute later when they reattempt, instead of logging "Failed to get attributes from session", we instead see "Redirect to person authentication login page: /auth/passport/passportlogin.xhtml" which then allows them to continue. Is there anything we can configure or modify so that users to not end up at this dead-end on the "/oxauth/error.html" page? Note that we do not have any custom scripts. The only modifications we have made are to brand the login and error pages with our own CSS. oxauth.log with private info redacted: ``` 2020-07-07 14:59:45,831 TRACE [Thread-335909] [org.gluu.oxauth.service.CleanerTimer] (CleanerTimer.java:137) - Starting conditions aren't reached 2020-07-07 14:59:45,841 DEBUG [oxAuthScheduler_Worker-3] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:53) - Bound request started 2020-07-07 14:59:45,841 DEBUG [oxAuthScheduler_Worker-3] [org.gluu.service.timer.TimerJob] (TimerJob.java:36) - Fire timer event [org.gluu.oxauth.service.cdi.event.AuthConfigurationEvent] with qualifiers [@org.gluu.service.cdi.event.Scheduled()] from instance 37041917 2020-07-07 14:59:45,842 DEBUG [oxAuthScheduler_Worker-3] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:63) - Bound request ended 2020-07-07 14:59:45,842 TRACE [Thread-335910] [org.gluu.oxauth.service.AppInitializer] (AppInitializer.java:277) - Attempting to use persistenceEntryManager: org.gluu.persist.ldap.operation.impl.LdapOperationsServiceImpl@4effab3b 2020-07-07 14:59:46,121 TRACE [qtp1590550415-16] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:304) - Found session_id cookie: '9982dcd8-<REDACTED>' 2020-07-07 14:59:46,121 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key '9982dcd8-<REDACTED>' 2020-07-07 14:59:46,122 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key '9982dcd8-<REDACTED>': 'null' 2020-07-07 14:59:46,123 TRACE [qtp1590550415-16] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:805) - Try to get session by id: 9982dcd8-<REDACTED> ... 2020-07-07 14:59:46,123 TRACE [qtp1590550415-16] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:817) - Failed to get session by id: 9982dcd8-<REDACTED> 2020-07-07 14:59:46,123 ERROR [qtp1590550415-16] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:634) - Failed to get attributes from session 2020-07-07 14:59:46,132 ERROR [qtp1590550415-16] [org.gluu.oxauth.exception.GlobalExceptionHandler] (GlobalExceptionHandler.java:50) - Committed javax.faces.FacesException: Committed at com.sun.faces.lifecycle.InvokeApplicationPhase.execute(InvokeApplicationPhase.java:90) ~[javax.faces-2.3.9.jar:2.3.9] at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:100) ~[javax.faces-2.3.9.jar:2.3.9] at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:201) ~[javax.faces-2.3.9.jar:2.3.9] at javax.faces.webapp.FacesServlet.service(FacesServlet.java:670) ~[javax.faces-2.3.9.jar:2.3.9] at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1395) ~[jetty-servlet-9.4.26.v20200117.jar:9.4.26.v20200117] 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.audit.debug.ServletLoggingFilter.doFilter(ServletLoggingFilter.java:84) ~[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(Thread.java:748) [?:1.8.0_222] Caused by: java.lang.IllegalStateException: Committed at org.eclipse.jetty.server.HttpChannel.resetBuffer(HttpChannel.java:908) ~[jetty-server-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.server.HttpOutput.resetBuffer(HttpOutput.java:1413) ~[?:?] at org.eclipse.jetty.server.Response.resetBuffer(Response.java:1132) ~[?:?] at org.eclipse.jetty.server.Response.sendRedirect(Response.java:496) ~[?:?] at org.eclipse.jetty.server.Response.sendRedirect(Response.java:505) ~[?:?] at com.sun.faces.context.ExternalContextImpl.redirect(ExternalContextImpl.java:827) ~[javax.faces-2.3.9.jar:2.3.9] at javax.faces.context.ExternalContextWrapper.redirect(ExternalContextWrapper.java:621) ~[javax.faces-2.3.9.jar:2.3.9] at com.sun.faces.application.NavigationHandlerImpl.handleNavigation(NavigationHandlerImpl.java:308) ~[javax.faces-2.3.9.jar:2.3.9] at com.sun.faces.application.NavigationHandlerImpl.handleNavigation(NavigationHandlerImpl.java:216) ~[javax.faces-2.3.9.jar:2.3.9] at com.sun.faces.application.ActionListenerImpl.processAction(ActionListenerImpl.java:132) ~[javax.faces-2.3.9.jar:2.3.9] at javax.faces.component.UIViewAction.broadcast(UIViewAction.java:587) ~[javax.faces-2.3.9.jar:2.3.9] at javax.faces.component.UIViewRoot.broadcastEvents(UIViewRoot.java:870) ~[javax.faces-2.3.9.jar:2.3.9] at javax.faces.component.UIViewRoot.processApplication(UIViewRoot.java:1418) ~[javax.faces-2.3.9.jar:2.3.9] at com.sun.faces.lifecycle.InvokeApplicationPhase.execute(InvokeApplicationPhase.java:82) ~[javax.faces-2.3.9.jar:2.3.9] ... 43 more 2020-07-07 14:59:46,136 ERROR [qtp1590550415-16] [org.gluu.oxauth.exception.GlobalExceptionHandler] (GlobalExceptionHandler.java:69) - Can't perform redirect to viewId: /error_service.htm java.lang.IllegalStateException: Committed at org.eclipse.jetty.server.HttpChannel.resetBuffer(HttpChannel.java:908) ~[jetty-server-9.4.26.v20200117.jar:9.4.26.v20200117] at org.eclipse.jetty.server.HttpOutput.resetBuffer(HttpOutput.java:1413) ~[?:?] at org.eclipse.jetty.server.Response.resetBuffer(Response.java:1132) ~[?:?] at org.eclipse.jetty.server.Response.sendRedirect(Response.java:496) ~[?:?] at org.eclipse.jetty.server.Response.sendRedirect(Response.java:505) ~[?:?] at com.sun.faces.context.ExternalContextImpl.redirect(ExternalContextImpl.java:827) ~[javax.faces-2.3.9.jar:2.3.9] at javax.faces.context.ExternalContextWrapper.redirect(ExternalContextWrapper.java:621) ~[javax.faces-2.3.9.jar:2.3.9] at org.gluu.oxauth.exception.GlobalExceptionHandler.performRedirect(GlobalExceptionHandler.java:67) ~[classes/:?] at org.gluu.oxauth.exception.GlobalExceptionHandler.handle(GlobalExceptionHandler.java:51) ~[classes/:?] at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:118) ~[javax.faces-2.3.9.jar:2.3.9] at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:201) ~[javax.faces-2.3.9.jar:2.3.9] at javax.faces.webapp.FacesServlet.service(FacesServlet.java:670) ~[javax.faces-2.3.9.jar:2.3.9] at org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1395) ~[jetty-servlet-9.4.26.v20200117.jar:9.4.26.v20200117] 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.audit.debug.ServletLoggingFilter.doFilter(ServletLoggingFilter.java:84) ~[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(Thread.java:748) [?:1.8.0_222] 2020-07-07 14:59:48,528 DEBUG [qtp1590550415-12] [org.gluu.service.ExternalResourceHandler] (ExternalResourceHandler.java:68) - Found overriden resource: /error.xhtml 2020-07-07 14:59:48,528 DEBUG [qtp1590550415-12] [org.gluu.service.ExternalResourceHandler] (ExternalResourceHandler.java:68) - Found overriden resource: /error.xhtml 2020-07-07 14:59:48,529 DEBUG [qtp1590550415-12] [org.gluu.service.ExternalResourceHandler] (ExternalResourceHandler.java:68) - Found overriden resource: /error.xhtml 2020-07-07 14:59:48,529 DEBUG [qtp1590550415-12] [org.gluu.service.ExternalResourceHandler] (ExternalResourceHandler.java:68) - Found overriden resource: /WEB-INF/incl/layout/login-extended-template.xhtml 2020-07-07 14:59:48,623 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'organization' 2020-07-07 14:59:48,623 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'organization': 'null' 2020-07-07 14:59:48,626 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'organization': 'Entry [dn=o=gluu]' 2020-07-07 14:59:50,735 DEBUG [oxAuthScheduler_Worker-2] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:53) - Bound request started 2020-07-07 14:59:50,736 DEBUG [oxAuthScheduler_Worker-2] [org.gluu.service.timer.TimerJob] (TimerJob.java:36) - Fire timer event [org.gluu.service.cdi.event.UpdateScriptEvent] with qualifiers [@org.gluu.service.cdi.event.Scheduled()] from instance 797976350 2020-07-07 14:59:50,756 DEBUG [oxAuthScheduler_Worker-2] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:63) - Bound request ended 2020-07-07 15:00:00,778 DEBUG [oxAuthScheduler_Worker-5] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:53) - Bound request started 2020-07-07 15:00:00,778 DEBUG [oxAuthScheduler_Worker-5] [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 2138691378 2020-07-07 15:00:00,778 DEBUG [oxAuthScheduler_Worker-5] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:63) - Bound request ended 2020-07-07 15:00:10,282 TRACE [qtp1590550415-12] [org.gluu.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:97) - Get request to: 'https://<REDACTED DOMAIN>/oxauth/restv1/authorize' 2020-07-07 15:00:10,283 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'inum=1101.f5968873-<REDACTED>,ou=clients,o=gluu' 2020-07-07 15:00:10,283 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'inum=1101.f5968873-<REDACTED>,ou=clients,o=gluu': 'null' 2020-07-07 15:00:10,283 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:62) - Key not in cache. Searching value via load function, key: 'inum=1101.f5968873-<REDACTED>,ou=clients,o=gluu' 2020-07-07 15:00:10,287 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'inum=1101.f5968873-<REDACTED>,ou=clients,o=gluu': 'DeletableEntity{expirationDate=null, deletable=true} BaseEntry [dn=null]' 2020-07-07 15:00:10,287 DEBUG [qtp1590550415-12] [org.gluu.oxauth.service.ClientService] (ClientService.java:136) - Found 1 entries for client id = 1101.f5968873-<REDACTED> 2020-07-07 15:00:10,288 TRACE [qtp1590550415-12] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:304) - Found session_id cookie: '9982dcd8-<REDACTED>' 2020-07-07 15:00:10,288 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key '9982dcd8-<REDACTED>' 2020-07-07 15:00:10,289 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key '9982dcd8-<REDACTED>': 'null' 2020-07-07 15:00:10,289 TRACE [qtp1590550415-12] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:805) - Try to get session by id: 9982dcd8-<REDACTED> ... 2020-07-07 15:00:10,290 TRACE [qtp1590550415-12] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:817) - Failed to get session by id: 9982dcd8-<REDACTED> 2020-07-07 15:00:10,290 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'inum=1101.f5968873-<REDACTED>,ou=clients,o=gluu' 2020-07-07 15:00:10,290 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'inum=1101.f5968873-<REDACTED>,ou=clients,o=gluu': 'DeletableEntity{expirationDate=null, deletable=true} BaseEntry [dn=null]' 2020-07-07 15:00:10,290 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:59) - Loaded from cache, key: 'inum=1101.f5968873-<REDACTED>,ou=clients,o=gluu' 2020-07-07 15:00:10,291 DEBUG [qtp1590550415-12] [org.gluu.oxauth.service.ClientService] (ClientService.java:136) - Found 1 entries for client id = 1101.f5968873-<REDACTED> 2020-07-07 15:00:10,292 DEBUG [qtp1590550415-12] [gluu.oxauth.authorize.ws.rs.AuthorizeRestWebServiceImpl] (AuthorizeRestWebServiceImpl.java:171) - Attempting to request authorization: responseType = code, clientId = 1101.f5968873-<REDACTED>, scope = openid email user_name, redirectUri = https://<REDACTED DOMAIN>/idp/Authn/oxAuth, nonce = U3omERH5n6, state = eyJ0eXAiOiJKV1QiLCJhbGciOiJub25lIn0.eyJzdGF0ZSI6InZDUXFXWWxFWDUiLCJjb252ZXJzYXRpb24iOiJlMnMxIn0., request = null, isSecure = true, requestSessionId = null, sessionId = null 2020-07-07 15:00:10,292 DEBUG [qtp1590550415-12] [gluu.oxauth.authorize.ws.rs.AuthorizeRestWebServiceImpl] (AuthorizeRestWebServiceImpl.java:177) - Attempting to request authorization: acrValues = urn:oasis:names:tc:SAML:2.0:ac:classes:Password, amrValues = null, originHeaders = null, codeChallenge = null, codeChallengeMethod = null, customRespHeaders = null, claims = null, tokenBindingHeader = null 2020-07-07 15:00:10,293 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'inum=1101.f5968873-<REDACTED>,ou=clients,o=gluu' 2020-07-07 15:00:10,293 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'inum=1101.f5968873-<REDACTED>,ou=clients,o=gluu': 'DeletableEntity{expirationDate=null, deletable=true} BaseEntry [dn=null]' 2020-07-07 15:00:10,294 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:59) - Loaded from cache, key: 'inum=1101.f5968873-<REDACTED>,ou=clients,o=gluu' 2020-07-07 15:00:10,294 DEBUG [qtp1590550415-12] [org.gluu.oxauth.service.ClientService] (ClientService.java:136) - Found 1 entries for client id = 1101.f5968873-<REDACTED> 2020-07-07 15:00:10,294 DEBUG [qtp1590550415-12] [org.gluu.oxauth.model.authorize.ScopeChecker] (ScopeChecker.java:39) - Checking scopes policy for: openid email user_name 2020-07-07 15:00:10,294 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'inum=F0C4,ou=scopes,o=gluu' 2020-07-07 15:00:10,295 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'inum=F0C4,ou=scopes,o=gluu': 'null' 2020-07-07 15:00:10,295 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:62) - Key not in cache. Searching value via load function, key: 'inum=F0C4,ou=scopes,o=gluu' 2020-07-07 15:00:10,299 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'inum=F0C4,ou=scopes,o=gluu': 'Scope{dn='inum=F0C4,ou=scopes,o=gluu', inum='F0C4', displayName='null', id='openid', iconUrl='null', description='Authenticate using OpenID Connect.', scopeType=openid, oxAuthClaims=null, defaultScope=true, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,299 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'openid': 'Scope{dn='inum=F0C4,ou=scopes,o=gluu', inum='F0C4', displayName='null', id='openid', iconUrl='null', description='Authenticate using OpenID Connect.', scopeType=openid, oxAuthClaims=null, defaultScope=true, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,299 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'inum=10B2,ou=scopes,o=gluu' 2020-07-07 15:00:10,300 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'inum=10B2,ou=scopes,o=gluu': 'null' 2020-07-07 15:00:10,300 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:62) - Key not in cache. Searching value via load function, key: 'inum=10B2,ou=scopes,o=gluu' 2020-07-07 15:00:10,304 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'inum=10B2,ou=scopes,o=gluu': 'Scope{dn='inum=10B2,ou=scopes,o=gluu', inum='10B2', displayName='null', id='user_name', iconUrl='null', description='View your local username in the Gluu Server.', scopeType=openid, oxAuthClaims=[inum=42E0,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,304 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'user_name': 'Scope{dn='inum=10B2,ou=scopes,o=gluu', inum='10B2', displayName='null', id='user_name', iconUrl='null', description='View your local username in the Gluu Server.', scopeType=openid, oxAuthClaims=[inum=42E0,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,304 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'inum=764C,ou=scopes,o=gluu' 2020-07-07 15:00:10,305 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'inum=764C,ou=scopes,o=gluu': 'null' 2020-07-07 15:00:10,305 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:62) - Key not in cache. Searching value via load function, key: 'inum=764C,ou=scopes,o=gluu' 2020-07-07 15:00:10,308 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'inum=764C,ou=scopes,o=gluu': 'Scope{dn='inum=764C,ou=scopes,o=gluu', inum='764C', displayName='null', id='email', iconUrl='null', description='View your email address.', scopeType=openid, oxAuthClaims=[inum=8F88,ou=attributes,o=gluu, inum=CAE3,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,309 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'email': 'Scope{dn='inum=764C,ou=scopes,o=gluu', inum='764C', displayName='null', id='email', iconUrl='null', description='View your email address.', scopeType=openid, oxAuthClaims=[inum=8F88,ou=attributes,o=gluu, inum=CAE3,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,309 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'inum=F0C4,ou=scopes,o=gluu' 2020-07-07 15:00:10,309 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'inum=F0C4,ou=scopes,o=gluu': 'Scope{dn='inum=F0C4,ou=scopes,o=gluu', inum='F0C4', displayName='null', id='openid', iconUrl='null', description='Authenticate using OpenID Connect.', scopeType=openid, oxAuthClaims=null, defaultScope=true, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,310 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:59) - Loaded from cache, key: 'inum=F0C4,ou=scopes,o=gluu' 2020-07-07 15:00:10,310 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'openid': 'Scope{dn='inum=F0C4,ou=scopes,o=gluu', inum='F0C4', displayName='null', id='openid', iconUrl='null', description='Authenticate using OpenID Connect.', scopeType=openid, oxAuthClaims=null, defaultScope=true, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,310 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'inum=10B2,ou=scopes,o=gluu' 2020-07-07 15:00:10,310 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'inum=10B2,ou=scopes,o=gluu': 'Scope{dn='inum=10B2,ou=scopes,o=gluu', inum='10B2', displayName='null', id='user_name', iconUrl='null', description='View your local username in the Gluu Server.', scopeType=openid, oxAuthClaims=[inum=42E0,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,311 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:59) - Loaded from cache, key: 'inum=10B2,ou=scopes,o=gluu' 2020-07-07 15:00:10,311 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'user_name': 'Scope{dn='inum=10B2,ou=scopes,o=gluu', inum='10B2', displayName='null', id='user_name', iconUrl='null', description='View your local username in the Gluu Server.', scopeType=openid, oxAuthClaims=[inum=42E0,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,311 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'inum=764C,ou=scopes,o=gluu' 2020-07-07 15:00:10,312 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'inum=764C,ou=scopes,o=gluu': 'Scope{dn='inum=764C,ou=scopes,o=gluu', inum='764C', displayName='null', id='email', iconUrl='null', description='View your email address.', scopeType=openid, oxAuthClaims=[inum=8F88,ou=attributes,o=gluu, inum=CAE3,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,312 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:59) - Loaded from cache, key: 'inum=764C,ou=scopes,o=gluu' 2020-07-07 15:00:10,312 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'email': 'Scope{dn='inum=764C,ou=scopes,o=gluu', inum='764C', displayName='null', id='email', iconUrl='null', description='View your email address.', scopeType=openid, oxAuthClaims=[inum=8F88,ou=attributes,o=gluu, inum=CAE3,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,313 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'inum=F0C4,ou=scopes,o=gluu' 2020-07-07 15:00:10,313 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'inum=F0C4,ou=scopes,o=gluu': 'Scope{dn='inum=F0C4,ou=scopes,o=gluu', inum='F0C4', displayName='null', id='openid', iconUrl='null', description='Authenticate using OpenID Connect.', scopeType=openid, oxAuthClaims=null, defaultScope=true, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,313 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:59) - Loaded from cache, key: 'inum=F0C4,ou=scopes,o=gluu' 2020-07-07 15:00:10,313 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'openid': 'Scope{dn='inum=F0C4,ou=scopes,o=gluu', inum='F0C4', displayName='null', id='openid', iconUrl='null', description='Authenticate using OpenID Connect.', scopeType=openid, oxAuthClaims=null, defaultScope=true, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,314 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'inum=10B2,ou=scopes,o=gluu' 2020-07-07 15:00:10,314 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'inum=10B2,ou=scopes,o=gluu': 'Scope{dn='inum=10B2,ou=scopes,o=gluu', inum='10B2', displayName='null', id='user_name', iconUrl='null', description='View your local username in the Gluu Server.', scopeType=openid, oxAuthClaims=[inum=42E0,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,314 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:59) - Loaded from cache, key: 'inum=10B2,ou=scopes,o=gluu' 2020-07-07 15:00:10,314 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'user_name': 'Scope{dn='inum=10B2,ou=scopes,o=gluu', inum='10B2', displayName='null', id='user_name', iconUrl='null', description='View your local username in the Gluu Server.', scopeType=openid, oxAuthClaims=[inum=42E0,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,315 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'inum=764C,ou=scopes,o=gluu' 2020-07-07 15:00:10,315 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'inum=764C,ou=scopes,o=gluu': 'Scope{dn='inum=764C,ou=scopes,o=gluu', inum='764C', displayName='null', id='email', iconUrl='null', description='View your email address.', scopeType=openid, oxAuthClaims=[inum=8F88,ou=attributes,o=gluu, inum=CAE3,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,315 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:59) - Loaded from cache, key: 'inum=764C,ou=scopes,o=gluu' 2020-07-07 15:00:10,315 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'email': 'Scope{dn='inum=764C,ou=scopes,o=gluu', inum='764C', displayName='null', id='email', iconUrl='null', description='View your email address.', scopeType=openid, oxAuthClaims=[inum=8F88,ou=attributes,o=gluu, inum=CAE3,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,316 DEBUG [qtp1590550415-12] [org.gluu.oxauth.model.authorize.ScopeChecker] (ScopeChecker.java:68) - Granted scopes: [openid, user_name, email] 2020-07-07 15:00:10,316 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'inum=1101.f5968873-<REDACTED>,ou=clients,o=gluu' 2020-07-07 15:00:10,316 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'inum=1101.f5968873-<REDACTED>,ou=clients,o=gluu': 'DeletableEntity{expirationDate=null, deletable=true} BaseEntry [dn=null]' 2020-07-07 15:00:10,316 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:59) - Loaded from cache, key: 'inum=1101.f5968873-<REDACTED>,ou=clients,o=gluu' 2020-07-07 15:00:10,316 DEBUG [qtp1590550415-12] [org.gluu.oxauth.service.ClientService] (ClientService.java:136) - Found 1 entries for client id = 1101.f5968873-<REDACTED> 2020-07-07 15:00:10,317 DEBUG [qtp1590550415-12] [org.gluu.oxauth.service.RedirectionUriService] (RedirectionUriService.java:77) - Validating redirection URI: clientIdentifier = 1101.f5968873-<REDACTED>, redirectionUri = https://<REDACTED DOMAIN>/idp/Authn/oxAuth, found = 1 2020-07-07 15:00:10,317 DEBUG [qtp1590550415-12] [org.gluu.oxauth.service.RedirectionUriService] (RedirectionUriService.java:83) - Comparing https://<REDACTED DOMAIN>/idp/Authn/oxAuth == https://<REDACTED DOMAIN>/idp/Authn/oxAuth 2020-07-07 15:00:10,329 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'inum=1101.f5968873-<REDACTED>,ou=clients,o=gluu' 2020-07-07 15:00:10,329 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'inum=1101.f5968873-<REDACTED>,ou=clients,o=gluu': 'DeletableEntity{expirationDate=null, deletable=true} BaseEntry [dn=null]' 2020-07-07 15:00:10,330 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:59) - Loaded from cache, key: 'inum=1101.f5968873-<REDACTED>,ou=clients,o=gluu' 2020-07-07 15:00:10,330 DEBUG [qtp1590550415-16] [org.gluu.oxauth.service.ClientService] (ClientService.java:136) - Found 1 entries for client id = 1101.f5968873-<REDACTED> 2020-07-07 15:00:10,330 DEBUG [qtp1590550415-16] [org.gluu.oxauth.model.authorize.ScopeChecker] (ScopeChecker.java:39) - Checking scopes policy for: openid email user_name 2020-07-07 15:00:10,330 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'inum=F0C4,ou=scopes,o=gluu' 2020-07-07 15:00:10,331 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'inum=F0C4,ou=scopes,o=gluu': 'Scope{dn='inum=F0C4,ou=scopes,o=gluu', inum='F0C4', displayName='null', id='openid', iconUrl='null', description='Authenticate using OpenID Connect.', scopeType=openid, oxAuthClaims=null, defaultScope=true, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,331 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:59) - Loaded from cache, key: 'inum=F0C4,ou=scopes,o=gluu' 2020-07-07 15:00:10,331 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'openid': 'Scope{dn='inum=F0C4,ou=scopes,o=gluu', inum='F0C4', displayName='null', id='openid', iconUrl='null', description='Authenticate using OpenID Connect.', scopeType=openid, oxAuthClaims=null, defaultScope=true, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,331 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'inum=10B2,ou=scopes,o=gluu' 2020-07-07 15:00:10,332 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'inum=10B2,ou=scopes,o=gluu': 'Scope{dn='inum=10B2,ou=scopes,o=gluu', inum='10B2', displayName='null', id='user_name', iconUrl='null', description='View your local username in the Gluu Server.', scopeType=openid, oxAuthClaims=[inum=42E0,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,332 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:59) - Loaded from cache, key: 'inum=10B2,ou=scopes,o=gluu' 2020-07-07 15:00:10,332 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'user_name': 'Scope{dn='inum=10B2,ou=scopes,o=gluu', inum='10B2', displayName='null', id='user_name', iconUrl='null', description='View your local username in the Gluu Server.', scopeType=openid, oxAuthClaims=[inum=42E0,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,332 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'inum=764C,ou=scopes,o=gluu' 2020-07-07 15:00:10,332 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'inum=764C,ou=scopes,o=gluu': 'Scope{dn='inum=764C,ou=scopes,o=gluu', inum='764C', displayName='null', id='email', iconUrl='null', description='View your email address.', scopeType=openid, oxAuthClaims=[inum=8F88,ou=attributes,o=gluu, inum=CAE3,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,333 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:59) - Loaded from cache, key: 'inum=764C,ou=scopes,o=gluu' 2020-07-07 15:00:10,333 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'email': 'Scope{dn='inum=764C,ou=scopes,o=gluu', inum='764C', displayName='null', id='email', iconUrl='null', description='View your email address.', scopeType=openid, oxAuthClaims=[inum=8F88,ou=attributes,o=gluu, inum=CAE3,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,333 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'inum=F0C4,ou=scopes,o=gluu' 2020-07-07 15:00:10,333 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'inum=F0C4,ou=scopes,o=gluu': 'Scope{dn='inum=F0C4,ou=scopes,o=gluu', inum='F0C4', displayName='null', id='openid', iconUrl='null', description='Authenticate using OpenID Connect.', scopeType=openid, oxAuthClaims=null, defaultScope=true, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,333 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:59) - Loaded from cache, key: 'inum=F0C4,ou=scopes,o=gluu' 2020-07-07 15:00:10,333 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'openid': 'Scope{dn='inum=F0C4,ou=scopes,o=gluu', inum='F0C4', displayName='null', id='openid', iconUrl='null', description='Authenticate using OpenID Connect.', scopeType=openid, oxAuthClaims=null, defaultScope=true, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,334 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'inum=10B2,ou=scopes,o=gluu' 2020-07-07 15:00:10,334 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'inum=10B2,ou=scopes,o=gluu': 'Scope{dn='inum=10B2,ou=scopes,o=gluu', inum='10B2', displayName='null', id='user_name', iconUrl='null', description='View your local username in the Gluu Server.', scopeType=openid, oxAuthClaims=[inum=42E0,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,334 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:59) - Loaded from cache, key: 'inum=10B2,ou=scopes,o=gluu' 2020-07-07 15:00:10,334 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'user_name': 'Scope{dn='inum=10B2,ou=scopes,o=gluu', inum='10B2', displayName='null', id='user_name', iconUrl='null', description='View your local username in the Gluu Server.', scopeType=openid, oxAuthClaims=[inum=42E0,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,334 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'inum=764C,ou=scopes,o=gluu' 2020-07-07 15:00:10,334 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'inum=764C,ou=scopes,o=gluu': 'Scope{dn='inum=764C,ou=scopes,o=gluu', inum='764C', displayName='null', id='email', iconUrl='null', description='View your email address.', scopeType=openid, oxAuthClaims=[inum=8F88,ou=attributes,o=gluu, inum=CAE3,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,335 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:59) - Loaded from cache, key: 'inum=764C,ou=scopes,o=gluu' 2020-07-07 15:00:10,335 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'email': 'Scope{dn='inum=764C,ou=scopes,o=gluu', inum='764C', displayName='null', id='email', iconUrl='null', description='View your email address.', scopeType=openid, oxAuthClaims=[inum=8F88,ou=attributes,o=gluu, inum=CAE3,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,335 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'inum=F0C4,ou=scopes,o=gluu' 2020-07-07 15:00:10,335 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'inum=F0C4,ou=scopes,o=gluu': 'Scope{dn='inum=F0C4,ou=scopes,o=gluu', inum='F0C4', displayName='null', id='openid', iconUrl='null', description='Authenticate using OpenID Connect.', scopeType=openid, oxAuthClaims=null, defaultScope=true, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,335 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:59) - Loaded from cache, key: 'inum=F0C4,ou=scopes,o=gluu' 2020-07-07 15:00:10,335 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'openid': 'Scope{dn='inum=F0C4,ou=scopes,o=gluu', inum='F0C4', displayName='null', id='openid', iconUrl='null', description='Authenticate using OpenID Connect.', scopeType=openid, oxAuthClaims=null, defaultScope=true, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,336 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'inum=10B2,ou=scopes,o=gluu' 2020-07-07 15:00:10,336 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'inum=10B2,ou=scopes,o=gluu': 'Scope{dn='inum=10B2,ou=scopes,o=gluu', inum='10B2', displayName='null', id='user_name', iconUrl='null', description='View your local username in the Gluu Server.', scopeType=openid, oxAuthClaims=[inum=42E0,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,336 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:59) - Loaded from cache, key: 'inum=10B2,ou=scopes,o=gluu' 2020-07-07 15:00:10,336 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'user_name': 'Scope{dn='inum=10B2,ou=scopes,o=gluu', inum='10B2', displayName='null', id='user_name', iconUrl='null', description='View your local username in the Gluu Server.', scopeType=openid, oxAuthClaims=[inum=42E0,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,336 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'inum=764C,ou=scopes,o=gluu' 2020-07-07 15:00:10,336 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'inum=764C,ou=scopes,o=gluu': 'Scope{dn='inum=764C,ou=scopes,o=gluu', inum='764C', displayName='null', id='email', iconUrl='null', description='View your email address.', scopeType=openid, oxAuthClaims=[inum=8F88,ou=attributes,o=gluu, inum=CAE3,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,336 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:59) - Loaded from cache, key: 'inum=764C,ou=scopes,o=gluu' 2020-07-07 15:00:10,337 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'email': 'Scope{dn='inum=764C,ou=scopes,o=gluu', inum='764C', displayName='null', id='email', iconUrl='null', description='View your email address.', scopeType=openid, oxAuthClaims=[inum=8F88,ou=attributes,o=gluu, inum=CAE3,ou=attributes,o=gluu], defaultScope=false, oxAuthGroupClaims=null, dynamicScopeScripts=null, umaAuthorizationPolicies=null}' 2020-07-07 15:00:10,337 DEBUG [qtp1590550415-16] [org.gluu.oxauth.model.authorize.ScopeChecker] (ScopeChecker.java:68) - Granted scopes: [openid, user_name, email] 2020-07-07 15:00:10,337 TRACE [qtp1590550415-16] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:304) - Found session_id cookie: '9982dcd8-<REDACTED>' 2020-07-07 15:00:10,338 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key '9982dcd8-<REDACTED>' 2020-07-07 15:00:10,339 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key '9982dcd8-<REDACTED>': 'null' 2020-07-07 15:00:10,339 TRACE [qtp1590550415-16] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:805) - Try to get session by id: 9982dcd8-<REDACTED> ... 2020-07-07 15:00:10,339 TRACE [qtp1590550415-16] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:817) - Failed to get session by id: 9982dcd8-<REDACTED> 2020-07-07 15:00:10,340 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key '9982dcd8-<REDACTED>' 2020-07-07 15:00:10,341 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key '9982dcd8-<REDACTED>': 'null' 2020-07-07 15:00:10,341 TRACE [qtp1590550415-16] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:805) - Try to get session by id: 9982dcd8-<REDACTED> ... 2020-07-07 15:00:10,341 TRACE [qtp1590550415-16] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:817) - Failed to get session by id: 9982dcd8-<REDACTED> 2020-07-07 15:00:10,343 TRACE [qtp1590550415-16] [gluu.oxauth.authorize.ws.rs.AuthorizeAction] (AuthorizeAction.java:263) - Redirect to person authentication login page: /auth/passport/passportlogin.xhtml 2020-07-07 15:00:10,343 TRACE [qtp1590550415-16] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:601) - Generated new session, id = 'fc5da627-f1ed-4fbb-9116-b68a07fbecc0', state = 'unauthenticated', asJwt = 'false', persisted = 'false' 2020-07-07 15:00:10,343 TRACE [qtp1590550415-16] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:670) - sessionIdAttributes: SessionIdAccessMap{permissionGranted={1101.f5968873-<REDACTED>=false}} 2020-07-07 15:00:10,343 TRACE [qtp1590550415-16] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'fc5da627-f1ed-4fbb-9116-b68a07fbecc0': 'SessionId {dn='fc5da627-f1ed-4fbb-9116-b68a07fbecc0', id='fc5da627-f1ed-4fbb-9116-b68a07fbecc0', lastUsedAt=Tue Jul 07 15:00:10 UTC 2020, userDn='', authenticationTime=Tue Jul 07 15:00:10 UTC 2020, state=unauthenticated, sessionState='59816092655fe6a40442d1810750c61a358463792b5efd771fd955e18df1c188.117d4c35-c088-433b-abc2-0d7bb74bd811', permissionGranted=null, isJwt=false, jwt=null, permissionGrantedMap=SessionIdAccessMap{permissionGranted={1101.f5968873-<REDACTED>=false}}, involvedClients=null, sessionAttributes={auth_step=1, acr=passport_saml, remote_ip=<REDACTED IP ADDRESS>, opbs=e7a3b403-d167-48e1-9451-f9b35312d4d2, scope=openid email user_name, acr_values=urn:oasis:names:tc:SAML:2.0:ac:classes:Password, response_type=code, redirect_uri=https://<REDACTED DOMAIN>/idp/Authn/oxAuth, state=eyJ0eXAiOiJKV1QiLCJhbGciOiJub25lIn0.eyJzdGF0ZSI6InZDUXFXWWxFWDUiLCJjb252ZXJzYXRpb24iOiJlMnMxIn0., nonce=U3omERH5n6, client_id=1101.f5968873-<REDACTED>}, persisted=true}' 2020-07-07 15:00:10,348 TRACE [qtp1590550415-16] [gluu.oxauth.authorize.ws.rs.AuthorizeAction] (AuthorizeAction.java:287) - Session 'fc5da627-f1ed-4fbb-9116-b68a07fbecc0' persisted to LDAP 2020-07-07 15:00:10,357 TRACE [qtp1590550415-12] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:304) - Found session_id cookie: 'fc5da627-f1ed-4fbb-9116-b68a07fbecc0' 2020-07-07 15:00:10,358 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:38) - Request data, key 'fc5da627-f1ed-4fbb-9116-b68a07fbecc0' 2020-07-07 15:00:10,360 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:40) - Loaded data, key 'fc5da627-f1ed-4fbb-9116-b68a07fbecc0': 'SessionId {dn='fc5da627-f1ed-4fbb-9116-b68a07fbecc0', id='fc5da627-f1ed-4fbb-9116-b68a07fbecc0', lastUsedAt=Tue Jul 07 15:00:10 UTC 2020, userDn='', authenticationTime=Tue Jul 07 15:00:10 UTC 2020, state=unauthenticated, sessionState='59816092655fe6a40442d1810750c61a358463792b5efd771fd955e18df1c188.117d4c35-c088-433b-abc2-0d7bb74bd811', permissionGranted=null, isJwt=false, jwt=null, permissionGrantedMap=SessionIdAccessMap{permissionGranted={1101.f5968873-<REDACTED>=false}}, involvedClients=null, sessionAttributes={auth_step=1, acr=passport_saml, remote_ip=<REDACTED IP ADDRESS>, opbs=e7a3b403-d167-48e1-9451-f9b35312d4d2, scope=openid email user_name, acr_values=urn:oasis:names:tc:SAML:2.0:ac:classes:Password, response_type=code, redirect_uri=https://<REDACTED DOMAIN>/idp/Authn/oxAuth, state=eyJ0eXAiOiJKV1QiLCJhbGciOiJub25lIn0.eyJzdGF0ZSI6InZDUXFXWWxFWDUiLCJjb252ZXJzYXRpb24iOiJlMnMxIn0., nonce=U3omERH5n6, client_id=1101.f5968873-<REDACTED>}, persisted=false}' 2020-07-07 15:00:10,361 TRACE [qtp1590550415-12] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:805) - Try to get session by id: fc5da627-f1ed-4fbb-9116-b68a07fbecc0 ... 2020-07-07 15:00:10,361 TRACE [qtp1590550415-12] [org.gluu.oxauth.service.SessionIdService] (SessionIdService.java:807) - Session dn: fc5da627-f1ed-4fbb-9116-b68a07fbecc0 2020-07-07 15:00:10,365 TRACE [qtp1590550415-12] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:540) - Attempting to store extraParameters: [selectedProvider, externalProviders] 2020-07-07 15:00:10,365 TRACE [qtp1590550415-12] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:559) - Storing sessionIdAttributes: {auth_external_attributes=[{"externalProviders":"java.lang.String"}], opbs=e7a3b403-d167-48e1-9451-f9b35312d4d2, externalProviders={}, response_type=code, nonce=U3omERH5n6, client_id=1101.f5968873-<REDACTED>, auth_step=1, acr=passport_saml, remote_ip=<REDACTED IP ADDRESS>, scope=openid email user_name, acr_values=urn:oasis:names:tc:SAML:2.0:ac:classes:Password, redirect_uri=https://<REDACTED DOMAIN>/idp/Authn/oxAuth, state=eyJ0eXAiOiJKV1QiLCJhbGciOiJub25lIn0.eyJzdGF0ZSI6InZDUXFXWWxFWDUiLCJjb252ZXJzYXRpb24iOiJlMnMxIn0.} 2020-07-07 15:00:10,366 TRACE [qtp1590550415-12] [org.gluu.oxauth.auth.Authenticator] (Authenticator.java:560) - Storing authExternalAttributes: {externalProviders=java.lang.String} 2020-07-07 15:00:10,366 TRACE [qtp1590550415-12] [org.gluu.service.BaseCacheService] (BaseCacheService.java:85) - Put data, key 'fc5da627-f1ed-4fbb-9116-b68a07fbecc0': 'SessionId {dn='fc5da627-f1ed-4fbb-9116-b68a07fbecc0', id='fc5da627-f1ed-4fbb-9116-b68a07fbecc0', lastUsedAt=Tue Jul 07 15:00:10 UTC 2020, userDn='', authenticationTime=Tue Jul 07 15:00:10 UTC 2020, state=unauthenticated, sessionState='59816092655fe6a40442d1810750c61a358463792b5efd771fd955e18df1c188.117d4c35-c088-433b-abc2-0d7bb74bd811', permissionGranted=null, isJwt=false, jwt=null, permissionGrantedMap=SessionIdAccessMap{permissionGranted={1101.f5968873-<REDACTED>=false}}, involvedClients=null, sessionAttributes={auth_external_attributes=[{"externalProviders":"java.lang.String"}], opbs=e7a3b403-d167-48e1-9451-f9b35312d4d2, externalProviders={}, response_type=code, nonce=U3omERH5n6, client_id=1101.f5968873-<REDACTED>, auth_step=1, acr=passport_saml, remote_ip=<REDACTED IP ADDRESS>, scope=openid email user_name, acr_values=urn:oasis:names:tc:SAML:2.0:ac:classes:Password, redirect_uri=https://<REDACTED DOMAIN>/idp/Authn/oxAuth, state=eyJ0eXAiOiJKV1QiLCJhbGciOiJub25lIn0.eyJzdGF0ZSI6InZDUXFXWWxFWDUiLCJjb252ZXJzYXRpb24iOiJlMnMxIn0.}, persisted=true}' 2020-07-07 15:00:10,376 DEBUG [qtp1590550415-12] [org.gluu.service.ExternalResourceHandler] (ExternalResourceHandler.java:68) - Found overriden resource: /WEB-INF/incl/layout/login-extended-template.xhtml 2020-07-07 15:00:15,771 DEBUG [oxAuthScheduler_Worker-1] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:53) - Bound request started 2020-07-07 15:00:15,771 DEBUG [oxAuthScheduler_Worker-1] [org.gluu.service.timer.TimerJob] (TimerJob.java:36) - Fire timer event [org.gluu.service.cdi.event.ConfigurationEvent] with qualifiers [@org.gluu.service.cdi.event.Scheduled()] from instance 1947042347 2020-07-07 15:00:15,771 DEBUG [oxAuthScheduler_Worker-1] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:63) - Bound request ended 2020-07-07 15:00:15,774 TRACE [Thread-335914] [org.gluu.oxauth.model.config.ConfigurationFactory] (ConfigurationFactory.java:264) - LDAP revision: 15, server revision:15 2020-07-07 15:00:15,777 DEBUG [oxAuthScheduler_Worker-4] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:53) - Bound request started 2020-07-07 15:00:15,777 DEBUG [oxAuthScheduler_Worker-4] [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 1301640783 2020-07-07 15:00:15,778 DEBUG [oxAuthScheduler_Worker-4] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:63) - Bound request ended 2020-07-07 15:00:15,793 DEBUG [oxAuthScheduler_Worker-3] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:53) - Bound request started 2020-07-07 15:00:15,793 DEBUG [oxAuthScheduler_Worker-3] [org.gluu.service.timer.TimerJob] (TimerJob.java:36) - Fire timer event [org.gluu.service.cdi.event.LdapStatusEvent] with qualifiers [@org.gluu.service.cdi.event.Scheduled()] from instance 1813528404 2020-07-07 15:00:15,794 DEBUG [oxAuthScheduler_Worker-3] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:63) - Bound request ended 2020-07-07 15:00:15,830 DEBUG [oxAuthScheduler_Worker-2] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:53) - Bound request started 2020-07-07 15:00:15,831 DEBUG [oxAuthScheduler_Worker-2] [org.gluu.service.timer.TimerJob] (TimerJob.java:36) - Fire timer event [org.gluu.service.cdi.event.CleanerEvent] with qualifiers [@org.gluu.service.cdi.event.Scheduled()] from instance 1561493392 2020-07-07 15:00:15,831 DEBUG [oxAuthScheduler_Worker-2] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:63) - Bound request ended 2020-07-07 15:00:15,831 DEBUG [Thread-335917] [org.gluu.oxauth.service.CleanerTimer] (CleanerTimer.java:189) - Built-in base dns: [ou=registered_devices,ou=u2f,o=gluu, ou=statistic,o=metric, ou=tokens,o=gluu, ou=clients,o=gluu, ou=pct,ou=uma,o=gluu, ou=resources,ou=uma,o=gluu, ou=people,o=gluu, ou=authorizations,o=gluu, ou=registration_requests,ou=u2f,o=gluu] 2020-07-07 15:00:15,831 DEBUG [Thread-335917] [org.gluu.oxauth.service.CleanerTimer] (CleanerTimer.java:153) - Start clean up for baseDn: ou=registered_devices,ou=u2f,o=gluu 2020-07-07 15:00:15,833 DEBUG [Thread-335917] [org.gluu.oxauth.service.CleanerTimer] (CleanerTimer.java:158) - Finished clean up for baseDn: ou=registered_devices,ou=u2f,o=gluu, takes: 1ms, removed items: 0 2020-07-07 15:00:15,833 DEBUG [Thread-335917] [org.gluu.oxauth.service.CleanerTimer] (CleanerTimer.java:153) - Start clean up for baseDn: ou=statistic,o=metric 2020-07-07 15:00:15,834 DEBUG [Thread-335917] [org.gluu.oxauth.service.CleanerTimer] (CleanerTimer.java:158) - Finished clean up for baseDn: ou=statistic,o=metric, takes: 1ms, removed items: 0 2020-07-07 15:00:15,834 DEBUG [Thread-335917] [org.gluu.oxauth.service.CleanerTimer] (CleanerTimer.java:153) - Start clean up for baseDn: ou=tokens,o=gluu 2020-07-07 15:00:15,835 DEBUG [Thread-335917] [org.gluu.oxauth.service.CleanerTimer] (CleanerTimer.java:158) - Finished clean up for baseDn: ou=tokens,o=gluu, takes: 0ms, removed items: 0 2020-07-07 15:00:15,835 DEBUG [Thread-335917] [org.gluu.oxauth.service.CleanerTimer] (CleanerTimer.java:153) - Start clean up for baseDn: ou=clients,o=gluu 2020-07-07 15:00:15,836 DEBUG [Thread-335917] [org.gluu.oxauth.service.CleanerTimer] (CleanerTimer.java:158) - Finished clean up for baseDn: ou=clients,o=gluu, takes: 0ms, removed items: 0 2020-07-07 15:00:15,836 DEBUG [Thread-335917] [org.gluu.oxauth.service.CleanerTimer] (CleanerTimer.java:153) - Start clean up for baseDn: ou=pct,ou=uma,o=gluu 2020-07-07 15:00:15,837 DEBUG [Thread-335917] [org.gluu.oxauth.service.CleanerTimer] (CleanerTimer.java:158) - Finished clean up for baseDn: ou=pct,ou=uma,o=gluu, takes: 0ms, removed items: 0 2020-07-07 15:00:15,837 DEBUG [Thread-335917] [org.gluu.oxauth.service.CleanerTimer] (CleanerTimer.java:153) - Start clean up for baseDn: ou=resources,ou=uma,o=gluu 2020-07-07 15:00:15,838 DEBUG [Thread-335917] [org.gluu.oxauth.service.CleanerTimer] (CleanerTimer.java:158) - Finished clean up for baseDn: ou=resources,ou=uma,o=gluu, takes: 0ms, removed items: 0 2020-07-07 15:00:15,838 DEBUG [Thread-335917] [org.gluu.oxauth.service.CleanerTimer] (CleanerTimer.java:153) - Start clean up for baseDn: ou=people,o=gluu 2020-07-07 15:00:15,838 DEBUG [Thread-335917] [org.gluu.oxauth.service.CleanerTimer] (CleanerTimer.java:158) - Finished clean up for baseDn: ou=people,o=gluu, takes: 0ms, removed items: 0 2020-07-07 15:00:15,838 DEBUG [Thread-335917] [org.gluu.oxauth.service.CleanerTimer] (CleanerTimer.java:153) - Start clean up for baseDn: ou=authorizations,o=gluu 2020-07-07 15:00:15,839 DEBUG [Thread-335917] [org.gluu.oxauth.service.CleanerTimer] (CleanerTimer.java:158) - Finished clean up for baseDn: ou=authorizations,o=gluu, takes: 0ms, removed items: 0 2020-07-07 15:00:15,839 DEBUG [Thread-335917] [org.gluu.oxauth.service.CleanerTimer] (CleanerTimer.java:153) - Start clean up for baseDn: ou=registration_requests,ou=u2f,o=gluu 2020-07-07 15:00:15,840 DEBUG [Thread-335917] [org.gluu.oxauth.service.CleanerTimer] (CleanerTimer.java:158) - Finished clean up for baseDn: ou=registration_requests,ou=u2f,o=gluu, takes: 0ms, removed items: 0 2020-07-07 15:00:15,840 DEBUG [Thread-335917] [org.gluu.service.cache.NativePersistenceCacheProvider] (NativePersistenceCacheProvider.java:253) - Start NATIVE_PERSISTENCE clean up 2020-07-07 15:00:15,842 DEBUG [oxAuthScheduler_Worker-5] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:53) - Bound request started 2020-07-07 15:00:15,842 DEBUG [oxAuthScheduler_Worker-5] [org.gluu.service.timer.TimerJob] (TimerJob.java:36) - Fire timer event [org.gluu.oxauth.service.cdi.event.AuthConfigurationEvent] with qualifiers [@org.gluu.service.cdi.event.Scheduled()] from instance 1475876814 2020-07-07 15:00:15,842 DEBUG [oxAuthScheduler_Worker-1] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:53) - Bound request started 2020-07-07 15:00:15,842 DEBUG [oxAuthScheduler_Worker-1] [org.gluu.service.timer.TimerJob] (TimerJob.java:36) - Fire timer event [org.gluu.oxauth.service.cdi.event.KeyGenerationEvent] with qualifiers [@org.gluu.service.cdi.event.Scheduled()] from instance 1936666472 2020-07-07 15:00:15,843 DEBUG [oxAuthScheduler_Worker-5] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:63) - Bound request ended 2020-07-07 15:00:15,843 TRACE [Thread-335918] [org.gluu.oxauth.service.AppInitializer] (AppInitializer.java:277) - Attempting to use persistenceEntryManager: org.gluu.persist.ldap.operation.impl.LdapOperationsServiceImpl@4effab3b 2020-07-07 15:00:15,844 DEBUG [oxAuthScheduler_Worker-1] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:63) - Bound request ended 2020-07-07 15:00:15,844 DEBUG [Thread-335917] [org.gluu.service.cache.NativePersistenceCacheProvider] (NativePersistenceCacheProvider.java:260) - End NATIVE_PERSISTENCE clean up, items removed: 2 2020-07-07 15:00:20,735 DEBUG [oxAuthScheduler_Worker-4] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:53) - Bound request started 2020-07-07 15:00:20,736 DEBUG [oxAuthScheduler_Worker-4] [org.gluu.service.timer.TimerJob] (TimerJob.java:36) - Fire timer event [org.gluu.service.cdi.event.UpdateScriptEvent] with qualifiers [@org.gluu.service.cdi.event.Scheduled()] from instance 682577581 2020-07-07 15:00:20,779 DEBUG [oxAuthScheduler_Worker-4] [org.gluu.service.timer.RequestJobListener] (RequestJobListener.java:63) - Bound request ended ```