Page load performance / Page Cache relevant?

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 :slightly_smiling_face:

Same here when using the file-based config. :slightly_smiling_face:
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.