That’s the intended configuration, i.e. an empty value for oidc.idtokenclaims
is interpreted as an empty list (i.e. no claim instead of the default list of claims).
It works
Same here when using the file-based config.
These SQLs for the XWiki.OIDC.ClientConfigurationClass
now disappeared when revisiting a cached page.
Performance is now decent. We’re fine I hope, thank you so much.
It would be interesting to check the in-wiki config as well, but now it throws an error for us:
HTTP Status 500 – Internal Server Error
Type Exception Report
Message Failed to handle Resource Reference [path = authenticator/callback, endpoint = authenticator, pathSegments = [callback]]
Beschreibung The server encountered an unexpected condition that prevented it from fulfilling the request.
Exception
javax.servlet.ServletException: Failed to handle Resource Reference [path = authenticator/callback, endpoint = authenticator, pathSegments = [callback]]
org.xwiki.resource.servlet.ResourceReferenceHandlerServlet.handleResourceReference(ResourceReferenceHandlerServlet.java:161)
org.xwiki.resource.servlet.ResourceReferenceHandlerServlet.service(ResourceReferenceHandlerServlet.java:87)
javax.servlet.http.HttpServlet.service(HttpServlet.java:779)
org.xwiki.container.servlet.filters.internal.SetHTTPHeaderFilter.doFilter(SetHTTPHeaderFilter.java:63)
org.xwiki.resource.servlet.RoutingFilter.doFilter(RoutingFilter.java:145)
Root Cause
org.xwiki.resource.ResourceReferenceHandlerException: Failed to handle http servlet request
org.xwiki.contrib.oidc.provider.internal.OIDCResourceReferenceHandler.handle(OIDCResourceReferenceHandler.java:110)
org.xwiki.resource.internal.DefaultResourceReferenceHandlerChain.handleNext(DefaultResourceReferenceHandlerChain.java:79)
org.xwiki.resource.internal.AbstractResourceReferenceHandlerManager.handle(AbstractResourceReferenceHandlerManager.java:82)
org.xwiki.resource.servlet.ResourceReferenceHandlerServlet.handleResourceReference(ResourceReferenceHandlerServlet.java:159)
org.xwiki.resource.servlet.ResourceReferenceHandlerServlet.service(ResourceReferenceHandlerServlet.java:87)
javax.servlet.http.HttpServlet.service(HttpServlet.java:779)
org.xwiki.container.servlet.filters.internal.SetHTTPHeaderFilter.doFilter(SetHTTPHeaderFilter.java:63)
org.xwiki.resource.servlet.RoutingFilter.doFilter(RoutingFilter.java:145)
Root Cause
java.lang.IllegalArgumentException: An Entity Reference name cannot be null or empty
org.xwiki.model.reference.EntityReference.setName(EntityReference.java:212)
org.xwiki.model.reference.EntityReference.<init>(EntityReference.java:154)
org.xwiki.model.reference.AbstractLocalizedEntityReference.<init>(AbstractLocalizedEntityReference.java:76)
org.xwiki.model.reference.DocumentReference.<init>(DocumentReference.java:174)
org.xwiki.contrib.oidc.auth.internal.OIDCUserManager.getNewUserDocument(OIDCUserManager.java:687)
org.xwiki.contrib.oidc.auth.internal.OIDCUserManager.updateUser(OIDCUserManager.java:302)
org.xwiki.contrib.oidc.auth.internal.OIDCUserManager.updateUserInfo(OIDCUserManager.java:201)
org.xwiki.contrib.oidc.auth.internal.OIDCUserManager.updateUserInfo(OIDCUserManager.java:169)
org.xwiki.contrib.oidc.auth.internal.endpoint.CallbackOIDCEndpoint.handle(CallbackOIDCEndpoint.java:203)
org.xwiki.contrib.oidc.provider.internal.OIDCResourceReferenceHandler.handle(OIDCResourceReferenceHandler.java:134)
org.xwiki.contrib.oidc.provider.internal.OIDCResourceReferenceHandler.handle(OIDCResourceReferenceHandler.java:108)
org.xwiki.resource.internal.DefaultResourceReferenceHandlerChain.handleNext(DefaultResourceReferenceHandlerChain.java:79)
org.xwiki.resource.internal.AbstractResourceReferenceHandlerManager.handle(AbstractResourceReferenceHandlerManager.java:82)
org.xwiki.resource.servlet.ResourceReferenceHandlerServlet.handleResourceReference(ResourceReferenceHandlerServlet.java:159)
org.xwiki.resource.servlet.ResourceReferenceHandlerServlet.service(ResourceReferenceHandlerServlet.java:87)
javax.servlet.http.HttpServlet.service(HttpServlet.java:779)
org.xwiki.container.servlet.filters.internal.SetHTTPHeaderFilter.doFilter(SetHTTPHeaderFilter.java:63)
org.xwiki.resource.servlet.RoutingFilter.doFilter(RoutingFilter.java:145)
Hinweis Der komplette Stacktrace der Ursache ist in den Server logs zu finden
Apache Tomcat/9.0.68
This now even occurs if I try to downgrade to the version we used before where the in-wiki config worked. Maybe the downgrade (i.e. uninstall and then install the dedicated version) is not fully possible for some reason? Anyway, we would not need it any more.
It’s not related to a cached page for me. What is cached is the user itself in the session, so as long as you keep the same session, the authenticator does nothing.
This suggests a problem with the “user name formater” (oidc.user.nameFormater
on properties side), it seems to produce an empty or null value for some reason.
At the wiki object, that parameter was set to ${oidc.user.email}
, as before, when it worked - we did not change anything.
I just released a 1.34.3 version with a bit more debug log to understand better what’s wrong with this user name formater configuration.
OK that’s great, we’ll try that.
To make the situation clear: The file based config in xwiki.properties works perfectly for us. It’s only that we also tried the inwiki-config, using the identical XWiki.OIDC.ClientConfigurationClass
object as before, which worked with the previous release, but now failed.
In the current situation, as we’ve been waiting for the performance issue to be resolved (which now is the case), we’d rather like to not experiment much further. However, I saved some error logs:
2023-01-21 12:41:00,122 [http-nio-8080-exec-4886 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] INFO x.x.u.i.x.XWikiAuthServiceImpl - User XWiki.myfirstname\.mylastname@mydomain\.com is authentified
2023-01-21 12:41:00,122 [http-nio-8080-exec-4886 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG x.x.u.i.x.XWikiAuthServiceImpl - XWikiAuthServiceImpl.checkAuth(XWikiContext) took 0 milliseconds to run.
2023-01-21 12:41:00,122 [http-nio-8080-exec-4886 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:00,122 [http-nio-8080-exec-4886 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:00,122 [http-nio-8080-exec-4886 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:00,124 [http-nio-8080-exec-4886 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:00,124 [http-nio-8080-exec-4886 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
...(log shortened)
2023-01-21 12:41:00,125 [pool-14-thread-1] DEBUG o.x.c.o.a.i.OIDCUserManager - OIDC user info request (org.xwiki.contrib.oidc.auth.internal.Endpoint@79dedc6,ya29.a0AX9GBdXGYjjwmtKPZtgXRZATfx7FMQE77m4xM0xuaifj8tAg8_jH8pft-jZb5-vcVpA1r8tnjAuIE9blHcZsKCm8UCKozSFY_5n5lI7j0mO9gLXw7ZeNWuQJFq3wNkKhvrAyuBif9vBE0WcGZ6p1-25MQF_Gyq4aCgYKAaYSARISFQHUCsbCEXXXQmQyBp6xh0b_q2dHVQ0166)
2023-01-21 12:41:00,128 [http-nio-8080-exec-4886 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:00,128 [pool-14-thread-1] DEBUG o.x.c.o.a.i.OIDCUserManager - OIDC user info request (https://openidconnect.googleapis.com/v1/userinfo?null,{Authorization=[Bearer ya29.a0AX9GBdXGYjjwmtKPZtgXRZATfx7FMQE77m4xM0xuaifj8tAg8_jH8pft-jZb5-vcVpA1r8tnjAuIE9blHcZsKCm8UCKozSFY_5n5lI7j0mO9gLXw7ZeNWuQJFq3wNkKhvrAyuBif9vBE0WcGZ6p1-25MQF_Gyq4aCgYKAaYSARISFQHUCsbCEXXXQmQyBp6xh0b_q2dHVQ0166], User-Agent=[OpenID Connect Authenticator/1.32.1]})
2023-01-21 12:41:00,180 [pool-14-thread-1] DEBUG o.x.c.o.a.i.OIDCUserManager - OIDC user info response ({
"sub": "114150584652287888377",
"name": "myfirstname mylastname",
"given_name": "myfirstname",
"family_name": "mylastname",
"picture": "https://lh3.googleusercontent.com/a/AEdFTp7m916hkaydEJV2jwCqR6q5Bm9rimShyBTgvTne\u003ds96-c",
"email": "myfirstname.mylastname@mydomain.com",
"email_verified": true,
"locale": "en",
"hd": "mydomain.com"
}
)
2023-01-21 12:41:01,538 [pool-14-thread-1] DEBUG o.x.c.o.a.i.OIDCUserManager - Updating XWiki claims
2023-01-21 12:41:01,539 [pool-14-thread-1] ERROR o.x.c.o.a.i.OIDCUserManager - Failed to update user informations
java.lang.ClassCastException: null
2023-01-21 12:41:02,829 [http-nio-8080-exec-4900 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] INFO x.x.u.i.x.XWikiAuthServiceImpl - User XWiki.myfirstname\.mylastname@mydomain\.com is authentified
2023-01-21 12:41:02,829 [http-nio-8080-exec-4900 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG x.x.u.i.x.XWikiAuthServiceImpl - XWikiAuthServiceImpl.checkAuth(XWikiContext) took 0 milliseconds to run.
2023-01-21 12:41:02,829 [http-nio-8080-exec-4900 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:02,829 [http-nio-8080-exec-4900 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:02,829 [http-nio-8080-exec-4900 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:02,830 [http-nio-8080-exec-4900 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:02,830 [http-nio-8080-exec-4900 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
...(log shortened)
2023-01-21 12:41:02,831 [pool-14-thread-1] DEBUG o.x.c.o.a.i.OIDCUserManager - OIDC user info request (org.xwiki.contrib.oidc.auth.internal.Endpoint@49924744,ya29.a0AX9GBdXGYjjwmtKPZtgXRZATfx7FMQE77m4xM0xuaifj8tAg8_jH8pft-jZb5-vcVpA1r8tnjAuIE9blHcZsKCm8UCKozSFY_5n5lI7j0mO9gLXw7ZeNWuQJFq3wNkKhvrAyuBif9vBE0WcGZ6p1-25MQF_Gyq4aCgYKAaYSARISFQHUCsbCEXXXQmQyBp6xh0b_q2dHVQ0166)
2023-01-21 12:41:02,832 [http-nio-8080-exec-4900 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:02,832 [pool-14-thread-1] DEBUG o.x.c.o.a.i.OIDCUserManager - OIDC user info request (https://openidconnect.googleapis.com/v1/userinfo?null,{Authorization=[Bearer ya29.a0AX9GBdXGYjjwmtKPZtgXRZATfx7FMQE77m4xM0xuaifj8tAg8_jH8pft-jZb5-vcVpA1r8tnjAuIE9blHcZsKCm8UCKozSFY_5n5lI7j0mO9gLXw7ZeNWuQJFq3wNkKhvrAyuBif9vBE0WcGZ6p1-25MQF_Gyq4aCgYKAaYSARISFQHUCsbCEXXXQmQyBp6xh0b_q2dHVQ0166], User-Agent=[OpenID Connect Authenticator/1.32.1]})
2023-01-21 12:41:02,885 [pool-14-thread-1] DEBUG o.x.c.o.a.i.OIDCUserManager - OIDC user info response ({
"sub": "114150584652287888377",
"name": "myfirstname mylastname",
"given_name": "myfirstname",
"family_name": "mylastname",
"picture": "https://lh3.googleusercontent.com/a/AEdFTp7m916hkaydEJV2jwCqR6q5Bm9rimShyBTgvTne\u003ds96-c",
"email": "myfirstname.mylastname@mydomain.com",
"email_verified": true,
"locale": "en",
"hd": "mydomain.com"
}
)
2023-01-21 12:41:02,909 [pool-14-thread-1] DEBUG o.x.c.o.a.i.OIDCUserManager - Updating XWiki claims
2023-01-21 12:41:02,910 [pool-14-thread-1] ERROR o.x.c.o.a.i.OIDCUserManager - Failed to update user informations
java.lang.ClassCastException: null
2023-01-21 12:41:04,163 [http-nio-8080-exec-4894 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] INFO x.x.u.i.x.XWikiAuthServiceImpl - User XWiki.myfirstname\.mylastname@mydomain\.com is authentified
2023-01-21 12:41:04,163 [http-nio-8080-exec-4894 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG x.x.u.i.x.XWikiAuthServiceImpl - XWikiAuthServiceImpl.checkAuth(XWikiContext) took 0 milliseconds to run.
2023-01-21 12:41:04,163 [http-nio-8080-exec-4894 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:04,163 [http-nio-8080-exec-4894 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:04,163 [http-nio-8080-exec-4894 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
...(log shortened)
2023-01-21 12:41:04,172 [pool-14-thread-1] DEBUG o.x.c.o.a.i.OIDCUserManager - OIDC user info request (org.xwiki.contrib.oidc.auth.internal.Endpoint@4b8e4d19,ya29.a0AX9GBdXGYjjwmtKPZtgXRZATfx7FMQE77m4xM0xuaifj8tAg8_jH8pft-jZb5-vcVpA1r8tnjAuIE9blHcZsKCm8UCKozSFY_5n5lI7j0mO9gLXw7ZeNWuQJFq3wNkKhvrAyuBif9vBE0WcGZ6p1-25MQF_Gyq4aCgYKAaYSARISFQHUCsbCEXXXQmQyBp6xh0b_q2dHVQ0166)
2023-01-21 12:41:04,173 [http-nio-8080-exec-4894 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:04,175 [pool-14-thread-1] DEBUG o.x.c.o.a.i.OIDCUserManager - OIDC user info request (https://openidconnect.googleapis.com/v1/userinfo?null,{Authorization=[Bearer ya29.a0AX9GBdXGYjjwmtKPZtgXRZATfx7FMQE77m4xM0xuaifj8tAg8_jH8pft-jZb5-vcVpA1r8tnjAuIE9blHcZsKCm8UCKozSFY_5n5lI7j0mO9gLXw7ZeNWuQJFq3wNkKhvrAyuBif9vBE0WcGZ6p1-25MQF_Gyq4aCgYKAaYSARISFQHUCsbCEXXXQmQyBp6xh0b_q2dHVQ0166], User-Agent=[OpenID Connect Authenticator/1.32.1]})
2023-01-21 12:41:04,237 [pool-14-thread-1] DEBUG o.x.c.o.a.i.OIDCUserManager - OIDC user info response ({
"sub": "114150584652287888377",
"name": "myfirstname mylastname",
"given_name": "myfirstname",
"family_name": "mylastname",
"picture": "https://lh3.googleusercontent.com/a/AEdFTp7m916hkaydEJV2jwCqR6q5Bm9rimShyBTgvTne\u003ds96-c",
"email": "myfirstname.mylastname@mydomain.com",
"email_verified": true,
"locale": "en",
"hd": "mydomain.com"
}
)
2023-01-21 12:41:04,261 [pool-14-thread-1] DEBUG o.x.c.o.a.i.OIDCUserManager - Updating XWiki claims
2023-01-21 12:41:04,262 [pool-14-thread-1] ERROR o.x.c.o.a.i.OIDCUserManager - Failed to update user informations
java.lang.ClassCastException: null
2023-01-21 12:41:05,491 [http-nio-8080-exec-4877 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] INFO x.x.u.i.x.XWikiAuthServiceImpl - User XWiki.myfirstname\.mylastname@mydomain\.com is authentified
2023-01-21 12:41:05,491 [http-nio-8080-exec-4877 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG x.x.u.i.x.XWikiAuthServiceImpl - XWikiAuthServiceImpl.checkAuth(XWikiContext) took 0 milliseconds to run.
2023-01-21 12:41:05,491 [http-nio-8080-exec-4877 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:05,491 [http-nio-8080-exec-4877 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:05,491 [http-nio-8080-exec-4877 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:05,492 [http-nio-8080-exec-4877 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:05,492 [http-nio-8080-exec-4877 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:05,493 [http-nio-8080-exec-4877 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
...(log shortened)
2023-01-21 12:41:05,493 [pool-14-thread-1] DEBUG o.x.c.o.a.i.OIDCUserManager - OIDC user info request (org.xwiki.contrib.oidc.auth.internal.Endpoint@17c03221,ya29.a0AX9GBdXGYjjwmtKPZtgXRZATfx7FMQE77m4xM0xuaifj8tAg8_jH8pft-jZb5-vcVpA1r8tnjAuIE9blHcZsKCm8UCKozSFY_5n5lI7j0mO9gLXw7ZeNWuQJFq3wNkKhvrAyuBif9vBE0WcGZ6p1-25MQF_Gyq4aCgYKAaYSARISFQHUCsbCEXXXQmQyBp6xh0b_q2dHVQ0166)
2023-01-21 12:41:05,494 [http-nio-8080-exec-4877 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:05,494 [pool-14-thread-1] DEBUG o.x.c.o.a.i.OIDCUserManager - OIDC user info request (https://openidconnect.googleapis.com/v1/userinfo?null,{Authorization=[Bearer ya29.a0AX9GBdXGYjjwmtKPZtgXRZATfx7FMQE77m4xM0xuaifj8tAg8_jH8pft-jZb5-vcVpA1r8tnjAuIE9blHcZsKCm8UCKozSFY_5n5lI7j0mO9gLXw7ZeNWuQJFq3wNkKhvrAyuBif9vBE0WcGZ6p1-25MQF_Gyq4aCgYKAaYSARISFQHUCsbCEXXXQmQyBp6xh0b_q2dHVQ0166], User-Agent=[OpenID Connect Authenticator/1.32.1]})
2023-01-21 12:41:05,541 [pool-14-thread-1] DEBUG o.x.c.o.a.i.OIDCUserManager - OIDC user info response ({
"sub": "114150584652287888377",
"name": "myfirstname mylastname",
"given_name": "myfirstname",
"family_name": "mylastname",
"picture": "https://lh3.googleusercontent.com/a/AEdFTp7m916hkaydEJV2jwCqR6q5Bm9rimShyBTgvTne\u003ds96-c",
"email": "myfirstname.mylastname@mydomain.com",
"email_verified": true,
"locale": "en",
"hd": "mydomain.com"
}
)
2023-01-21 12:41:05,567 [pool-14-thread-1] DEBUG o.x.c.o.a.i.OIDCUserManager - Updating XWiki claims
2023-01-21 12:41:05,568 [pool-14-thread-1] ERROR o.x.c.o.a.i.OIDCUserManager - Failed to update user informations
java.lang.ClassCastException: null
2023-01-21 12:41:06,037 [XWiki Solr index thread] ERROR o.a.s.h.RequestHandlerBase - org.apache.solr.common.SolrException: ERROR: [doc=xwiki:GoogleSSOConfig_en] multiple values encountered for non multiValued field property.XWiki.OIDC.ClientConfigurationClass.scope_sortString: [openid, profile, email]
at org.apache.solr.update.DocumentBuilder.toDocument(DocumentBuilder.java:160)
at org.apache.solr.update.DocumentBuilder.toDocument(DocumentBuilder.java:100)
at org.apache.solr.update.AddUpdateCommand.lambda$null$0(AddUpdateCommand.java:261)
at java.base/java.util.stream.ReferencePipeline$3$1.accept(Unknown Source)
at java.base/java.util.ArrayList$ArrayListSpliterator.tryAdvance(Unknown Source)
at java.base/java.util.stream.StreamSpliterators$WrappingSpliterator.lambda$initPartialTraversalState$0(Unknown Source)
at java.base/java.util.stream.StreamSpliterators$AbstractWrappingSpliterator.fillBuffer(Unknown Source)
at java.base/java.util.stream.StreamSpliterators$AbstractWrappingSpliterator.doAdvance(Unknown Source)
at java.base/java.util.stream.StreamSpliterators$WrappingSpliterator.tryAdvance(Unknown Source)
at java.base/java.util.Spliterators$1Adapter.hasNext(Unknown Source)
at org.apache.lucene.index.DocumentsWriterPerThread.updateDocuments(DocumentsWriterPerThread.java:200)
at org.apache.lucene.index.DocumentsWriter.updateDocuments(DocumentsWriter.java:415)
at org.apache.lucene.index.IndexWriter.updateDocuments(IndexWriter.java:1471)
at org.apache.lucene.index.IndexWriter.updateDocuments(IndexWriter.java:1464)
at org.apache.solr.update.DirectUpdateHandler2.updateDocOrDocValues(DirectUpdateHandler2.java:967)
at org.apache.solr.update.DirectUpdateHandler2.doNormalUpdate(DirectUpdateHandler2.java:342)
at org.apache.solr.update.DirectUpdateHandler2.addDoc0(DirectUpdateHandler2.java:294)
at org.apache.solr.update.DirectUpdateHandler2.addDoc(DirectUpdateHandler2.java:241)
at org.apache.solr.update.processor.RunUpdateProcessorFactory$RunUpdateProcessor.processAdd(RunUpdateProcessorFactory.java:73)
at org.apache.solr.update.processor.UpdateRequestProcessor.processAdd(UpdateRequestProcessor.java:55)
at org.apache.solr.update.processor.NestedUpdateProcessorFactory$NestedUpdateProcessor.processAdd(NestedUpdateProcessorFactory.java:79)
at org.apache.solr.update.processor.UpdateRequestProcessor.processAdd(UpdateRequestProcessor.java:55)
at org.apache.solr.update.processor.DistributedUpdateProcessor.doLocalAdd(DistributedUpdateProcessor.java:256)
at org.apache.solr.update.processor.DistributedUpdateProcessor.doVersionAdd(DistributedUpdateProcessor.java:495)
at org.apache.solr.update.processor.DistributedUpdateProcessor.lambda$versionAdd$0(DistributedUpdateProcessor.java:336)
at org.apache.solr.update.VersionBucket.runWithLock(VersionBucket.java:50)
at org.apache.solr.update.processor.DistributedUpdateProcessor.versionAdd(DistributedUpdateProcessor.java:336)
at org.apache.solr.update.processor.DistributedUpdateProcessor.processAdd(DistributedUpdateProcessor.java:222)
at org.apache.solr.handler.loader.JavabinLoader$1.update(JavabinLoader.java:110)
at org.apache.solr.client.solrj.request.JavaBinUpdateRequestCodec$StreamingCodec.readOuterMostDocIterator(JavaBinUpdateRequestCodec.java:343)
at org.apache.solr.client.solrj.request.JavaBinUpdateRequestCodec$StreamingCodec.readIterator(JavaBinUpdateRequestCodec.java:291)
at org.apache.solr.common.util.JavaBinCodec.readObject(JavaBinCodec.java:338)
at org.apache.solr.common.util.JavaBinCodec.readVal(JavaBinCodec.java:283)
at org.apache.solr.client.solrj.request.JavaBinUpdateRequestCodec$StreamingCodec.readNamedList(JavaBinUpdateRequestCodec.java:244)
at org.apache.solr.common.util.JavaBinCodec.readObject(JavaBinCodec.java:303)
at org.apache.solr.common.util.JavaBinCodec.readVal(JavaBinCodec.java:283)
at org.apache.solr.common.util.JavaBinCodec.unmarshal(JavaBinCodec.java:196)
at org.apache.solr.client.solrj.request.JavaBinUpdateRequestCodec.unmarshal(JavaBinUpdateRequestCodec.java:131)
at org.apache.solr.handler.loader.JavabinLoader.parseAndLoadDocs(JavabinLoader.java:122)
at org.apache.solr.handler.loader.JavabinLoader.load(JavabinLoader.java:70)
at org.apache.solr.handler.UpdateRequestHandler$1.load(UpdateRequestHandler.java:97)
at org.apache.solr.handler.ContentStreamHandlerBase.handleRequestBody(ContentStreamHandlerBase.java:82)
at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:216)
at org.apache.solr.core.SolrCore.execute(SolrCore.java:2646)
at org.apache.solr.client.solrj.embedded.EmbeddedSolrServer.request(EmbeddedSolrServer.java:229)
at org.apache.solr.client.solrj.SolrRequest.process(SolrRequest.java:214)
at org.apache.solr.client.solrj.SolrClient.add(SolrClient.java:177)
at org.apache.solr.client.solrj.SolrClient.add(SolrClient.java:138)
at org.apache.solr.client.solrj.SolrClient.add(SolrClient.java:156)
at org.xwiki.search.solr.internal.AbstractSolrInstance.add(AbstractSolrInstance.java:62)
at org.xwiki.search.solr.internal.DefaultSolrIndexer.processBatch(DefaultSolrIndexer.java:410)
at org.xwiki.search.solr.internal.DefaultSolrIndexer.run(DefaultSolrIndexer.java:376)
at java.base/java.lang.Thread.run(Unknown Source)
2023-01-21 12:41:25,639 [http-nio-8080-exec-4872 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:25,639 [http-nio-8080-exec-4872 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:25,640 [http-nio-8080-exec-4872 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:26,975 [http-nio-8080-exec-4884 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] INFO x.x.u.i.x.XWikiAuthServiceImpl - User XWiki.myfirstname\.mylastname@mydomain\.com is authentified
2023-01-21 12:41:26,975 [http-nio-8080-exec-4884 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG x.x.u.i.x.XWikiAuthServiceImpl - XWikiAuthServiceImpl.checkAuth(XWikiContext) took 0 milliseconds to run.
2023-01-21 12:41:26,975 [http-nio-8080-exec-4884 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:26,975 [http-nio-8080-exec-4884 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
...(log shortened)
2023-01-21 12:41:26,977 [http-nio-8080-exec-4884 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] ERROR o.x.c.o.a.i.OIDCUserManager - Failed to update user informations
java.lang.ClassCastException: null
2023-01-21 12:41:26,977 [http-nio-8080-exec-4884 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:26,977 [http-nio-8080-exec-4884 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:26,978 [http-nio-8080-exec-4884 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:28,304 [http-nio-8080-exec-4908 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] INFO x.x.u.i.x.XWikiAuthServiceImpl - User XWiki.myfirstname\.mylastname@mydomain\.com is authentified
2023-01-21 12:41:28,304 [http-nio-8080-exec-4908 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG x.x.u.i.x.XWikiAuthServiceImpl - XWikiAuthServiceImpl.checkAuth(XWikiContext) took 0 milliseconds to run.
2023-01-21 12:41:28,304 [http-nio-8080-exec-4908 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:28,304 [http-nio-8080-exec-4908 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
...(log shortened)
2023-01-21 12:41:28,307 [http-nio-8080-exec-4908 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] ERROR o.x.c.o.a.i.OIDCUserManager - Failed to update user informations
java.lang.ClassCastException: null
2023-01-21 12:41:28,307 [http-nio-8080-exec-4908 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:28,307 [http-nio-8080-exec-4908 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:28,308 [http-nio-8080-exec-4908 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:29,615 [http-nio-8080-exec-4853 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG o.x.c.o.a.OIDCAuthServiceImpl - Checking if there is already a user in the session
2023-01-21 12:41:29,616 [http-nio-8080-exec-4853 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] INFO x.x.u.i.x.XWikiAuthServiceImpl - User XWiki.myfirstname\.mylastname@mydomain\.com is authentified
2023-01-21 12:41:29,616 [http-nio-8080-exec-4853 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG x.x.u.i.x.XWikiAuthServiceImpl - XWikiAuthServiceImpl.checkAuth(XWikiContext) took 0 milliseconds to run.
2023-01-21 12:41:29,616 [http-nio-8080-exec-4853 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG o.x.c.o.a.OIDCAuthServiceImpl - Checking if a user info refresh is needed
2023-01-21 12:41:29,616 [http-nio-8080-exec-4853 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:29,616 [http-nio-8080-exec-4853 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG o.x.c.o.a.i.OIDCUserManager - Refresing the user info
2023-01-21 12:41:29,616 [http-nio-8080-exec-4853 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:29,616 [http-nio-8080-exec-4853 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:29,618 [http-nio-8080-exec-4853 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
...(log shortened)
2023-01-21 12:41:29,620 [http-nio-8080-exec-4853 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] ERROR o.x.c.o.a.i.OIDCUserManager - Failed to update user informations
java.lang.ClassCastException: class com.nimbusds.openid.connect.sdk.claims.IDTokenClaimsSet cannot be cast to class com.nimbusds.openid.connect.sdk.claims.IDTokenClaimsSet (com.nimbusds.openid.connect.sdk.claims.IDTokenClaimsSet is in unnamed module of loader org.xwiki.classloader.NamespaceURLClassLoader @3e7c66b3; com.nimbusds.openid.connect.sdk.claims.IDTokenClaimsSet is in unnamed module of loader org.xwiki.classloader.NamespaceURLClassLoader @272975b)
at org.xwiki.contrib.oidc.auth.internal.OIDCClientConfiguration.getIdToken(OIDCClientConfiguration.java:846)
at org.xwiki.contrib.oidc.auth.internal.OIDCUserManager.updateUserInfoAsync(OIDCUserManager.java:129)
at org.xwiki.contrib.oidc.auth.internal.OIDCUserManager.checkUpdateUserInfo(OIDCUserManager.java:149)
at org.xwiki.contrib.oidc.auth.OIDCAuthServiceImpl.checkAuth(OIDCAuthServiceImpl.java:102)
at com.xpn.xwiki.XWiki.checkAuth(XWiki.java:4336)
at org.xwiki.security.authorization.internal.XWikiCachingRightService.authenticateUser(XWikiCachingRightService.java:241)
at org.xwiki.security.authorization.internal.XWikiCachingRightService.checkAccess(XWikiCachingRightService.java:271)
at com.xpn.xwiki.XWiki.checkAccess(XWiki.java:4359)
at com.xpn.xwiki.XWiki.prepareDocuments(XWiki.java:5880)
at com.xpn.xwiki.web.XWikiAction.execute(XWikiAction.java:502)
at com.xpn.xwiki.web.XWikiAction.execute(XWikiAction.java:292)
at com.xpn.xwiki.web.LegacyActionServlet.service(LegacyActionServlet.java:115)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:779)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
at com.xpn.xwiki.web.ActionFilter.doFilter(ActionFilter.java:122)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
at org.xwiki.wysiwyg.filter.ConversionFilter.doFilter(ConversionFilter.java:61)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
at org.xwiki.container.servlet.filters.internal.SetHTTPHeaderFilter.doFilter(SetHTTPHeaderFilter.java:63)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
at org.xwiki.container.servlet.filters.internal.SavedRequestRestorerFilter.doFilter(SavedRequestRestorerFilter.java:208)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
at org.xwiki.container.servlet.filters.internal.SetCharacterEncodingFilter.doFilter(SetCharacterEncodingFilter.java:111)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
at org.xwiki.resource.servlet.RoutingFilter.doFilter(RoutingFilter.java:132)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:135)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:687)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:360)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:399)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:893)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1789)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.base/java.lang.Thread.run(Unknown Source)
2023-01-21 12:41:29,620 [http-nio-8080-exec-4853 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:29,620 [http-nio-8080-exec-4853 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:29,621 [http-nio-8080-exec-4853 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:29,940 [http-nio-8080-exec-4899 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG o.x.c.o.a.OIDCAuthServiceImpl - Checking if there is already a user in the session
2023-01-21 12:41:29,940 [http-nio-8080-exec-4899 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] INFO x.x.u.i.x.XWikiAuthServiceImpl - User XWiki.myfirstname\.mylastname@mydomain\.com is authentified
2023-01-21 12:41:29,940 [http-nio-8080-exec-4899 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG x.x.u.i.x.XWikiAuthServiceImpl - XWikiAuthServiceImpl.checkAuth(XWikiContext) took 0 milliseconds to run.
2023-01-21 12:41:29,940 [http-nio-8080-exec-4899 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG o.x.c.o.a.OIDCAuthServiceImpl - Checking if a user info refresh is needed
2023-01-21 12:41:29,940 [http-nio-8080-exec-4899 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:29,940 [http-nio-8080-exec-4899 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG o.x.c.o.a.i.OIDCUserManager - Refresing the user info
2023-01-21 12:41:29,940 [http-nio-8080-exec-4899 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
2023-01-21 12:41:29,940 [http-nio-8080-exec-4899 - http://xwiki.pilot.mydomain.com/bin/get/XWiki/Extensions] DEBUG .o.a.i.OIDCClientConfiguration - Session: 9754F72D3CB2005BD3A8CBF13C141622
(log shortened)
During that logged period on Jan 21st I tried several uninstalls and reinstalls of the previous version, as I wrote. Does this log also give you some insights? If not, we’ll try the extended logging from 1.34.3, but that might take some time.
Sure, no problem. You have already been very helpful !
This one is indeed interesting. It generally means that there is some classloader problem and I think I know where it’s coming from, fixing it, but in general a good workaround is to restart.