[keycloak-user] Enabling User Caching from Custom UserStorageProvider leads to MORE requests

[Rob Shepherd]

Hi,

I’m having trouble getting UserModel caching to work properly.  It seems like a bug. 

I have a successful implementation of a UserStorageProvider using HTTP/REST calls to fetch user data. This has been working well in trials. 

I have just enabled caching in the Realm > User Federation > Cache Settings > Cache Policy and selected a MAX_LIFESPAN time of 300’000ms (5mins)

I have found that for a test loop  (1. login, 2. delete app session cookie, 3. authenticate by SSO cookie) this leads to MORE requests to the backend.


Below is the logging output which demonstrates this.

My question:

Could this be a bug? 
or are there particular UserModel classes/interfaces that must be used to permit caching?

it seems like even for an object loaded in memory for a running thread/request it is not being found in the cache and lookup happens everytime the user object is required.




Here is the fetching and caching over that time…. with caching enabled first……

19:13:29,102 INFO  [org.me.MyCustomUserStorageProvider] (default task-32) UserStorageProvider#getUserByEmail(): r... at gmail.com 
19:13:34,637 INFO  [org.me.MyCustomUserStorageProvider] (default task-43) UserStorageProvider#getUserById(): f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df
19:13:34,706 INFO  [org.me.MyCustomUserStorageProvider] (default task-38) UserStorageProvider#getUserById(): f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df
19:13:34,746 INFO  [org.me.MyCustomUserStorageProvider] (default task-38) Caching for delegate: MyUserAdapter:f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df
19:13:34,754 INFO  [org.me.MyCustomUserStorageProvider] (default task-38) UserStorageProvider#getUserById(): f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df
19:13:34,783 INFO  [org.me.MyCustomUserStorageProvider] (default task-38) UserStorageProvider#getUserById(): f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df
19:13:37,454 INFO  [org.me.MyCustomUserStorageProvider] (default task-45) UserStorageProvider#getUserById(): f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df
19:13:37,496 INFO  [org.me.MyCustomUserStorageProvider] (default task-45) Caching for delegate: MyUserAdapter:f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df
19:13:37,501 INFO  [org.me.MyCustomUserStorageProvider] (default task-45) UserStorageProvider#getUserById(): f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df
19:13:37,540 INFO  [org.me.MyCustomUserStorageProvider] (default task-45) UserStorageProvider#getUserById(): f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df
19:13:37,570 INFO  [org.me.MyCustomUserStorageProvider] (default task-45) UserStorageProvider#getUserById(): f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df
19:13:37,605 INFO  [org.me.MyCustomUserStorageProvider] (default task-45) UserStorageProvider#getUserById(): f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df
19:13:37,631 INFO  [org.me.MyCustomUserStorageProvider] (default task-45) UserStorageProvider#getUserById(): f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df
19:13:37,661 INFO  [org.me.MyCustomUserStorageProvider] (default task-45) UserStorageProvider#getUserById(): f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df
19:13:37,689 INFO  [org.me.MyCustomUserStorageProvider] (default task-45) UserStorageProvider#getUserById(): f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df
19:13:37,714 INFO  [org.me.MyCustomUserStorageProvider] (default task-45) UserStorageProvider#getUserById(): f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df
19:13:37,751 INFO  [org.me.MyCustomUserStorageProvider] (default task-45) UserStorageProvider#getUserById(): f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df
19:13:37,832 INFO  [org.me.MyCustomUserStorageProvider] (default task-50) UserStorageProvider#getUserById(): f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df
19:13:37,882 INFO  [org.me.MyCustomUserStorageProvider] (default task-50) Caching for delegate: MyUserAdapter:f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df


That’s a total of 3 cache writes from 16 lookups for the same user in less than 1 minute, involving 3 requests to Keycloak in this session. 

And now with the cache turned off and the cache flushed…..

18:57:45,343 INFO  [org.me.MyCustomUserStorageProvider] (default task-58) UserStorageProvider#getUserByEmail(): r... at gmail.com 
18:57:45,534 INFO  [org.me.MyCustomUserStorageProvider] (default task-56) UserStorageProvider#getUserById(): f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df
18:57:45,662 INFO  [org.me.MyCustomUserStorageProvider] (default task-61) UserStorageProvider#getUserById(): f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df
18:57:56,208 INFO  [org.me.MyCustomUserStorageProvider] (default task-64) UserStorageProvider#getUserById(): f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df
18:57:56,270 INFO  [org.me.MyCustomUserStorageProvider] (default task-60) UserStorageProvider#getUserById(): f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df
18:58:01,186 INFO  [org.me.MyCustomUserStorageProvider] (default task-7) UserStorageProvider#getUserById(): f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df
18:58:01,265 INFO  [org.me.MyCustomUserStorageProvider] (default task-9) UserStorageProvider#getUserById(): f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df
18:58:01,354 INFO  [org.me.MyCustomUserStorageProvider] (default task-12) UserStorageProvider#getUserById(): f:d0c27624-05e4-4574-bc59-1911e9853917:5a04cf428c6bda1d05dbe0df

Thats a total of 8 lookups for the same user in less than 1 minute, involving 3 requests to Keycloak in this session.