search

OpenConext / OpenConext-oidcng

OpenID Connect gateway - The Next Generation
3 stars 5 forks source link

json logger logs wrong info #138

Closed phavekes closed 3 hours ago

phavekes commented 3 hours ago

This issue is imported from pivotal - Originaly created at Aug 26, 2020 by Bart Geesink

below is a message logged by oidcng: It shows a stacktrace about a redirect mismatch, but the rest of the attributes suggest a userinfo error.

{ "@timestamp": "2020-08-26T09:38:24.824+02:00", "message": "Error has occurred", "logger_name": "oidc.web.ErrorController", "level": "ERROR", "stack_trace": "oidc.exceptions.RedirectMismatchException: Client intranet.erasmusmc.nl with registered redirect URI\'s [https://intranet-redactie-en.prod.erasmusmc.nl/wp/wp-admin/admin-ajax.php?action=surfconext-callback, https://intranet.erasmusmc.nl/auth/callback, https://intranet-agd1-en.acc.erasmusmc.nl/auth/callback, https://intranet-redactie.acc.erasmusmc.nl/wp/wp-admin/admin-ajax.php?action=surfconext-callback, https://intranet-redactie-agd1.prod.erasmusmc.nl/wp/wp-admin/admin-ajax.php?action=surfconext-callback, https://intranet-redactie-agd1-en.prod.erasmusmc.nl/wp/wp-admin/admin-ajax.php?action=surfconext-callback, https://intranet-agd1.prod.erasmusmc.nl/auth/callback, https://intranet-agd1.acc.erasmusmc.nl/auth/callback, https://intranet-redactie-agd1-en.acc.erasmusmc.nl/wp/wp-admin/admin-ajax.php?action=surfconext-callback, https://intranet-redactie.erasmusmc.nl/wp/wp-admin/admin-ajax.php?action=surfconext-callback, https://intranet-en.prod.erasmusmc.nl/auth/callback, https://intranet-en.acc.erasmusmc.nl/auth/callback, https://intranet-redactie-agd1.erasmusmc.nl/wp/wp-admin/admin-ajax.php?action=surfconext-callback, https://intranet-en.erasmusmc.nl/auth/callback, https://intranet-redactie-en.erasmusmc.nl/wp/wp-admin/admin-ajax.php?action=surfconext-callback, https://intranet-agd1.erasmusmc.nl/auth/callback, https://intranet-redactie-agd1.acc.erasmusmc.nl/wp/wp-admin/admin-ajax.php?action=surfconext-callback, https://intranet-agd1-en.erasmusmc.nl/auth/callback, https://intranet.prod.erasmusmc.nl/auth/callback, https://intranet-redactie-en.acc.erasmusmc.nl/wp/wp-admin/admin-ajax.php?action=surfconext-callback, https://intranet.acc.erasmusmc.nl/auth/callback, https://intranet-agd1-en.prod.erasmusmc.nl/auth/callback, https://intranet-redactie-agd1-en.erasmusmc.nl/wp/wp-admin/admin-ajax.php?action=surfconext-callback, https://intranet-redactie.prod.erasmusmc.nl/wp/wp-admin/admin-ajax.php?action=surfconext-callback, https://oidc-playground.surfconext.nl/redirect] requested authorization with redirectURI https://intranet.test.erasmusmc.nl/auth/callback\n\tat oidc.endpoints.AuthorizationEndpoint.validateRedirectionURI(AuthorizationEndpoint.java:375)\n\tat oidc.web.ConfigurableSamlAuthenticationRequestFilter.validateAuthorizationRequest(ConfigurableSamlAuthenticationRequestFilter.java:190)\n\tat oidc.web.ConfigurableSamlAuthenticationRequestFilter.doFilterInternal(ConfigurableSamlAuthenticationRequestFilter.java:154)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)\n\tat org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:113)\n\tat org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)\n\tat org.springframework.security.saml.provider.SamlMetadataFilter.doFilterInternal(SamlMetadataFilter.java:75)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)\n\tat org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:113)\n\tat org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)\n\tat org.springframework.security.saml.provider.config.ThreadLocalSamlConfigurationFilter.doFilterInternal(ThreadLocalSamlConfigurationFilter.java:42)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)\n\tat org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)\n\tat org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:116)\n\tat org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:113)\n\tat org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)\n\tat org.springframework.web.filter.CorsFilter.doFilterInternal(CorsFilter.java:92)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)\n\tat org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)\n\tat org.springframework.security.web.header.HeaderWriterFilter.doHeadersAfter(HeaderWriterFilter.java:92)\n\tat org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:77)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)\n\tat org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)\n\tat org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:105)\n\tat org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)\n\tat org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:56)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)\n\tat org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)\n\tat org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:215)\n\tat org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:178)\n\tat org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:358)\n\tat org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:271)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)\n\tat org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)\n\tat org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)\n\tat org.springframework.session.web.http.SessionRepositoryFilter.doFilterInternal(SessionRepositoryFilter.java:141)\n\tat org.springframework.session.web.http.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:82)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)\n\tat org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)\n\tat org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)\n\tat org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)\n\tat org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541)\n\tat org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139)\n\tat org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)\n\tat org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)\n\tat org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)\n\tat org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:367)\n\tat org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)\n\tat org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)\n\tat org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1639)\n\tat org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)\n\tat org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)\n\tat java.lang.Thread.run(Thread.java:748)\n", "code": "code", "user_id": "5f3b512e39346621d49d8585", "action": "Userinfo", "user_name_id": "urn:collab:person:erasmusmc.nl:143047", "accessTokenValue": "eyJraWQiOiJrZXlfMjAyMF8wOF8yNl8wMF8wMF8wMF8wNDciLCJ0eXAiOiJKV1QiLCJhbGciOiJSUzI1NiJ9.eyJhdWQiOiJsb2dpbi5hZmFzb25saW5lLmNvbSIsInN1YiI6ImxvZ2luLmFmYXNvbmxpbmUuY29tIiwibmJmIjoxNTk4NDI3NDg1LCJpc3MiOiJodHRwczpcL1wvY29ubmVjdC5zdXJmY29uZXh0Lm5sIiwiY2xhaW1zIjoiQVJrRktQODFjNUJSYmRDRm5jZ2FPVmVWZW5RcFRjR1hNUnc2alp0YkF2VEVWVUlyZEJIakhFQVBZRHNYeVczQlh0aUVXSDgzczVudkpkd0RQM0FUSjVrWEU1SWU2dFRiZmFkWXkyNGZoZEhnUW9Rb01oWWltdEo5R3d1VFc4ZHZURER5MEEyWFwvRXR1aVJxVlVXSVhnNWNZU0pwaEwyRUNjMGhlNE9XTlpRVjl2alhMalwvaWJ1NnhUbHJKZ0t0Y004eGdvcG5scjN0NnFVTWRacW1heTliUkV0R214KzN5OTBqWThqK3RBd0pRMDh6OXlDT1V0TDAwOFNycGp1azVqY3ZQTXpRcEo1ZVVraERoYUs2TXNtTnloSHY3S3c1TXJNUkp1UUQ0Vk5sZlwvXC9pcU5mYWZhUFwvSU9BMStxQVlBK1FLVnREcFVXZWpsRmZZOUFzb1RHWXA5OUJ0NURtSktXU2lsV09CVEtkSkhLOFwvZTdEemZQdVZxZjV4dHNzWGd0SkowN1cxdnBrc0hySUE5TVJkZ0VHSjV0Y1d1RXNSZUZ5aFU4ZmNnRlBuSHB5Rmk1aTRCSGlHSmNERjRKdEhRU2tNUkh6M0RrUFhXWGdrYmhJdVpWTnNCTUNRNExHUG4wT1FIRG0xYm5OM3g5U3JBeDUyZTBHMFRoMVB6U2t5VkVVM0pCNXZBXC9oUmFDMVd5WFl6bWdPbW5RZ0RUMU90OVh5OXBrU1wvaFBlMDBYQlJyXC9xYmpxM2NOWHhTd3cwZnJoQjhXTXRzdXVha0ZuY3dFR0NETGpYYkYwTnpUakNWV1U3Q0xFUE50YkJKbWNvdVVPT3lcL1NLZTFHUVE2QkZHQWUzY003b0ptWTdLYjAiLCJleHAiOjE1OTg0MzEwODUsImNsYWltX2tleV9pZCI6IjQxOTc2ODU3NSIsImlhdCI6MTU5ODQyNzQ4NSwianRpIjoiMzczYjYxMTYtMWViYS00M2NmLWI4ZTMtNDhhMmYwMzMwMWE5In0.g_JdJ5jHKsGWYlNvQ--WnXs4ucqsAL9YLTD3WBqofjXTxCdxJucieCBcR_HdrZoZxM7T71bhQyXfGcFTv9G_ljQU7Q-Il_7AdDGcvsJSwgY5HN3UcOuHJx1sAthrFl5Ox5-PdcIt2bUc7ZK-Xubv6C7RxO82URypy3qe8nqqKzjSp24pd0WWWlxQhMij7S2APHztIHSXfxDckK3cR0BAVR1QhzZA9zfOn6fCGpQE-e-Y76iRj9uHQsr-32VC8lSYblNROCWn0w1NCbA-rK20asYw3HfK2O4jAw_jOfPah4ncuO3UEWRv4N5RNV470qOZFEHOx1nFiL7EbeoCdAa7tg", "grant": "authorization_code", "rp": "login.afasonline.com", "app": "oidcng" }

phavekes commented 3 hours ago

The Thread-local MDC context information was not cleared before new requests and old information was re-used. Solution is to use a Filter at the start of the filter chain to clear out MDC information before anything is logged. (Okke Harsta - Sep 7, 2020)