From be3430a4848470ac2ad59be0c2af1a6f4538f95e Mon Sep 17 00:00:00 2001 From: Alaka-ibr Date: Sun, 23 Aug 2026 22:10:54 +0100 Subject: [PATCH] fix(cache): add structured debug log for each cache eviction (#737) Emit a debug-level structured log on every in-memory cache eviction with the fields required by the acceptance criteria: - cache_key: the evicted entry's key - reason: 'ttl_expired' or 'capacity_overflow' - cache_size_after: map size read after the delete call - evicted_at: ISO 8601 timestamp at eviction time The stale-on-read path in getCachedCreatorList is a TTL expiry variant and now logs with reason 'ttl_expired' instead of the previous 'stale'. The delete is performed before the log call so cache_size_after reflects the post-eviction size as specified. --- .../creators-cache-eviction-log.test.ts | 180 ++++++++++++++++++ src/modules/creators/creators.cache.ts | 30 +-- 2 files changed, 195 insertions(+), 15 deletions(-) create mode 100644 src/modules/creators/creators-cache-eviction-log.test.ts diff --git a/src/modules/creators/creators-cache-eviction-log.test.ts b/src/modules/creators/creators-cache-eviction-log.test.ts new file mode 100644 index 0000000..55bc9a3 --- /dev/null +++ b/src/modules/creators/creators-cache-eviction-log.test.ts @@ -0,0 +1,180 @@ +import { + getCachedCreatorList, + setCachedCreatorList, + resetCreatorListCache, +} from './creators.cache'; +import { logger } from '../../utils/logger.utils'; + +jest.mock('../../utils/logger.utils', () => ({ + logger: { + debug: jest.fn(), + info: jest.fn(), + warn: jest.fn(), + error: jest.fn(), + isLevelEnabled: jest.fn().mockReturnValue(true), + }, +})); + +jest.mock('../../constants/creator-public-cache.constants', () => ({ + CREATOR_PUBLIC_ROUTE_CACHE_MAX_AGE_SECONDS: { publicRead: 60 }, +})); + +const mockLogger = logger as unknown as { + debug: jest.Mock; +}; + +const BASE_QUERY = { + limit: 20, + offset: 0, + sort: 'createdAt' as const, + order: 'desc' as const, + include: [] as never[], +}; + +function findEvictionCalls(): Record[] { + return mockLogger.debug.mock.calls + .map((args: unknown[]) => args[0] as Record) + .filter( + (obj: Record) => + obj.event === 'creator_list_cache_eviction' + ); +} + +describe('cache eviction structured log (#737)', () => { + beforeEach(() => { + jest.clearAllMocks(); + resetCreatorListCache(); + }); + + describe('TTL expiry', () => { + it('emits a debug log with reason ttl_expired when a stale entry is read', () => { + setCachedCreatorList(BASE_QUERY as any, [], 0); + + jest.spyOn(Date, 'now').mockReturnValue(Date.now() + 120_000); + + getCachedCreatorList(BASE_QUERY as any); + + const evictions = findEvictionCalls(); + const ttlEviction = evictions.find( + (e) => e.reason === 'ttl_expired' + ); + + expect(ttlEviction).toBeDefined(); + expect(ttlEviction).toHaveProperty('cache_key'); + expect(ttlEviction).toHaveProperty('reason', 'ttl_expired'); + expect(ttlEviction).toHaveProperty('cache_size_after'); + expect(ttlEviction).toHaveProperty('evicted_at'); + + jest.restoreAllMocks(); + }); + + it('cache_size_after reflects the size after eviction', () => { + setCachedCreatorList(BASE_QUERY as any, [], 0); + + jest.spyOn(Date, 'now').mockReturnValue(Date.now() + 120_000); + + getCachedCreatorList(BASE_QUERY as any); + + const evictions = findEvictionCalls(); + const ttlEviction = evictions.find( + (e) => e.reason === 'ttl_expired' + ); + + expect(ttlEviction!.cache_size_after).toBe(0); + + jest.restoreAllMocks(); + }); + + it('evicted_at is a valid ISO 8601 timestamp', () => { + setCachedCreatorList(BASE_QUERY as any, [], 0); + + jest.spyOn(Date, 'now').mockReturnValue(Date.now() + 120_000); + + getCachedCreatorList(BASE_QUERY as any); + + const evictions = findEvictionCalls(); + const ttlEviction = evictions.find( + (e) => e.reason === 'ttl_expired' + ); + const parsed = new Date(ttlEviction!.evicted_at as string); + + expect(parsed.toISOString()).toBe(ttlEviction!.evicted_at); + + jest.restoreAllMocks(); + }); + + it('log level is debug', () => { + setCachedCreatorList(BASE_QUERY as any, [], 0); + + jest.spyOn(Date, 'now').mockReturnValue(Date.now() + 120_000); + + getCachedCreatorList(BASE_QUERY as any); + + const evictions = findEvictionCalls(); + + expect(evictions.length).toBeGreaterThanOrEqual(1); + expect(mockLogger.debug).toHaveBeenCalled(); + + jest.restoreAllMocks(); + }); + }); + + describe('capacity overflow', () => { + it('emits a debug log with reason capacity_overflow when the cache exceeds max entries', () => { + for (let i = 0; i < 252; i++) { + const query = { ...BASE_QUERY, offset: i }; + setCachedCreatorList(query as any, [], 0); + } + + const evictions = findEvictionCalls(); + const overflowEviction = evictions.find( + (e) => e.reason === 'capacity_overflow' + ); + + expect(overflowEviction).toBeDefined(); + expect(overflowEviction).toHaveProperty('cache_key'); + expect(overflowEviction).toHaveProperty( + 'reason', + 'capacity_overflow' + ); + expect(overflowEviction).toHaveProperty('cache_size_after'); + expect(overflowEviction).toHaveProperty('evicted_at'); + }); + + it('cache_size_after reflects the size after the overflow eviction', () => { + for (let i = 0; i < 252; i++) { + const query = { ...BASE_QUERY, offset: i }; + setCachedCreatorList(query as any, [], 0); + } + + const evictions = findEvictionCalls(); + const overflowEvictions = evictions.filter( + (e) => e.reason === 'capacity_overflow' + ); + + for (const eviction of overflowEvictions) { + expect( + typeof eviction.cache_size_after === 'number' + ).toBe(true); + expect( + (eviction.cache_size_after as number) <= 250 + ).toBe(true); + } + }); + + it('evicted_at is a valid ISO 8601 timestamp on overflow eviction', () => { + for (let i = 0; i < 252; i++) { + const query = { ...BASE_QUERY, offset: i }; + setCachedCreatorList(query as any, [], 0); + } + + const evictions = findEvictionCalls(); + const overflowEviction = evictions.find( + (e) => e.reason === 'capacity_overflow' + ); + const parsed = new Date(overflowEviction!.evicted_at as string); + + expect(parsed.toISOString()).toBe(overflowEviction!.evicted_at); + }); + }); +}); diff --git a/src/modules/creators/creators.cache.ts b/src/modules/creators/creators.cache.ts index 06fad63..5302ad8 100644 --- a/src/modules/creators/creators.cache.ts +++ b/src/modules/creators/creators.cache.ts @@ -29,15 +29,15 @@ function getCreatorListCacheTtlMs(): number { function pruneCreatorListCache(now: number): void { for (const [cacheKey, entry] of creatorListCache.entries()) { if (entry.expiresAt <= now) { + creatorListCache.delete(cacheKey); logger.debug({ msg: 'Creator list cache eviction', event: 'creator_list_cache_eviction', - cacheKey, - reason: 'expired', - expiresAt: entry.expiresAt, - now, + cache_key: cacheKey, + reason: 'ttl_expired', + cache_size_after: creatorListCache.size, + evicted_at: new Date(now).toISOString(), }); - creatorListCache.delete(cacheKey); } } @@ -51,15 +51,15 @@ function pruneCreatorListCache(now: number): void { .slice(0, overflow); for (const [cacheKey] of oldestEntries) { + creatorListCache.delete(cacheKey); logger.debug({ msg: 'Creator list cache eviction', event: 'creator_list_cache_eviction', - cacheKey, - reason: 'overflow', - cacheSize: creatorListCache.size, - maxSize: MAX_CREATOR_LIST_CACHE_ENTRIES, + cache_key: cacheKey, + reason: 'capacity_overflow', + cache_size_after: creatorListCache.size, + evicted_at: new Date(now).toISOString(), }); - creatorListCache.delete(cacheKey); } } @@ -117,15 +117,15 @@ export function getCachedCreatorList( } if (cachedEntry) { + creatorListCache.delete(cacheKey); logger.debug({ msg: 'Creator list cache eviction', event: 'creator_list_cache_eviction', - cacheKey, - reason: 'stale', - expiresAt: cachedEntry.expiresAt, - now, + cache_key: cacheKey, + reason: 'ttl_expired', + cache_size_after: creatorListCache.size, + evicted_at: new Date(now).toISOString(), }); - creatorListCache.delete(cacheKey); } pruneCreatorListCache(now);