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

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...(a)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...(a)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.