log cache activity with context

packages/server/app.ts

@@ -25,6 +25,7 @@ import {
 } from '@/logging/expressLogging'
 
 import { errorLoggingMiddleware } from '@/logging/errorLogging'
+import { redisLogger } from '@/logging/logging'
 import prometheusClient from 'prom-client'
 
 import { ApolloServer } from '@apollo/server'
@@ -474,7 +475,10 @@ export async function init() {
       authContextMiddlewareFactory({
         cache: redisCacheFactory({
           redis: getGenericRedis(),
-          options: { ttlMilliseconds: getCacheAuthPipelineTtlSeconds() * 1000 }
+          options: {
+            ttlMilliseconds: getCacheAuthPipelineTtlSeconds() * 1000,
+            logger: redisLogger
+          }
         })
       })
     )

packages/server/logging/requestContext.ts

@@ -2,6 +2,7 @@ import { REQUEST_ID_HEADER } from '@/logging/expressLogging'
 import { asyncRequestContextEnabled } from '@/modules/shared/helpers/envHelper'
 import type express from 'express'
 import { AsyncLocalStorage } from 'node:async_hooks'
+import type { Logger } from 'pino'
 
 type StorageType = {
   requestId: string
@@ -38,3 +39,15 @@ export const enterNewRequestContext = (params: { reqId: string }) => {
 }
 
 export const getRequestContext = () => storage?.getStore()
+
+export const maybeLoggerWithContext = ({ logger }: { logger?: Logger }) => {
+  const reqCtx = getRequestContext()
+  return logger?.child({
+    ...(reqCtx
+      ? {
+          req: { id: reqCtx.requestId },
+          dbMetrics: reqCtx.dbMetrics
+        }
+      : {})
+  })
+}

packages/server/modules/core/utils/redisCacheProvider.ts

@@ -1,23 +1,30 @@
 import type { Redis } from 'ioredis'
 import { CacheProvider } from '@/modules/core/utils/cacheHandler'
+import { Logger } from 'pino'
+import { maybeLoggerWithContext } from '@/logging/requestContext'
 
 export const redisCacheFactory = <T>(deps: {
   redis: Redis
-  options: { ttlMilliseconds: number }
+  options: { ttlMilliseconds: number; logger?: Logger }
 }): CacheProvider<T> => {
   const { redis } = deps
   return {
     get: async (key: string) => {
       const result = await redis.get(key)
-      return result ? (JSON.parse(result) as T) : undefined
+      const reqLogger = maybeLoggerWithContext({ logger: deps.options.logger })
+      if (result) {
+        reqLogger?.info(`Cache hit for key: '${key}'`)
+        return JSON.parse(result) as T
+      }
+
+      reqLogger?.info(`Cache miss for key: '${key}'`)
+      return undefined
     },
     set: async (key: string, value: T) => {
-      await redis.set(
-        key,
-        JSON.stringify(value),
-        'EX',
-        Math.floor(deps.options.ttlMilliseconds / 1000) // convert milliseconds to seconds
-      )
+      const reqLogger = maybeLoggerWithContext({ logger: deps.options.logger })
+      const ttl = Math.floor(deps.options.ttlMilliseconds / 1000) // convert milliseconds to seconds
+      reqLogger?.info(`Upserting cache for key: '${key}' with ttl: ${ttl}s`)
+      await redis.set(key, JSON.stringify(value), 'EX', ttl)
     }
   }
 }