search

UserOfficeProject / issue-tracker

Shared place for features and bugs from all collaborators.
0 stars 0 forks source link

Check datasource/cache initialisation in STFC mode #1188

Closed ACLay closed 1 month ago

ACLay commented 1 month ago

What is the problem and why is it a problem

In STFC we use an external service as our source of users. To improve performance we cache responses from that service within our users data source, and we log statistics from those caches to enable performance monitoring.

This afternoon I noticed that we seem to be logging results from 6 versions of each cache present in that datasource. This behaviour exists on our dev environment, as well as prod which is running version 7.1.1.

If we have multiple instances of the cache/datasource, then we're potentially losing some of the benefits of the cache, as user requests made or checked against different caches could result in duplicate requests to the external source being performed.

Oddly, this does not seem to affect the uowsTokenCache used in StfcUserAuthorization.ts, which only logs for one instance.

Sample cache stats:

[2024-10-10T15:02:11.478Z] INFO - Cache statistics for the last 300 seconds
 {"cache":"uowsBasicUserDetailsCache","stats":{"hits":0,"misses":0,"additions":0,"updates":0,"removals":0,"entries":0,"maxEntries":1000},"loggingFrequencySeconds":300}
[2024-10-10T15:02:11.478Z] INFO - Cache statistics for the last 300 seconds
 {"cache":"uowsSearchableBasicUserDetailsCache","stats":{"hits":0,"misses":0,"additions":0,"updates":0,"removals":0,"entries":0,"maxEntries":1000},"loggingFrequencySeconds":300}
[2024-10-10T15:02:11.478Z] INFO - Cache statistics for the last 300 seconds
 {"cache":"uowsRolesCache","stats":{"hits":0,"misses":0,"additions":0,"updates":0,"removals":0,"entries":0,"maxEntries":1000},"loggingFrequencySeconds":300}
[2024-10-10T15:02:11.478Z] INFO - Cache statistics for the last 300 seconds
 {"cache":"uowsBasicUserDetailsCache","stats":{"hits":1055,"misses":24,"additions":0,"updates":0,"removals":0,"entries":0,"maxEntries":1000},"loggingFrequencySeconds":300}
[2024-10-10T15:02:11.478Z] INFO - Cache statistics for the last 300 seconds
 {"cache":"uowsSearchableBasicUserDetailsCache","stats":{"hits":0,"misses":0,"additions":0,"updates":0,"removals":0,"entries":0,"maxEntries":1000},"loggingFrequencySeconds":300}
[2024-10-10T15:02:11.478Z] INFO - Cache statistics for the last 300 seconds
 {"cache":"uowsRolesCache","stats":{"hits":0,"misses":0,"additions":0,"updates":0,"removals":0,"entries":0,"maxEntries":1000},"loggingFrequencySeconds":300}
[2024-10-10T15:02:11.478Z] INFO - Cache statistics for the last 300 seconds
 {"cache":"uowsBasicUserDetailsCache","stats":{"hits":0,"misses":0,"additions":0,"updates":0,"removals":0,"entries":9,"maxEntries":1000},"loggingFrequencySeconds":300}
[2024-10-10T15:02:11.478Z] INFO - Cache statistics for the last 300 seconds
 {"cache":"uowsSearchableBasicUserDetailsCache","stats":{"hits":0,"misses":0,"additions":0,"updates":0,"removals":0,"entries":0,"maxEntries":1000},"loggingFrequencySeconds":300}
[2024-10-10T15:02:11.478Z] INFO - Cache statistics for the last 300 seconds
 {"cache":"uowsRolesCache","stats":{"hits":0,"misses":0,"additions":0,"updates":0,"removals":0,"entries":0,"maxEntries":1000},"loggingFrequencySeconds":300}
[2024-10-10T15:02:11.478Z] INFO - Cache statistics for the last 300 seconds
 {"cache":"uowsBasicUserDetailsCache","stats":{"hits":0,"misses":0,"additions":0,"updates":0,"removals":0,"entries":0,"maxEntries":1000},"loggingFrequencySeconds":300}
[2024-10-10T15:02:11.478Z] INFO - Cache statistics for the last 300 seconds
 {"cache":"uowsSearchableBasicUserDetailsCache","stats":{"hits":0,"misses":0,"additions":0,"updates":0,"removals":0,"entries":0,"maxEntries":1000},"loggingFrequencySeconds":300}
[2024-10-10T15:02:11.478Z] INFO - Cache statistics for the last 300 seconds
 {"cache":"uowsRolesCache","stats":{"hits":0,"misses":0,"additions":0,"updates":0,"removals":0,"entries":0,"maxEntries":1000},"loggingFrequencySeconds":300}
[2024-10-10T15:02:11.794Z] INFO - Cache statistics for the last 300 seconds
 {"cache":"uowsBasicUserDetailsCache","stats":{"hits":0,"misses":0,"additions":0,"updates":0,"removals":0,"entries":0,"maxEntries":1000},"loggingFrequencySeconds":300}
[2024-10-10T15:02:11.794Z] INFO - Cache statistics for the last 300 seconds
 {"cache":"uowsSearchableBasicUserDetailsCache","stats":{"hits":0,"misses":0,"additions":0,"updates":0,"removals":0,"entries":0,"maxEntries":1000},"loggingFrequencySeconds":300}
[2024-10-10T15:02:11.794Z] INFO - Cache statistics for the last 300 seconds
 {"cache":"uowsRolesCache","stats":{"hits":0,"misses":0,"additions":0,"updates":0,"removals":0,"entries":0,"maxEntries":1000},"loggingFrequencySeconds":300}
[2024-10-10T15:02:11.983Z] INFO - Cache statistics for the last 300 seconds
 {"cache":"uowsBasicUserDetailsCache","stats":{"hits":180,"misses":97,"additions":65,"updates":0,"removals":0,"entries":193,"maxEntries":1000},"loggingFrequencySeconds":300}
[2024-10-10T15:02:11.984Z] INFO - Cache statistics for the last 300 seconds
 {"cache":"uowsSearchableBasicUserDetailsCache","stats":{"hits":0,"misses":0,"additions":0,"updates":0,"removals":0,"entries":0,"maxEntries":1000},"loggingFrequencySeconds":300}
[2024-10-10T15:02:11.985Z] INFO - Cache statistics for the last 300 seconds
 {"cache":"uowsRolesCache","stats":{"hits":2,"misses":0,"additions":0,"updates":0,"removals":0,"entries":0,"maxEntries":1000},"loggingFrequencySeconds":300}
[2024-10-10T15:02:11.985Z] INFO - Cache statistics for the last 300 seconds
 {"cache":"uowsTokenCache","stats":{"hits":21,"misses":0,"additions":0,"updates":0,"removals":0,"entries":0,"maxEntries":1000},"loggingFrequencySeconds":300}

Steps to reproduce (if it's a bug).