search

klinux / gocd-keycloak-oauth-authorization-plugin

GoCD keycloak authorization plugin
Apache License 2.0
2 stars 5 forks source link

Unable to re-authenticate user after timeout after session timeout #3

Open marcogreiveldinger opened 1 year ago

marcogreiveldinger commented 1 year ago

Hi there, I have the plugin configured to use keycloak as IDP. Now after the max. session timeout I am getting the error at the frontend: Unable to re-authenticate user after timeout. Smilar to issue #1 I also increased the Access Token Lifespan but this just mitigates the problem to a later point in time...

The first line on the logs bothers me a bit.. failed with error ''. It shows an empty error. Do you have any idea, how to find out what the problem could be? I have the Keycloak as a working IDP for examples also configured in my grafana instance and the userinfo endpoint works perfectly.

I am using GoCD 20.3.0 and the latest plugin version available.

The following can be found in the logs:

jvm 1 | 2023-02-17 09:10:38,798 ERROR [qtp711437486-34] p.c.g.a.k.c.g.a.k.KeycloakPlugin:127 [plugin-cd.go.authorization.keycloak] - Error while executing request go.cd.authorization.authenticate-user
    2023-02-17T09:10:38.806+01:00   jvm 1 | java.lang.RuntimeException: Api call to `/auth/realms/myTeam/protocol/openid-connect/userinfo` failed with error: ``
    2023-02-17T09:10:38.806+01:00   jvm 1 | at cd.go.authorization.keycloak.KeycloakApiClient.executeRequest(KeycloakApiClient.java:148)
    2023-02-17T09:10:38.806+01:00   jvm 1 | at cd.go.authorization.keycloak.KeycloakApiClient.userProfile(KeycloakApiClient.java:135)
    2023-02-17T09:10:38.806+01:00   jvm 1 | at cd.go.authorization.keycloak.executors.UserAuthenticationRequestExecutor.execute(UserAuthenticationRequestExecutor.java:59)
    2023-02-17T09:10:38.806+01:00   jvm 1 | at cd.go.authorization.keycloak.requests.Request.execute(Request.java:47)
    2023-02-17T09:10:38.806+01:00   jvm 1 | at cd.go.authorization.keycloak.KeycloakPlugin.handle(KeycloakPlugin.java:71)
    2023-02-17T09:10:38.806+01:00   jvm 1 | at com.thoughtworks.go.plugin.infra.DefaultPluginManager.lambda$submitTo$0(DefaultPluginManager.java:134)
    2023-02-17T09:10:38.806+01:00   jvm 1 | at com.thoughtworks.go.plugin.infra.FelixGoPluginOSGiFramework.executeActionOnTheService(FelixGoPluginOSGiFramework.java:208)
    2023-02-17T09:10:38.806+01:00   jvm 1 | at com.thoughtworks.go.plugin.infra.FelixGoPluginOSGiFramework.doOn(FelixGoPluginOSGiFramework.java:164)
    2023-02-17T09:10:38.806+01:00   jvm 1 | at com.thoughtworks.go.plugin.infra.DefaultPluginManager.submitTo(DefaultPluginManager.java:131)
    2023-02-17T09:10:38.806+01:00   jvm 1 | at com.thoughtworks.go.plugin.access.PluginRequestHelper.submitRequest(PluginRequestHelper.java:49)
    2023-02-17T09:10:38.806+01:00   jvm 1 | at com.thoughtworks.go.plugin.access.authorization.AuthorizationExtension.authenticateUser(AuthorizationExtension.java:260)
    2023-02-17T09:10:38.806+01:00   jvm 1 | at com.thoughtworks.go.server.newsecurity.providers.WebBasedPluginAuthenticationProvider.authenticateWithExtension(WebBasedPluginAuthenticationProvider.java:80)
    2023-02-17T09:10:38.806+01:00   jvm 1 | at com.thoughtworks.go.server.newsecurity.providers.WebBasedPluginAuthenticationProvider.authenticateWithExtension(WebBasedPluginAuthenticationProvider.java:41)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at com.thoughtworks.go.server.newsecurity.providers.AbstractPluginAuthenticationProvider.authenticateUser(AbstractPluginAuthenticationProvider.java:118)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at com.thoughtworks.go.server.newsecurity.providers.AbstractPluginAuthenticationProvider.reauthenticate(AbstractPluginAuthenticationProvider.java:65)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at com.thoughtworks.go.server.newsecurity.filters.AbstractReAuthenticationFilter.attemptAuthentication(AbstractReAuthenticationFilter.java:120)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at com.thoughtworks.go.server.newsecurity.filters.AbstractReAuthenticationFilter.performReauthentication(AbstractReAuthenticationFilter.java:89)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at com.thoughtworks.go.server.newsecurity.filters.AbstractReAuthenticationFilter.doFilterInternal(AbstractReAuthenticationFilter.java:76)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at com.thoughtworks.go.server.newsecurity.filters.InvalidateAuthenticationOnSecurityConfigChangeFilter.doFilterInternal(InvalidateAuthenticationOnSecurityConfigChangeFilter.java:105)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:185)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at com.thoughtworks.go.server.newsecurity.filters.RememberLastRequestUrlFilter.doFilterInternal(RememberLastRequestUrlFilter.java:36)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:185)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at com.thoughtworks.go.server.newsecurity.filters.AlwaysCreateSessionFilter.doFilterInternal(AlwaysCreateSessionFilter.java:40)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:185)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at com.thoughtworks.go.server.newsecurity.filters.ModeAwareFilter.doFilter(ModeAwareFilter.java:79)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at com.thoughtworks.go.server.web.BackupFilter.doFilterInternal(BackupFilter.java:79)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
    2023-02-17T09:10:38.807+01:00   jvm 1 | at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:177)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at com.thoughtworks.go.server.newsecurity.filterchains.MainFilterChain.doFilter(MainFilterChain.java:79)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:347)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:263)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1626)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at com.thoughtworks.go.server.web.DefaultHeadersFilter.doFilter(DefaultHeadersFilter.java:51)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:201)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1626)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:552)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:772)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:600)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:505)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.server.Server.handle(Server.java:516)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479)
    2023-02-17T09:10:38.808+01:00   jvm 1 | at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277)
    2023-02-17T09:10:38.809+01:00   jvm 1 | at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
    2023-02-17T09:10:38.809+01:00   jvm 1 | at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
    2023-02-17T09:10:38.809+01:00   jvm 1 | at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
    2023-02-17T09:10:38.809+01:00   jvm 1 | at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338)
    2023-02-17T09:10:38.809+01:00   jvm 1 | at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315)
    2023-02-17T09:10:38.809+01:00   jvm 1 | at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
    2023-02-17T09:10:38.809+01:00   jvm 1 | at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
    2023-02-17T09:10:38.809+01:00   jvm 1 | at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409)
    2023-02-17T09:10:38.809+01:00   jvm 1 | at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
    2023-02-17T09:10:38.809+01:00   jvm 1 | at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
    2023-02-17T09:10:38.809+01:00   jvm 1 | at java.base/java.lang.Thread.run(Unknown Source)
klinux commented 1 year ago

Hi, no, I don't have idea what happens, but let me look at this to find out.

klinux commented 1 year ago

Here the error is complete:

jvm 1    | 2023-02-17 13:15:00,354 ERROR [qtp2084854285-54] p.c.g.a.k.c.g.a.k.KeycloakPlugin:127 [plugin-cd.go.authorization.keycloak] - Error while executing request go.cd.authorization.authenticate-user
jvm 1    | java.lang.RuntimeException: Api call to `/auth/realms/master/protocol/openid-connect/userinfo` failed with error: `{"error":"invalid_token","error_description":"Token verification failed"}`
jvm 1    |      at cd.go.authorization.keycloak.KeycloakApiClient.executeRequest(KeycloakApiClient.java:149)
jvm 1    |      at cd.go.authorization.keycloak.KeycloakApiClient.userProfile(KeycloakApiClient.java:135)
jvm 1    |      at cd.go.authorization.keycloak.executors.UserAuthenticationRequestExecutor.execute(UserAuthenticationRequestExecutor.java:59)
jvm 1    |      at cd.go.authorization.keycloak.requests.Request.execute(Request.java:47)
jvm 1    |      at cd.go.authorization.keycloak.KeycloakPlugin.handle(KeycloakPlugin.java:71)
jvm 1    |      at com.thoughtworks.go.plugin.infra.DefaultPluginManager.lambda$submitTo$0(DefaultPluginManager.java:134)
jvm 1    |      at com.thoughtworks.go.plugin.infra.FelixGoPluginOSGiFramework.executeActionOnTheService(FelixGoPluginOSGiFramework.java:208)
jvm 1    |      at com.thoughtworks.go.plugin.infra.FelixGoPluginOSGiFramework.doOn(FelixGoPluginOSGiFramework.java:164)
jvm 1    |      at com.thoughtworks.go.plugin.infra.DefaultPluginManager.submitTo(DefaultPluginManager.java:131)
jvm 1    |      at com.thoughtworks.go.plugin.access.PluginRequestHelper.submitRequest(PluginRequestHelper.java:49)
jvm 1    |      at com.thoughtworks.go.plugin.access.authorization.AuthorizationExtension.authenticateUser(AuthorizationExtension.java:260)
jvm 1    |      at com.thoughtworks.go.server.newsecurity.providers.WebBasedPluginAuthenticationProvider.authenticateWithExtension(WebBasedPluginAuthenticationProvider.java:80)
jvm 1    |      at com.thoughtworks.go.server.newsecurity.providers.WebBasedPluginAuthenticationProvider.authenticateWithExtension(WebBasedPluginAuthenticationProvider.java:41)

The token is not valid to request de userinfo endponint, I will see why this happens.

klinux commented 1 year ago

Unfurtenetely the gocd api not provide a way to use refresh_token, and this error happens when access_token has expired and can't use the userinfo endpoint, you need to align the Access Token Lifespan and SSO Session Idle with session of gocd.

gocd session is about 1 hour, here I let the Access Token Lifespan with 1h and SSO Session Idle 2h.

Look at this configuration of gocd -Dgo.security.reauthentication.interval

marcogreiveldinger commented 1 year ago

Thanks for investigating and the proposals! So would that be a feature request for the gocd project in your opinion?