Page load performance / Page Cache relevant?

Lukas · December 30, 2022, 7:20am

Hi all. First of all, again, a big thanks to all contributors who made this great platform possible. We’re using it for several months now and are generally very happy, especially with the huge functional flexibility and configurability which is provided via the UI.

Our setting: 13.10 with PostgreSQL and Tomcat behind a Nginx proxy and a Kubernetes deployment. We implemented 17 subwikis and some 1.500 custom pages, with currently around 25-30 users.

Lately, the page load performance seems to be degrading a bit and I’m trying to nail down the reasons. One hypothesis is that it has to do with the Page Cache but I’m not 100% sure, so let me first share the symptoms:

Quite frequently when we’re accessing the “Main” pages of the subwikis, it takes several seconds (typically 2-7) to load, even if no other user is active. These “Main” pages still are the shipped versions and don’t have anything special.
I’ve been using the debug=true URL parameter and could identify time is spent executing several Velocity templates belonging to the Flamingo skin. E.g. the frequentlyUsedDocs.vm which just executes 6 getDocument() calls and sometimes takes 1-2 seconds to execute, especially for the call #set($preferencesDoc = $!xwiki.getDocument('XWiki.XWikiPreferences')).
As these get-calls are probably spread a lot around the templates it’s not surprising page loads become slow. Another template which takes its time to execute is especially the drawer.vm, but also others.

Here’s a screenshot of the startpage.vm part of a typical page load:

My hypothesis is that due to the amount of documents we have (~ 20.000 if we just sum up a count(*) on the xwikidoc tables in all subwikis), the Page Cache (or Document Cache, meaning the same, right? – the Infinispan name is "xwiki.store.pagecache(local)") is probably too small – it’s still at the setting of 500 documents as of the xwiki.cfg. Maybe after a while of accessing several subwikis, some docs are pushed out of the cache and need to be retrieved from the database. What underlines this assumption is that when I clear this cache manually using Groovy (I adapted the scripts from this extension) page loads become significantly slower.

Here are the metrics I can get about this cache, using mbean.getProperty() for each available attribute. Honestly they don’t tell me much – apparently the numberOfEntries metric has become deprecated. What I notice is that if I clear the cache, the statistics hardly change, as if they are cumulated since last system reboot.

"xwiki.store.pagecache(local)"

* removeTimes:
* averageWriteTime: 0
* removeMisses: 128
* averageReadTime: 0
* evictions: 100384
* averageRemoveTimeNanos: 267205
* removeHits: 3292
* timeSinceStart: 556477
* missTimes:
* misses: 621598
* hitTimes:
* readWriteRatio: 59.3171283467643
* numberOfEntries: -1
* numberOfEntriesInMemory: -1
* averageWriteTimeNanos: 386245
* statisticsEnabled:
* stores: 110069
* requiredMinimumNumberOfNodes: 1
* hits: 5907379
* timeSinceReset: 556477
* hitRatio: 0.9047939669568449
* averageReadTimeNanos: 26883
* storeTimes:
* averageRemoveTime: 0
* dataMemoryUsed: 0
* offHeapMemoryUsed: 0
* elapsedTime: 556477

I should also mention that we use the OpenID Connect extension for Google SSO and are adding some custom global JSX and CSX extension objects. However, I can’t see how this can affect the behaviour described above (except for it might affect the javascript.vm or colorThemeInit.vm execution time (?) - but many templates are slow, not only these).

We could of course increase the page cache as we do have ~ 2GB heap and ~0.5GB non-heap of memory. However, my questions are the following:

Is my Page Cache hypothesis a reasonable explanation for the slow page load?
Is there a timeout when docs are moved out of the Page Cache (there seems to be no setting for that)?
If we increase the Page Cache, should we do that in careful steps or is it safe to move it up to, say, 5000? What are experiences around this setting?
Even without having a doc in the cache, shouldn’t the database retrievals be faster? Can it be due to fragmentation and/or long page historys over time? What is the best way of checking whether database queries are a bottleneck - e.g. some test SQLs? (I’ve e.g. been checking pg_stat_user_tables and see there are several dead tuples in some xwikidoc tables, although autovacuum is on. Not sure if this is important though.)
Side question about the caching of rendered JSX or CSX Velocity code: If we set caching policy to “long”, what does this mean exactly – some hours, a day, a week, or is it affected by other factors? I couldn’t find any documentation on this.

Any answers or suggestions very welcome!

tmortagne · December 30, 2022, 8:20am

Hi,

In case you did not look at it already, you might find some ideas to improve performances on https://www.xwiki.org/xwiki/bin/view/Documentation/AdminGuide/Performances/.

The hitRatio does not look too bad to me. Is your page loading still slow when you refresh a page several times ? If it is, then all the pages you need should be in the cache for the following refresh, so it should mean the problem is somewhere else. That’s unless something in your skin loads enough document to fill the cache at each load but something like this would be very visible.

No timeout. Document are invalidated when:

they are modified
the cache is full

Better do it step by step and monitor how your memory use grows. I thought the Infinispan JMX was giving heap use, but it does not seem to be the cache (anymore ?) but you could get it using some profiler.

Loading a given document is not supposed to be so bad (unless the document itself really contains a lot of things), but loading a document when the cache is totally empty is a very different matter. Loading a document from scratch generally imply loading quite a lot of other documents, mainly because of the object model: the class of each object, stored in a different document, needs to be loaded too. But accessing a document also imply loading the documents of all the parties indirectly involved (the user, the groups of the user, and all the documents manipulated by the various elements of the skin, etc.) making the very first load after a totally empty document cache quite slower.

I honestly don’t know much about Postgres, unfortunately. I’m more used to MySQL (and MariaDB) but mainly because I’m too lazy to spend more time familiarizing with Potsgres for which I’m hearing a lot of good things. In MySQL what generally has a big impact on the performances is the size of the innodb_buffer_pool_size, but I doubt it helps you much.

That cache policy controls the browser Cache-Control Expires value and is as follows from what I can see in the code:

LONG: 30 * 24 * 3600 * 1000 so 30 days expressed in milliseconds
SHORT: 1 * 24 * 3600 * 1000 so 1 day expressed in milliseconds

Lukas · December 30, 2022, 9:01am

Thanks, that was fast!

I indeed had some looks, although we did not try everything yet.

No, it’s not. Except if I do the refresh in very short intervals like 1-2 seconds, then it can be slow again - but I suppose that’s for other reasons like unfinished background processes from the previous refresh. If I refresh in intervals like 30 seconds and remain on the same page it’s nearly always fast.

What we do in one global JSX object is to collect wiki metadata by Velocity calls like $services.wiki.getAll(). However I thought the result of this should be cached because of the caching policy “long”. Maybe I misunderstand something here? See also end of post.

Ok, we’ll try.

That is helpful information, thanks. I have a question related to this: Is the loading of users / groups during loading of another page (as you described) affected by the allgroupimplicit=1 setting? I yes, we might give it a try.

No problem - maybe somebody else can help out? Or at least: Maybe you could tell me whether there’s a logger I could activate (using the Logging App) to see the SQLs sent to the PostgreSQL database? org.hibernate.SQL seems to give only the SQLs sent to Hibernate (which has its own cache if I’m not mistaken).

Thanks. Actually I thought this affects the duration how long the parsed Velocity code remains cached on server side - see e.g. this explanation. Maybe I’m misunderstanding it’s meaning? See above.

tmortagne · December 30, 2022, 9:48am

By the way, do you really mean the exact 13.10 version or 13.10.x ? I would really recommend using the latest version of that branch (currently 13.10.10), since many things were fixed since (including some important security fixes). We also just started what is now the new LTS branch with 14.10.2 but upgrading to it might be more work depending on how much customization of standard pages you may have.

OK, then it indeed it really looks like the problem is that the document cache might be too small (at least not big enough to contain all the very frequently needed documents).

Even if the JSX was asked every time, the impact of $services.wiki.getAll() is very low since the wiki descriptors are cached and never really evicted (unless explicitly modified).

Not enough to explain such an impact. Also, the security module actually have its own caching of groups and there is very little chance for XWikiAllGroup to ever be evicted from that cache since it’s used quite a lot (the cache policy is to evict the least used entries when it’s full).

No, this value is only used to generate the HTTP Cache-Control header in the response, but I agree with you that the documentation is not very explicit about that. The warning skin extension “used together with the Parse content option set to Yes” is just to remind you that since it’s a browser side cache, it might be risky for dynamic content because there is no way to invalidate it when something changes. I updated a bit the documentation to reflect that a bit better.

Lukas · December 30, 2022, 10:28am

We’re using 13.10.9.

OK, as said, we’ll try increasing it. Apart from that I’ll keep looking for anything which might frequently cause huge cache fills / evictions.

Btw, about my question above

I figured out myself that it’s indeed the org.hibernate.SQL logger - I looked at the wrong place. I’ll use these SQLs for direct testing in the database. Only problem is these logs are littering the stdout very much as also every Solr indexing SQL is logged there.

tmortagne · December 30, 2022, 10:33am

Solr is loading a lot of document when the index is not up to date, but when it’s done it should not be visible much unless there is a lot of document changes (after the init it only reacts to document change events).

Lukas · January 9, 2023, 2:27pm

Update: we’ve been setting the page cache to 2000. So far, we experience no obvious large increase of memory consumption but will monitor it further.

The cache works well, meaning that viewed pages are returned from the cache. I verified this by checking the PostgreSQL database log output where generally none of the initial SQL (executed with an empty cache) are to be found during page load any more. So far, so good.

However, there is an exception, and it appears this might be related to the fact that our page loads sometimes still are slow even if cached (still often > 2 sec). This happens especially if pages are accessed shortly after another (< 10 sec). My guess is this is due to unfinished processes caused by the previous page load, and there is indeed one SQL which is still executed when the page was cached:

2023-01-09 10:47:51.044 GMT [8058] LOG:  execute S_7: select baseobject0_.XWO_NAME as col_0_0_ from xwikiobjects baseobject0_ cross join xwikistrings stringprop1_ where baseobject0_.XWO_CLASSNAME=$1 and baseobject0_.XWO_ID=stringprop1_.XWS_ID and stringprop1_.XWS_NAME=$2 and stringprop1_.XWS_VALUE=$3
2023-01-09 10:47:51.044 GMT [8058] DETAIL:  parameters: $1 = 'XWiki.OIDC.ClientConfigurationClass', $2 = 'configurationName', $3 = 'default'

To be more precise, this statement is executed identically (!) hundreds of times (!) during page load and in the 5-10 seconds after.

The statement obviously belongs to the OpenID Connect extension we recently installed to enable Google SSO.
We are using the in-wiki method, defining a page (in the root namespace) with an object of the XWiki.OIDC.ClientConfigurationClass. Exactly the one which is queried above.
However, it is rather unclear why this is executed identically for so often, and also, why this page is not cached itself. Maybe something in our custom Velocity / CSS / JS code is causing this, but no clue what this can be.
Or it is the fact that we have 17 subwikis. (The SQL posted above is sometimes executed in the public schema and sometimes in the subwiki’s schema - where the object does not exist.) However, the extension is intended for usage in a farm so this should not be the issue.

Any ideas?

We also tried to get rid of the in-wiki-config, to remove this page and its object and to put everything into the xwiki.properties.
However, this attempt failed because we couldn’t get rid of sending custom claims to Google, which Google does not accept (any more). A similar problem is described in this thread: Claims must have a single object value 'id_token'
The in-wiki-configuration, so far, is the only method which worked for us to get the Google SSO enabled, so we need to live with that somehow.

If I should open another thread for this OpenID Connect question please let me know.

tmortagne · January 12, 2023, 8:46am

This is indeed very strange. And that’s when a single user access a single page without any other interaction at all ?

The wiki side of the configuration is supposed to be just that, a wiki storage for the same data, but then it’s handled the same way AFAIK. How exactly did you resolve your problem with the wiki configuration ?

Lukas · January 12, 2023, 9:36am

Exactly. Happy to provide more details / logs if you tell me what exactly would help (e.g. output of a certain XWiki logger, full thread dump etc.). We even disabled all side panels.

xwiki.cfg:
xwiki.authentication.authclass=org.xwiki.contrib.oidc.auth.OIDCAuthServiceImpl

xwiki.properties:
nothing

page with object of class XWiki.OIDC.ClientConfigurationClass:
This is the xml of the exported object (I just removed Google client id and secret):

  <object>
    <name>GoogleSSOConfig</name>
    <number>0</number>
    <className>XWiki.OIDC.ClientConfigurationClass</className>
    <guid>680745ea-d673-4bc2-b408-a7bf1f58920c</guid>
    <class>
      <name>XWiki.OIDC.ClientConfigurationClass</name>
      <customClass/>
      <customMapping/>
      <defaultViewSheet/>
      <defaultEditSheet/>
      <defaultWeb/>
      <nameField/>
      <validationScript/>
      <authorizationEndpoint>
        <disabled>0</disabled>
        <name>authorizationEndpoint</name>
        <number>7</number>
        <prettyName>Authorization OIDC endpoint</prettyName>
        <size>255</size>
        <unmodifiable>0</unmodifiable>
        <classType>com.xpn.xwiki.objects.classes.StringClass</classType>
      </authorizationEndpoint>
      <clientId>
        <disabled>0</disabled>
        <name>clientId</name>
        <number>11</number>
        <prettyName>Client ID</prettyName>
        <size>255</size>
        <unmodifiable>0</unmodifiable>
        <classType>com.xpn.xwiki.objects.classes.StringClass</classType>
      </clientId>
      <clientSecret>
        <disabled>0</disabled>
        <name>clientSecret</name>
        <number>12</number>
        <prettyName>Secret</prettyName>
        <size>255</size>
        <unmodifiable>0</unmodifiable>
        <classType>com.xpn.xwiki.objects.classes.StringClass</classType>
      </clientSecret>
      <configurationName>
        <disabled>0</disabled>
        <name>configurationName</name>
        <number>1</number>
        <prettyName>Configuration name</prettyName>
        <size>255</size>
        <unmodifiable>0</unmodifiable>
        <classType>com.xpn.xwiki.objects.classes.StringClass</classType>
      </configurationName>
      <groupsClaim>
        <disabled>0</disabled>
        <name>groupsClaim</name>
        <number>2</number>
        <prettyName>Group claim</prettyName>
        <size>255</size>
        <unmodifiable>0</unmodifiable>
        <classType>com.xpn.xwiki.objects.classes.StringClass</classType>
      </groupsClaim>
      <idTokenClaims>
        <cache>0</cache>
        <disabled>0</disabled>
        <displayType>input</displayType>
        <freeText>forbidden</freeText>
        <largeStorage>0</largeStorage>
        <multiSelect>1</multiSelect>
        <name>idTokenClaims</name>
        <number>20</number>
        <prettyName>ID Token Claims</prettyName>
        <relationalStorage>0</relationalStorage>
        <separator>|</separator>
        <separators>|,</separators>
        <size>5</size>
        <unmodifiable>0</unmodifiable>
        <values/>
        <classType>com.xpn.xwiki.objects.classes.StaticListClass</classType>
      </idTokenClaims>
      <logoutEndpoint>
        <disabled>0</disabled>
        <name>logoutEndpoint</name>
        <number>10</number>
        <prettyName>Logout OIDC endpoint</prettyName>
        <size>255</size>
        <unmodifiable>0</unmodifiable>
        <classType>com.xpn.xwiki.objects.classes.StringClass</classType>
      </logoutEndpoint>
      <logoutEndpointMethod>
        <disabled>0</disabled>
        <name>logoutEndpointMethod</name>
        <number>16</number>
        <prettyName>Logout endpoint method</prettyName>
        <size>255</size>
        <unmodifiable>0</unmodifiable>
        <classType>com.xpn.xwiki.objects.classes.StringClass</classType>
      </logoutEndpointMethod>
      <logoutMechanism>
        <disabled>0</disabled>
        <name>logoutMechanism</name>
        <number>17</number>
        <prettyName>Logout mechanism</prettyName>
        <size>255</size>
        <unmodifiable>0</unmodifiable>
        <classType>com.xpn.xwiki.objects.classes.StringClass</classType>
      </logoutMechanism>
      <scope>
        <cache>0</cache>
        <disabled>0</disabled>
        <displayType>input</displayType>
        <freeText>forbidden</freeText>
        <largeStorage>0</largeStorage>
        <multiSelect>1</multiSelect>
        <name>scope</name>
        <number>19</number>
        <prettyName>Scope</prettyName>
        <relationalStorage>0</relationalStorage>
        <separator>|</separator>
        <separators>|,</separators>
        <size>5</size>
        <unmodifiable>0</unmodifiable>
        <values/>
        <classType>com.xpn.xwiki.objects.classes.StaticListClass</classType>
      </scope>
      <skipped>
        <disabled>0</disabled>
        <displayFormType>select</displayFormType>
        <displayType>select</displayType>
        <name>skipped</name>
        <number>18</number>
        <prettyName>Is authentication skipped ?</prettyName>
        <unmodifiable>0</unmodifiable>
        <classType>com.xpn.xwiki.objects.classes.BooleanClass</classType>
      </skipped>
      <tokenEndpoint>
        <disabled>0</disabled>
        <name>tokenEndpoint</name>
        <number>8</number>
        <prettyName>Token OIDC endpoint</prettyName>
        <size>255</size>
        <unmodifiable>0</unmodifiable>
        <classType>com.xpn.xwiki.objects.classes.StringClass</classType>
      </tokenEndpoint>
      <tokenEndpointMethod>
        <disabled>0</disabled>
        <name>tokenEndpointMethod</name>
        <number>13</number>
        <prettyName>Token endpoint authentication method</prettyName>
        <size>255</size>
        <unmodifiable>0</unmodifiable>
        <classType>com.xpn.xwiki.objects.classes.StringClass</classType>
      </tokenEndpointMethod>
      <userInfoClaims>
        <cache>0</cache>
        <disabled>0</disabled>
        <displayType>input</displayType>
        <freeText>forbidden</freeText>
        <largeStorage>0</largeStorage>
        <multiSelect>1</multiSelect>
        <name>userInfoClaims</name>
        <number>21</number>
        <prettyName>User info Claims</prettyName>
        <relationalStorage>0</relationalStorage>
        <separator>|</separator>
        <separators>|,</separators>
        <size>5</size>
        <unmodifiable>0</unmodifiable>
        <values/>
        <classType>com.xpn.xwiki.objects.classes.StaticListClass</classType>
      </userInfoClaims>
      <userInfoEndpoint>
        <disabled>0</disabled>
        <name>userInfoEndpoint</name>
        <number>9</number>
        <prettyName>User info OIDC endpoint</prettyName>
        <size>255</size>
        <unmodifiable>0</unmodifiable>
        <classType>com.xpn.xwiki.objects.classes.StringClass</classType>
      </userInfoEndpoint>
      <userInfoEndpointHeaders>
        <cache>0</cache>
        <disabled>0</disabled>
        <displayType>input</displayType>
        <freeText>forbidden</freeText>
        <largeStorage>0</largeStorage>
        <multiSelect>1</multiSelect>
        <name>userInfoEndpointHeaders</name>
        <number>15</number>
        <prettyName>User info endpoint headers</prettyName>
        <relationalStorage>0</relationalStorage>
        <separator>|</separator>
        <separators>|,</separators>
        <size>5</size>
        <unmodifiable>0</unmodifiable>
        <values/>
        <classType>com.xpn.xwiki.objects.classes.StaticListClass</classType>
      </userInfoEndpointHeaders>
      <userInfoEndpointMethod>
        <disabled>0</disabled>
        <name>userInfoEndpointMethod</name>
        <number>14</number>
        <prettyName>User information endpoint method</prettyName>
        <size>255</size>
        <unmodifiable>0</unmodifiable>
        <classType>com.xpn.xwiki.objects.classes.StringClass</classType>
      </userInfoEndpointMethod>
      <userInfoRefreshRate>
        <disabled>0</disabled>
        <name>userInfoRefreshRate</name>
        <number>22</number>
        <numberType>integer</numberType>
        <prettyName>User info refresh rate</prettyName>
        <size>5</size>
        <unmodifiable>0</unmodifiable>
        <classType>com.xpn.xwiki.objects.classes.NumberClass</classType>
      </userInfoRefreshRate>
      <userMapping>
        <cache>0</cache>
        <disabled>0</disabled>
        <displayType>input</displayType>
        <freeText>forbidden</freeText>
        <largeStorage>0</largeStorage>
        <multiSelect>1</multiSelect>
        <name>userMapping</name>
        <number>5</number>
        <prettyName>User mapping</prettyName>
        <relationalStorage>0</relationalStorage>
        <separator>|</separator>
        <separators>|,</separators>
        <size>5</size>
        <unmodifiable>0</unmodifiable>
        <values/>
        <classType>com.xpn.xwiki.objects.classes.StaticListClass</classType>
      </userMapping>
      <userNameFormatter>
        <disabled>0</disabled>
        <name>userNameFormatter</name>
        <number>4</number>
        <prettyName>XWiki username formatter</prettyName>
        <size>255</size>
        <unmodifiable>0</unmodifiable>
        <classType>com.xpn.xwiki.objects.classes.StringClass</classType>
      </userNameFormatter>
      <userSubjectFormatter>
        <disabled>0</disabled>
        <name>userSubjectFormatter</name>
        <number>3</number>
        <prettyName>Subject formatter</prettyName>
        <size>255</size>
        <unmodifiable>0</unmodifiable>
        <classType>com.xpn.xwiki.objects.classes.StringClass</classType>
      </userSubjectFormatter>
      <xwikiProvider>
        <disabled>0</disabled>
        <name>xwikiProvider</name>
        <number>6</number>
        <prettyName>XWiki provider</prettyName>
        <size>255</size>
        <unmodifiable>0</unmodifiable>
        <classType>com.xpn.xwiki.objects.classes.StringClass</classType>
      </xwikiProvider>
    </class>
    <property>
      <authorizationEndpoint>https://accounts.google.com/o/oauth2/v2/auth</authorizationEndpoint>
    </property>
    <property>
      <clientId>xxx</clientId>
    </property>
    <property>
      <clientSecret>yyy</clientSecret>
    </property>
    <property>
      <configurationName>default</configurationName>
    </property>
    <property>
      <groupsClaim></groupsClaim>
    </property>
    <property>
      <idTokenClaims/>
    </property>
    <property>
      <logoutEndpoint>https://oauth2.googleapis.com/revoke</logoutEndpoint>
    </property>
    <property>
      <logoutEndpointMethod></logoutEndpointMethod>
    </property>
    <property>
      <logoutMechanism></logoutMechanism>
    </property>
    <property>
      <scope>
        <value>openid</value>
        <value>profile</value>
        <value>email</value>
      </scope>
    </property>
    <property>
      <skipped>0</skipped>
    </property>
    <property>
      <tokenEndpoint>https://oauth2.googleapis.com/token</tokenEndpoint>
    </property>
    <property>
      <tokenEndpointMethod></tokenEndpointMethod>
    </property>
    <property>
      <userInfoClaims/>
    </property>
    <property>
      <userInfoEndpoint>https://openidconnect.googleapis.com/v1/userinfo</userInfoEndpoint>
    </property>
    <property>
      <userInfoEndpointHeaders/>
    </property>
    <property>
      <userInfoEndpointMethod></userInfoEndpointMethod>
    </property>
    <property>
      <userInfoRefreshRate/>
    </property>
    <property>
      <userMapping/>
    </property>
    <property>
      <userNameFormatter>${oidc.user.email}</userNameFormatter>
    </property>
    <property>
      <userSubjectFormatter>${oidc.user.email}</userSubjectFormatter>
    </property>
    <property>
      <xwikiProvider></xwikiProvider>
    </property>
  </object>

This config works.

What did not work, as said, was to remove that xwiki page and instead insert the following into xwiki.properties:

oidc.endpoint.authorization=https://accounts.google.com/o/oauth2/v2/auth
oidc.clientid=xxx
oidc.secret=yyy
oidc.groups.claim=
oidc.idtokenclaims=
oidc.endpoint.logout=https://oauth2.googleapis.com/revoke
oidc.scope=openid,profile,email
oidc.endpoint.token=https://oauth2.googleapis.com/token
oidc.userinfoclaims=
oidc.endpoint.userinfo=https://openidconnect.googleapis.com/v1/userinfo
oidc.user.mapping=
oidc.user.nameFormater=${oidc.user.email}
oidc.user.subjectFormater=${oidc.user.email}

It would then send the custom claims, although they are set to NULL, filled in a rather meaningless way like {"id_token":{"":null},"userinfo":{"":null}}.
The parameters are the same as in the page object so the treatment must be different at some point. We also tried completely leaving out these claim params (like oidc.userinfoclaims) from the xwiki.properties, which did not change the result.

tmortagne · January 12, 2023, 10:59am

Any idea what is exactly sent when it works ?

Lukas · January 12, 2023, 12:25pm

We’re currently sending (as it works):

scope: openid+profile+email
claims: {}
response_type: code
etc

We believe that the problem with the claim generated from the xwiki.properties version (which does not work), which is (as posted already) {"id_token":{"":null},"userinfo":{"":null}}, is that Google expects a plain empty string here and no JSON substructure.

tmortagne · January 12, 2023, 12:49pm

{} is a JSON substructure, it’s an object with no fields.

Also, as I said in the other thread, OpenID Connect specification is quite explicit about the format of claims…

Anyway, I will try to understand why you have this behavior with your wiki configuration (it might suggest a bug in the way this property in gathered by the wiki configuration source) and see if I can think of something that make sense in terms of xwiki.properties configuration to reach that behavior as a workaround for yet another bad implementation of OIDC.

Lukas · January 12, 2023, 1:34pm

That’d be great.

As said, if we can be of any help (tests, logs) just let me know.

tmortagne · January 12, 2023, 1:55pm

And that user is already authenticated when you try, right ?

So I did find where this query is coming from (it’s used to find the document corresponding to the configured provider name for the wiki configuration, and this is never cached currently). But it’s supposed to be executed only a few times per authentication and when the user info refresh rate is reached (10 minutes by default).

It would be very interesting if you could (for an already authenticated user):

try to access something like https://mydomain/xwiki/bin/get/Main/WebHome to be sure only one HTTP request is executed (no web resource loaded for the UI) and see how many of those query you have
if it still gets tons of them or for every query below the refresh rate threshold it would be interesting to enable OIDC debug log to see what it’s doing (and hope full understand why), you could also add to debug log for package com.xpn.xwiki.user.impl.xwiki

Lukas · January 12, 2023, 4:29pm

Right.

Good idea. I receive the said SQL query about that class still 13-15 times (depending on whether I access the Main page in a subwiki or not) if I send one single GET.

If I view the page via a browser then the following requests are sent, according to the Tomcat localhost_access_log:

10.2.1.22 - - [12/Jan/2023:15:55:03 +0000] "GET /wiki/mysubwiki/view/Main HTTP/1.1" 200 54178
10.2.1.22 - - [12/Jan/2023:15:55:03 +0000] "GET /wiki/mysubwiki/ssx/XWiki/Mentions/MentionsMacro?language=en&docVersion=1.1 HTTP/1.1" 200 251
10.2.1.22 - - [12/Jan/2023:15:55:04 +0000] "GET /webjars/wiki%3Amysubwiki/xwiki-platform-tree-webjar/13.10.9/tree.min.css?evaluate=true HTTP/1.1" 200 31620
10.2.1.22 - - [12/Jan/2023:15:55:04 +0000] "GET /webjars/wiki%3Amysubwiki/xwiki-platform-tree-webjar/13.10.9/require-config.min.js?evaluate=true&minify=true HTTP/1.1" 200 449
10.2.1.22 - - [12/Jan/2023:15:55:04 +0000] "GET /wiki/mysubwiki/jsx/XWiki/Notifications/Code/Macro/NotificationsMacro?language=en&docVersion=1.1 HTTP/1.1" 200 9318
10.2.1.22 - - [12/Jan/2023:15:55:04 +0000] "GET /wiki/mysubwiki/get/Main/WebHome?xpage=xpart&vm=commentsinline.vm HTTP/1.1" 200 3549
10.2.1.22 - - [12/Jan/2023:15:55:04 +0000] "GET /rest/notifications/count?media=json&
10.2.1.22 - - [12/Jan/2023:15:55:04 +0000] "GET /wiki/mysubwiki/get/Main/WebHome?outputSyntax=plain&sheet=XWiki.ExportDocumentTree&filterHiddenDocuments=false&showAttachments=false&showTranslations=false&root=document%3Amysubwiki%3AMain.WebHome&showRoot=true&data=children&id=%23 HTTP/1.1" 200 589
10.2.1.22 - - [12/Jan/2023:15:55:04 +0000] "GET /wiki/mysubwiki/get/TourCode/TourJson?xpage=plain&outputSyntax=plain&tourDoc=Main.WebHome HTTP/1.1" 200 3283
10.2.1.22 - - [12/Jan/2023:15:55:04 +0000] "GET /webjars/wiki%3Amysubwiki/xwiki-platform-tree-webjar/13.10.9/require-config.min.js?evaluate=true HTTP/1.1" 200 449
10.2.1.22 - - [12/Jan/2023:15:55:04 +0000] "GET /wiki/mysubwiki/get/CKEditor/Translator?outputSyntax=plain&language=en&prefix=resourcePicker&key=attach.hint&key=doc.hint HTTP/1.1" 200 65
10.2.1.22 - - [12/Jan/2023:15:55:04 +0000] "GET /wiki/mysubwiki/get/CKEditor/Translator?outputSyntax=plain&language=en&prefix=resource&key=attach.label&key=attach.placeholder&key=data.label&key=doc.label&key=doc.placeholder&key=icon.label&key=mailto.label&key=mailto.placeholder&key=path.label&key=path.placeholder&key=unc.label&key=unc.placeholder&key=unknown.label&key=url.label&key=url.placeholder&key=user.label&key=user.placeholder HTTP/1.1" 200 516
10.2.1.22 - - [12/Jan/2023:15:55:05 +0000] "GET /webjars/wiki%3Amysubwiki/xwiki-platform-tree-webjar/13.10.9/finder.min.css?evaluate=true HTTP/1.1" 200 813
10.2.1.22 - - [12/Jan/2023:15:55:05 +0000] "GET /wiki/mysubwiki/get/Main/?xpage=editactions HTTP/1.1" 200 1749
10.2.1.22 - - [12/Jan/2023:15:55:05 +0000] "GET /webjars/wiki%3Amysubwiki/application-ckeditor-webjar/1.64.5/plugins/xwiki-localization/l10n.min.js HTTP/1.1" 200 513
10.2.1.22 - - [12/Jan/2023:15:55:05 +0000] "GET /webjars/wiki%3Amysubwiki/application-ckeditor-webjar/1.64.5/plugins/xwiki-resource/resourcePicker.min.css?evaluate=true HTTP/1.1" 200 1080
10.2.1.22 - - [12/Jan/2023:15:55:05 +0000] "GET /webjars/wiki%3Amysubwiki/application-ckeditor-webjar/1.64.5/plugins/xwiki-macro/macroWizard.min.css?evaluate=true HTTP/1.1" 200 3171

These are 15-20 requests. If each of these requests is processed concurrently and is individually leading to the need of checking the OIDC config then it appears logical that the amount of SQL statements asking for the ClientConfigurationClass can be estimated to ~ 15 x 15 ~ hundreds of times.

We’ll do that, might take a bit longer.

tmortagne · January 12, 2023, 5:45pm

OK so that’s really unexpected, definitely a good test trigger, it will be interesting to see what debug log has to say about what is happening there.

On my side, tomorrow (GMT+1 here), I’m going to try to reproduce the same thing as you locally (I don’t have much experience with the wiki configuration of OIDC) as it would be the best to not steal more of your time.

Lukas · January 13, 2023, 7:01am

Did several tests. Here is a typical output of the loggers after sending one single GET to the Main.WebHome, being logged in:

2023-01-13 06:31:03,151 [http-nio-8080-exec-3022 - http://mydomain.com/bin/get/Main/WebHome] INFO  x.x.u.i.x.XWikiAuthServiceImpl - User XWiki.myusername is authentified 
2023-01-13 06:31:03,151 [http-nio-8080-exec-3022 - http://mydomain.com/bin/get/Main/WebHome] DEBUG x.x.u.i.x.XWikiAuthServiceImpl - XWikiAuthServiceImpl.checkAuth(XWikiContext) took 0 milliseconds to run. 
2023-01-13 06:31:03,151 [http-nio-8080-exec-3022 - http://mydomain.com/bin/get/Main/WebHome] DEBUG .o.a.i.OIDCClientConfiguration - Session: EB5ED0831C93033E116A6D626DA90FB2 
2023-01-13 06:31:03,151 [http-nio-8080-exec-3022 - http://mydomain.com/bin/get/Main/WebHome] DEBUG .o.a.i.OIDCClientConfiguration - Session: EB5ED0831C93033E116A6D626DA90FB2 
2023-01-13 06:31:03,151 [http-nio-8080-exec-3022 - http://mydomain.com/bin/get/Main/WebHome] DEBUG .o.a.i.OIDCClientConfiguration - Session: EB5ED0831C93033E116A6D626DA90FB2 
2023-01-13 06:31:03,152 [http-nio-8080-exec-3022 - http://mydomain.com/bin/get/Main/WebHome] DEBUG .o.a.i.OIDCClientConfiguration - Session: EB5ED0831C93033E116A6D626DA90FB2 
2023-01-13 06:31:03,152 [http-nio-8080-exec-3022 - http://mydomain.com/bin/get/Main/WebHome] DEBUG .o.a.i.OIDCClientConfiguration - Session: EB5ED0831C93033E116A6D626DA90FB2 
2023-01-13 06:31:03,153 [http-nio-8080-exec-3022 - http://mydomain.com/bin/get/Main/WebHome] DEBUG .o.a.i.OIDCClientConfiguration - Session: EB5ED0831C93033E116A6D626DA90FB2 
2023-01-13 06:31:03,153 [http-nio-8080-exec-3022 - http://mydomain.com/bin/get/Main/WebHome] DEBUG .o.a.i.OIDCClientConfiguration - Session: EB5ED0831C93033E116A6D626DA90FB2 
2023-01-13 06:31:03,153 [http-nio-8080-exec-3022 - http://mydomain.com/bin/get/Main/WebHome] DEBUG .o.a.i.OIDCClientConfiguration - Session: EB5ED0831C93033E116A6D626DA90FB2 
2023-01-13 06:31:03,153 [http-nio-8080-exec-3022 - http://mydomain.com/bin/get/Main/WebHome] DEBUG .o.a.i.OIDCClientConfiguration - Session: EB5ED0831C93033E116A6D626DA90FB2 
2023-01-13 06:31:03,154 [pool-14-thread-1] DEBUG o.x.c.o.a.i.OIDCUserManager    - OIDC user info request (org.xwiki.contrib.oidc.auth.internal.Endpoint@30577388,ya29.a0AX9GBdVVQqaVTsRUY2-VmZxacNfC4fioLaLlA-8DeRoCyEkwxPsU_JUW-uPFieGvnUGbCEkz5tPFEZZTGpeQh83o0_5OJuGBB6uKnx2ZfrlmJw-EXINSvohunUyIGx9yas7UToFrC9aDQ04dNpZxhbdzPogYQ7IaCgYKAZcSARISFQHUCsbCvK5ceUL8Q-AmA9Aq2yBNPA0166) 
2023-01-13 06:31:03,155 [http-nio-8080-exec-3022 - http://mydomain.com/bin/get/Main/WebHome] DEBUG .o.a.i.OIDCClientConfiguration - Session: EB5ED0831C93033E116A6D626DA90FB2 
2023-01-13 06:31:03,161 [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.a0AX9GBdVVQqaVTsRUY2-VmZxacNfC4fioLaLlA-8DeRoCyEkwxPsU_JUW-uPFieGvnUGbCEkz5tPFEZZTGpeQh83o0_5OJuGBB6uKnx2ZfrlmJw-EXINSvohunUyIGx9yas7UToFrC9aDQ04dNpZxhbdzPogYQ7IaCgYKAZcSARISFQHUCsbCvK5ceUL8Q-AmA9Aq2yBNPA0166], User-Agent=[OpenID Connect Authenticator/1.32.1]}) 
2023-01-13 06:31:03,234 [http-nio-8080-exec-3018 - http://mydomain.com/favicon.ico] INFO  x.x.u.i.x.XWikiAuthServiceImpl - User XWiki.myusername is authentified 
2023-01-13 06:31:03,234 [http-nio-8080-exec-3018 - http://mydomain.com/favicon.ico] DEBUG x.x.u.i.x.XWikiAuthServiceImpl - XWikiAuthServiceImpl.checkAuth(XWikiContext) took 0 milliseconds to run. 
2023-01-13 06:31:03,234 [http-nio-8080-exec-3018 - http://mydomain.com/favicon.ico] DEBUG .o.a.i.OIDCClientConfiguration - Session: EB5ED0831C93033E116A6D626DA90FB2 
2023-01-13 06:31:03,234 [http-nio-8080-exec-3018 - http://mydomain.com/favicon.ico] DEBUG .o.a.i.OIDCClientConfiguration - Session: EB5ED0831C93033E116A6D626DA90FB2 
2023-01-13 06:31:03,234 [http-nio-8080-exec-3018 - http://mydomain.com/favicon.ico] DEBUG .o.a.i.OIDCClientConfiguration - Session: EB5ED0831C93033E116A6D626DA90FB2 
2023-01-13 06:31:03,236 [http-nio-8080-exec-3018 - http://mydomain.com/favicon.ico] DEBUG .o.a.i.OIDCClientConfiguration - Session: EB5ED0831C93033E116A6D626DA90FB2 
2023-01-13 06:31:03,236 [http-nio-8080-exec-3018 - http://mydomain.com/favicon.ico] DEBUG .o.a.i.OIDCClientConfiguration - Session: EB5ED0831C93033E116A6D626DA90FB2 
2023-01-13 06:31:03,237 [http-nio-8080-exec-3018 - http://mydomain.com/favicon.ico] DEBUG .o.a.i.OIDCClientConfiguration - Session: EB5ED0831C93033E116A6D626DA90FB2 
2023-01-13 06:31:03,237 [http-nio-8080-exec-3018 - http://mydomain.com/favicon.ico] DEBUG .o.a.i.OIDCClientConfiguration - Session: EB5ED0831C93033E116A6D626DA90FB2 
2023-01-13 06:31:03,237 [http-nio-8080-exec-3018 - http://mydomain.com/favicon.ico] DEBUG .o.a.i.OIDCClientConfiguration - Session: EB5ED0831C93033E116A6D626DA90FB2 
2023-01-13 06:31:03,237 [http-nio-8080-exec-3018 - http://mydomain.com/favicon.ico] DEBUG .o.a.i.OIDCClientConfiguration - Session: EB5ED0831C93033E116A6D626DA90FB2 
2023-01-13 06:31:03,238 [http-nio-8080-exec-3018 - http://mydomain.com/favicon.ico] DEBUG .o.a.i.OIDCClientConfiguration - Session: EB5ED0831C93033E116A6D626DA90FB2 
2023-01-13 06:31:03,299 [pool-14-thread-1] DEBUG o.x.c.o.a.i.OIDCUserManager    - OIDC user info response ({
  "error": "invalid_request",
  "error_description": "Invalid Credentials"
}
) 
2023-01-13 06:31:03,299 [pool-14-thread-1] ERROR o.x.c.o.a.i.OIDCUserManager    - Failed to update user informations 
org.xwiki.contrib.oidc.provider.internal.OIDCException: Failed to get user info:invalid_request
	at org.xwiki.contrib.oidc.auth.internal.OIDCUserManager.updateUserInfo(OIDCUserManager.java:190)
	at org.xwiki.contrib.oidc.auth.internal.OIDCUserManager.lambda$updateUserInfoAsync$0(OIDCUserManager.java:134)
	at org.xwiki.context.concurrent.ExecutionContextRunnable.run(ExecutionContextRunnable.java:71)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at java.base/java.lang.Thread.run(Unknown Source)
2023-01-13 06:31:03,299 [pool-14-thread-1] DEBUG o.x.c.o.a.i.OIDCUserManager    - OIDC user info request (org.xwiki.contrib.oidc.auth.internal.Endpoint@123a020b,ya29.a0AX9GBdVVQqaVTsRUY2-VmZxacNfC4fioLaLlA-8DeRoCyEkwxPsU_JUW-uPFieGvnUGbCEkz5tPFEZZTGpeQh83o0_5OJuGBB6uKnx2ZfrlmJw-EXINSvohunUyIGx9yas7UToFrC9aDQ04dNpZxhbdzPogYQ7IaCgYKAZcSARISFQHUCsbCvK5ceUL8Q-AmA9Aq2yBNPA0166) 
2023-01-13 06:31:03,301 [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.a0AX9GBdVVQqaVTsRUY2-VmZxacNfC4fioLaLlA-8DeRoCyEkwxPsU_JUW-uPFieGvnUGbCEkz5tPFEZZTGpeQh83o0_5OJuGBB6uKnx2ZfrlmJw-EXINSvohunUyIGx9yas7UToFrC9aDQ04dNpZxhbdzPogYQ7IaCgYKAZcSARISFQHUCsbCvK5ceUL8Q-AmA9Aq2yBNPA0166], User-Agent=[OpenID Connect Authenticator/1.32.1]}) 
2023-01-13 06:31:03,334 [pool-14-thread-1] DEBUG o.x.c.o.a.i.OIDCUserManager    - OIDC user info response ({
  "error": "invalid_request",
  "error_description": "Invalid Credentials"
}
) 
2023-01-13 06:31:03,334 [pool-14-thread-1] ERROR o.x.c.o.a.i.OIDCUserManager    - Failed to update user informations 
org.xwiki.contrib.oidc.provider.internal.OIDCException: Failed to get user info:invalid_request
	at org.xwiki.contrib.oidc.auth.internal.OIDCUserManager.updateUserInfo(OIDCUserManager.java:190)
	at org.xwiki.contrib.oidc.auth.internal.OIDCUserManager.lambda$updateUserInfoAsync$0(OIDCUserManager.java:134)
	at org.xwiki.context.concurrent.ExecutionContextRunnable.run(ExecutionContextRunnable.java:71)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at java.base/java.lang.Thread.run(Unknown Source)

This is the corresponding database log:

2023-01-13 06:31:03.151 GMT [32128] LOG:  execute <unnamed>: BEGIN
2023-01-13 06:31:03.151 GMT [32128] LOG:  execute <unnamed>: SET search_path TO "public"
2023-01-13 06:31:03.152 GMT [32128] LOG:  execute S_126: select baseobject0_.XWO_NAME as col_0_0_ from xwikiobjects baseobject0_ cross join xwikistrings stringprop1_ where baseobject0_.XWO_CLASSNAME=$1 and baseobject0_.XWO_ID=stringprop1_.XWS_ID and stringprop1_.XWS_NAME=$2 and stringprop1_.XWS_VALUE=$3
2023-01-13 06:31:03.152 GMT [32128] DETAIL:  parameters: $1 = 'XWiki.OIDC.ClientConfigurationClass', $2 = 'configurationName', $3 = 'default'
2023-01-13 06:31:03.152 GMT [32128] LOG:  execute S_123: ROLLBACK
2023-01-13 06:31:03.153 GMT [32128] LOG:  execute <unnamed>: BEGIN
2023-01-13 06:31:03.153 GMT [32128] LOG:  execute <unnamed>: SET search_path TO "public"
2023-01-13 06:31:03.153 GMT [32128] LOG:  execute S_126: select baseobject0_.XWO_NAME as col_0_0_ from xwikiobjects baseobject0_ cross join xwikistrings stringprop1_ where baseobject0_.XWO_CLASSNAME=$1 and baseobject0_.XWO_ID=stringprop1_.XWS_ID and stringprop1_.XWS_NAME=$2 and stringprop1_.XWS_VALUE=$3
2023-01-13 06:31:03.153 GMT [32128] DETAIL:  parameters: $1 = 'XWiki.OIDC.ClientConfigurationClass', $2 = 'configurationName', $3 = 'default'
2023-01-13 06:31:03.153 GMT [32128] LOG:  execute S_123: ROLLBACK
2023-01-13 06:31:03.154 GMT [32128] LOG:  execute <unnamed>: BEGIN
2023-01-13 06:31:03.154 GMT [32128] LOG:  execute <unnamed>: SET search_path TO "public"
2023-01-13 06:31:03.154 GMT [1892] LOG:  execute <unnamed>: BEGIN
2023-01-13 06:31:03.154 GMT [1892] LOG:  execute <unnamed>: SET search_path TO "public"
2023-01-13 06:31:03.154 GMT [32128] LOG:  execute S_126: select baseobject0_.XWO_NAME as col_0_0_ from xwikiobjects baseobject0_ cross join xwikistrings stringprop1_ where baseobject0_.XWO_CLASSNAME=$1 and baseobject0_.XWO_ID=stringprop1_.XWS_ID and stringprop1_.XWS_NAME=$2 and stringprop1_.XWS_VALUE=$3
2023-01-13 06:31:03.154 GMT [32128] DETAIL:  parameters: $1 = 'XWiki.OIDC.ClientConfigurationClass', $2 = 'configurationName', $3 = 'default'
2023-01-13 06:31:03.154 GMT [1892] LOG:  execute S_7: select baseobject0_.XWO_NAME as col_0_0_ from xwikiobjects baseobject0_ cross join xwikistrings stringprop1_ where baseobject0_.XWO_CLASSNAME=$1 and baseobject0_.XWO_ID=stringprop1_.XWS_ID and stringprop1_.XWS_NAME=$2 and stringprop1_.XWS_VALUE=$3
2023-01-13 06:31:03.154 GMT [1892] DETAIL:  parameters: $1 = 'XWiki.OIDC.ClientConfigurationClass', $2 = 'configurationName', $3 = 'default'
2023-01-13 06:31:03.155 GMT [32128] LOG:  execute S_123: ROLLBACK
2023-01-13 06:31:03.155 GMT [1892] LOG:  execute S_4: ROLLBACK
2023-01-13 06:31:03.235 GMT [1892] LOG:  execute <unnamed>: BEGIN
2023-01-13 06:31:03.235 GMT [1892] LOG:  execute <unnamed>: SET search_path TO "public"
2023-01-13 06:31:03.236 GMT [1892] LOG:  execute S_7: select baseobject0_.XWO_NAME as col_0_0_ from xwikiobjects baseobject0_ cross join xwikistrings stringprop1_ where baseobject0_.XWO_CLASSNAME=$1 and baseobject0_.XWO_ID=stringprop1_.XWS_ID and stringprop1_.XWS_NAME=$2 and stringprop1_.XWS_VALUE=$3
2023-01-13 06:31:03.236 GMT [1892] DETAIL:  parameters: $1 = 'XWiki.OIDC.ClientConfigurationClass', $2 = 'configurationName', $3 = 'default'
2023-01-13 06:31:03.236 GMT [1892] LOG:  execute S_4: ROLLBACK
2023-01-13 06:31:03.236 GMT [1892] LOG:  execute <unnamed>: BEGIN
2023-01-13 06:31:03.236 GMT [1892] LOG:  execute <unnamed>: SET search_path TO "public"
2023-01-13 06:31:03.237 GMT [1892] LOG:  execute S_7: select baseobject0_.XWO_NAME as col_0_0_ from xwikiobjects baseobject0_ cross join xwikistrings stringprop1_ where baseobject0_.XWO_CLASSNAME=$1 and baseobject0_.XWO_ID=stringprop1_.XWS_ID and stringprop1_.XWS_NAME=$2 and stringprop1_.XWS_VALUE=$3
2023-01-13 06:31:03.237 GMT [1892] DETAIL:  parameters: $1 = 'XWiki.OIDC.ClientConfigurationClass', $2 = 'configurationName', $3 = 'default'
2023-01-13 06:31:03.237 GMT [1892] LOG:  execute S_4: ROLLBACK
2023-01-13 06:31:03.238 GMT [1892] LOG:  execute <unnamed>: BEGIN
2023-01-13 06:31:03.238 GMT [1892] LOG:  execute <unnamed>: SET search_path TO "public"
2023-01-13 06:31:03.238 GMT [1892] LOG:  execute S_7: select baseobject0_.XWO_NAME as col_0_0_ from xwikiobjects baseobject0_ cross join xwikistrings stringprop1_ where baseobject0_.XWO_CLASSNAME=$1 and baseobject0_.XWO_ID=stringprop1_.XWS_ID and stringprop1_.XWS_NAME=$2 and stringprop1_.XWS_VALUE=$3
2023-01-13 06:31:03.238 GMT [1892] DETAIL:  parameters: $1 = 'XWiki.OIDC.ClientConfigurationClass', $2 = 'configurationName', $3 = 'default'
2023-01-13 06:31:03.238 GMT [1892] LOG:  execute S_4: ROLLBACK
2023-01-13 06:31:03.300 GMT [1892] LOG:  execute <unnamed>: BEGIN
2023-01-13 06:31:03.300 GMT [1892] LOG:  execute <unnamed>: SET search_path TO "public"
2023-01-13 06:31:03.301 GMT [1892] LOG:  execute S_7: select baseobject0_.XWO_NAME as col_0_0_ from xwikiobjects baseobject0_ cross join xwikistrings stringprop1_ where baseobject0_.XWO_CLASSNAME=$1 and baseobject0_.XWO_ID=stringprop1_.XWS_ID and stringprop1_.XWS_NAME=$2 and stringprop1_.XWS_VALUE=$3
2023-01-13 06:31:03.301 GMT [1892] DETAIL:  parameters: $1 = 'XWiki.OIDC.ClientConfigurationClass', $2 = 'configurationName', $3 = 'default'
2023-01-13 06:31:03.301 GMT [1892] LOG:  execute S_4: ROLLBACK

I must say I don’t really understand what’s going on. Apparently there’s a problem with “invalid credentials” but from the order of timestamps that seems to happen only at the end (but maybe the logging is just delayed / throttled here).

From the coincidence of timestamps between the xwiki and the DB log it is apparent that the SQL statement are each executed directly after log entries like
2023-01-13 06:31:03,153 [http-nio-8080-exec-3022 - http://mydomain.com/bin/get/Main/WebHome] DEBUG .o.a.i.OIDCClientConfiguration - Session: EB5ED0831C93033E116A6D626DA90FB2
Not sure what exactly causes this log entry. The session remains the same.

Two additional notes:

The amount of times the SQL is executed is only 8 now, reduced from the >15 I posted above. This is because previously there was a warning about deprecated usage of $velocityCount in a side panel which caused several additional log entries like 2023-01-13 05:10:28,621 [http-nio-8080-exec-2801 - http://mydomain.com/favicon.ico] WARN o.x.v.XWikiVelocityContext - Deprecated binding [$velocityCount] used in [xwiki:Panels.mySidePanel] to appear, causing additional executions of the database SQL. I’ve now replaced this by $foreach.count.
The error message about the “invalid credentials” does not always appear, but in most of the tests. But also without the error, the amount of SQL executions does not decrease.

That’d probably be best to see the full picture - I might be omitting crucial information here.

No problem. I’m glad for your quick and competent support.

tmortagne · January 19, 2023, 1:19pm

That part should be ok in the OIDC version 1.34.1 that I just released.

tmortagne · January 19, 2023, 1:39pm

So, I could not reproduce this. What happens for me at each request is that the authenticator is called, see there is already a user in the session, and returns it without the need to access the configuration at all.

I just added more debug log in a 1.34.2 version to get more detail on what exactly happen in the authenticator when you execute an HTTP request.

Lukas · January 20, 2023, 5:45am

Great, thanks, we’ll try.

As for the parameters, would you say our config posted here (at the end) is ok or should we better completely leave out the params which shall be NULL?