feat: rework logging system

Author: Julien-R44

benchmarks/package.json

@@ -9,7 +9,7 @@
   "keywords": [],
   "main": "index.js",
   "scripts": {
-    "test": "echo \"Error: no test specified\" && exit 1"
+    "bench:all": "pnpm tsx all.ts"
   },
   "devDependencies": {
     "@keyv/redis": "^4.2.0",

packages/bentocache/src/bento_cache.ts

@@ -70,7 +70,7 @@ export class BentoCache<KnownCaches extends Record<string, BentoStore>> implemen
       busOptions: entry.bus?.options,
     })
 
-    return new Cache(cacheName, cacheStack, this.#options)
+    return new Cache(cacheName, cacheStack)
   }
 
   get defaultStoreName() {

packages/bentocache/src/cache/cache.ts

@@ -28,11 +28,11 @@ export class Cache implements CacheProvider {
   #stack: CacheStack
   #options: BentoCacheOptions
 
-  constructor(name: string, stack: CacheStack, options: BentoCacheOptions) {
+  constructor(name: string, stack: CacheStack) {
     this.name = name
 
     this.#stack = stack
-    this.#options = options
+    this.#options = stack.options
     this.#getSetHandler = new GetSetHandler(this.#stack)
   }
 
@@ -44,7 +44,7 @@ export class Cache implements CacheProvider {
    * Returns a new instance of the driver namespaced
    */
   namespace(namespace: string) {
-    return new Cache(this.name, this.#stack.namespace(namespace), this.#options)
+    return new Cache(this.name, this.#stack.namespace(namespace))
   }
 
   get<T = any>(options: GetOptions<T>): Promise<T>
@@ -56,32 +56,32 @@ export class Cache implements CacheProvider {
     this.#options.logger.logMethod({ method: 'get', key, options, cacheName: this.name })
 
     const localItem = this.#stack.l1?.get(key, options)
-    if (localItem !== undefined && !localItem.isLogicallyExpired()) {
-      this.#stack.emit(cacheEvents.hit(key, localItem.getValue(), this.name))
+    if (localItem?.isGraced === false) {
+      this.#stack.emit(cacheEvents.hit(key, localItem.entry.getValue(), this.name))
       this.#options.logger.logL1Hit({ cacheName: this.name, key, options })
-      return localItem.getValue()
+      return localItem.entry.getValue()
     }
 
     const remoteItem = await this.#stack.l2?.get(key, options)
 
-    if (remoteItem !== undefined && !remoteItem.isLogicallyExpired()) {
-      this.#stack.l1?.set(key, remoteItem.serialize(), options)
-      this.#stack.emit(cacheEvents.hit(key, remoteItem.getValue(), this.name))
+    if (remoteItem?.isGraced === false) {
+      this.#stack.l1?.set(key, remoteItem.entry.serialize(), options)
+      this.#stack.emit(cacheEvents.hit(key, remoteItem.entry.getValue(), this.name))
       this.#options.logger.logL2Hit({ cacheName: this.name, key, options })
-      return remoteItem.getValue()
+      return remoteItem.entry.getValue()
     }
 
     if (remoteItem && options.isGraceEnabled()) {
-      this.#stack.l1?.set(key, remoteItem.serialize(), options)
-      this.#stack.emit(cacheEvents.hit(key, remoteItem.serialize(), this.name, true))
+      this.#stack.l1?.set(key, remoteItem.entry.serialize(), options)
+      this.#stack.emit(cacheEvents.hit(key, remoteItem.entry.serialize(), this.name, true))
       this.#options.logger.logL2Hit({ cacheName: this.name, key, options, graced: true })
-      return remoteItem.getValue()
+      return remoteItem.entry.getValue()
     }
 
     if (localItem && options.isGraceEnabled()) {
-      this.#stack.emit(cacheEvents.hit(key, localItem.serialize(), this.name, true))
+      this.#stack.emit(cacheEvents.hit(key, localItem.entry.serialize(), this.name, true))
       this.#options.logger.logL1Hit({ cacheName: this.name, key, options, graced: true })
-      return localItem.getValue()
+      return localItem.entry.getValue()
     }
 
     this.#stack.emit(cacheEvents.miss(key, this.name))

packages/bentocache/src/cache/facades/local_cache.ts

@@ -15,7 +15,7 @@ export class LocalCache {
   constructor(driver: L1CacheDriver, logger: Logger, serializer: CacheSerializer | undefined) {
     this.#driver = driver
     this.#serializer = serializer
-    this.#logger = logger.child({ context: 'bentocache.localCache' })
+    this.#logger = logger.child({ layer: 'l1' })
   }
 
   /**
@@ -25,18 +25,26 @@ export class LocalCache {
     /**
      * Try to get the item from the local cache
      */
-    this.#logger.trace({ key, opId: options.id }, 'try getting local cache item')
+    this.#logger.trace({ key, opId: options.id }, 'try getting from l1 cache')
     const value = this.#driver.get(key)
 
     /**
      * If the item is not found, return undefined
      */
     if (value === undefined) {
-      this.#logger.trace({ key, opId: options.id }, 'local cache item not found')
+      this.#logger.debug({ key, opId: options.id }, 'cache miss')
       return
     }
 
-    return CacheEntry.fromDriver(key, value, this.#serializer)
+    const entry = CacheEntry.fromDriver(key, value, this.#serializer)
+    const isGraced = entry.isLogicallyExpired()
+    if (isGraced) {
+      this.#logger.debug({ key, opId: options.id }, 'cache hit (graced)')
+    } else {
+      this.#logger.debug({ key, opId: options.id }, 'cache hit')
+    }
+
+    return { entry, isGraced }
   }
 
   /**
@@ -54,15 +62,15 @@ export class LocalCache {
     /**
      * Save the item to the local cache
      */
-    this.#logger.trace({ key, value, opId: options.id }, 'saving local cache item')
+    this.#logger.debug({ key, opId: options.id }, 'saving item')
     this.#driver.set(key, value, physicalTtl)
   }
 
   /**
    * Delete an item from the local cache
    */
   delete(key: string, options?: CacheEntryOptions) {
-    this.#logger.trace({ key, opId: options?.id }, 'deleting local cache item')
+    this.#logger.debug({ key, opId: options?.id }, 'deleting item')
     return this.#driver.delete(key)
   }
 
@@ -74,7 +82,7 @@ export class LocalCache {
    * is down and the grace period is enabled
    */
   logicallyExpire(key: string) {
-    this.#logger.trace({ key }, 'logically expiring local cache item')
+    this.#logger.debug({ key }, 'logically expiring item')
 
     const value = this.#driver.get(key)
     if (value === undefined) return
@@ -87,7 +95,7 @@ export class LocalCache {
    * Delete many item from the local cache
    */
   deleteMany(keys: string[], options: CacheEntryOptions) {
-    this.#logger.trace({ keys, options, opId: options.id }, 'deleting local cache items')
+    this.#logger.debug({ keys, options, opId: options.id }, 'deleting items')
     this.#driver.deleteMany(keys)
   }
 

packages/bentocache/src/cache/facades/remote_cache.ts

@@ -31,22 +31,22 @@ export class RemoteCache {
       ? new CircuitBreaker({ breakDuration: options.l2CircuitBreakerDuration })
       : undefined
 
-    this.#logger = logger.child({ context: 'bentocache.remoteCache' })
+    this.#logger = logger.child({ layer: 'l2' })
   }
 
   /**
    * Try to execute a cache operation and fallback to a default value
    * if the operation fails
    */
-  async #tryCacheOperation(
+  async #tryCacheOperation<T>(
     operation: string,
     options: CacheEntryOptions,
     fallbackValue: unknown,
-    fn: () => any,
-  ) {
+    fn: () => T,
+  ): Promise<T> {
     if (this.#circuitBreaker?.isOpen()) {
       this.#logger.error({ opId: options.id }, `circuit breaker is open. ignoring operation`)
-      return fallbackValue
+      return fallbackValue as any
     }
 
     try {
@@ -64,7 +64,7 @@ export class RemoteCache {
         (is.undefined(options.suppressL2Errors) && this.#hasL1Backup) ||
         options.suppressL2Errors
       ) {
-        return fallbackValue
+        return fallbackValue as any
       }
 
       throw error
@@ -79,7 +79,15 @@ export class RemoteCache {
       const value = await this.#driver.get(key)
       if (value === undefined) return
 
-      return CacheEntry.fromDriver(key, value, this.#options.serializer)
+      const entry = CacheEntry.fromDriver(key, value, this.#options.serializer)
+      const isGraced = entry.isLogicallyExpired()
+      if (isGraced) {
+        this.#logger.debug({ key, opId: options.id }, 'cache hit (graced)')
+      } else {
+        this.#logger.debug({ key, opId: options.id }, 'cache hit')
+      }
+
+      return { entry, isGraced }
     })
   }
 
@@ -88,6 +96,7 @@ export class RemoteCache {
    */
   async set(key: string, value: string, options: CacheEntryOptions) {
     return await this.#tryCacheOperation('set', options, false, async () => {
+      this.#logger.debug({ key, opId: options.id }, 'saving item')
       await this.#driver.set(key, value, options.getPhysicalTtl())
       return true
     })
@@ -98,6 +107,7 @@ export class RemoteCache {
    */
   async delete(key: string, options: CacheEntryOptions) {
     return await this.#tryCacheOperation('delete', options, false, async () => {
+      this.#logger.debug({ key, opId: options.id }, 'deleting item')
       return await this.#driver.delete(key)
     })
   }
@@ -107,6 +117,7 @@ export class RemoteCache {
    */
   async deleteMany(keys: string[], options: CacheEntryOptions) {
     return await this.#tryCacheOperation('deleteMany', options, false, async () => {
+      this.#logger.debug({ keys, opId: options.id }, 'deleting items')
       return await this.#driver.deleteMany(keys)
     })
   }

packages/bentocache/src/cache/factory_runner.ts

@@ -38,9 +38,14 @@ export class FactoryRunner {
 
       if (result === this.#skipSymbol) return
 
+      this.#stack.logger.info({ cache: this.#stack.name, opId: options.id, key }, 'factory success')
       await this.#stack.set(key, result, options)
       return result
     } catch (error) {
+      this.#stack.logger.warn(
+        { cache: this.#stack.name, opId: options.id, key, error },
+        'factory failed',
+      )
       options.onFactoryError?.(new errors.E_FACTORY_ERROR(key, error, isBackground))
 
       if (!isBackground) throw new errors.E_FACTORY_ERROR(key, error)
@@ -57,6 +62,14 @@ export class FactoryRunner {
     lockReleaser: MutexInterface.Releaser,
   ) {
     const timeout = options.factoryTimeout(hasFallback)
+    if (timeout) {
+      this.#stack.logger.info(
+        { cache: this.#stack.name, opId: options.id, key },
+        `running factory with ${timeout.type} timeout of ${timeout.duration}ms`,
+      )
+    } else {
+      this.#stack.logger.info({ cache: this.#stack.name, opId: options.id, key }, 'running factory')
+    }
 
     /**
      * If the timeout is 0, we will not wait for the factory to resolve
@@ -71,6 +84,10 @@ export class FactoryRunner {
     const result = await pTimeout(runFactory, {
       milliseconds: timeout?.duration ?? Number.POSITIVE_INFINITY,
       fallback: async () => {
+        this.#stack.logger.warn(
+          { cache: this.#stack.name, opId: options.id, key },
+          `factory timed out after ${timeout?.duration}ms`,
+        )
         throw new timeout!.exception(key)
       },
     })

packages/bentocache/src/cache/get_set/single_tier_handler.ts

@@ -7,7 +7,7 @@ import { FactoryRunner } from '../factory_runner.js'
 import type { Factory } from '../../types/helpers.js'
 import type { CacheEvent } from '../../types/events.js'
 import { cacheEvents } from '../../events/cache_events.js'
-import type { CacheEntry } from '../cache_entry/cache_entry.js'
+import type { GetCacheValueReturn } from '../../types/internals/index.js'
 import type { CacheEntryOptions } from '../cache_entry/cache_entry_options.js'
 
 export class SingleTierHandler {
@@ -35,11 +35,15 @@ export class SingleTierHandler {
   /**
    * Returns a value from the remote cache and emit a CacheHit event
    */
-  async #returnRemoteCacheValue(key: string, item: CacheEntry, options: CacheEntryOptions) {
-    this.logger.trace({ key, cache: this.stack.name, opId: options.id }, 'remote cache hit')
+  async #returnRemoteCacheValue(
+    key: string,
+    item: GetCacheValueReturn,
+    options: CacheEntryOptions,
+  ) {
+    this.logger.logL2Hit({ cacheName: this.stack.name, key, options })
 
-    this.#emit(cacheEvents.hit(key, item.getValue(), this.stack.name))
-    return item.getValue()
+    this.#emit(cacheEvents.hit(key, item.entry.getValue(), this.stack.name))
+    return item.entry.getValue()
   }
 
   /**
@@ -55,27 +59,21 @@ export class SingleTierHandler {
 
   #returnGracedValueOrThrow(
     key: string,
-    item: CacheEntry | undefined,
+    item: GetCacheValueReturn | undefined,
     options: CacheEntryOptions,
     err: Error,
   ) {
     if (options.isGraceEnabled() && item) {
-      const isLogicallyExpired = item.isLogicallyExpired()
-      this.#emit(cacheEvents.hit(key, item.getValue(), this.stack.name, isLogicallyExpired))
-      this.logger.trace(
-        { key, cache: this.stack.name, opId: options.id },
-        'remote cache hit (graced)',
-      )
-
-      return item.getValue()
+      this.#emit(cacheEvents.hit(key, item.entry.getValue(), this.stack.name, item.isGraced))
+      return item.entry.getValue()
     }
 
     throw err
   }
 
   async #applyFallbackAndReturnGracedValue(
     key: string,
-    item: CacheEntry,
+    item: GetCacheValueReturn,
     options: CacheEntryOptions,
   ) {
     if (options.grace && options.graceBackoff) {
@@ -84,29 +82,26 @@ export class SingleTierHandler {
         'apply fallback duration',
       )
 
-      this.stack.l2?.set(key, item.applyBackoff(options.graceBackoff).serialize() as any, options)
+      this.stack.l2?.set(
+        key,
+        item.entry.applyBackoff(options.graceBackoff).serialize() as any,
+        options,
+      )
     }
 
     this.logger.trace({ key, cache: this.stack.name, opId: options.id }, 'returns stale value')
-    this.#emit(cacheEvents.hit(key, item.getValue(), this.stack.name, true))
-    return item.getValue()
-  }
-
-  /**
-   * Check if a cache item is not undefined and not logically expired
-   */
-  #isItemValid(item: CacheEntry | undefined): item is CacheEntry {
-    return !!item && !item.isLogicallyExpired()
+    this.#emit(cacheEvents.hit(key, item.entry.getValue(), this.stack.name, true))
+    return item.entry.getValue()
   }
 
   async handle(key: string, factory: Factory, options: CacheEntryOptions) {
-    let remoteItem: CacheEntry | undefined
+    let remoteItem: GetCacheValueReturn | undefined
 
     /**
      * Check in the remote cache first if we have something
      */
     remoteItem = await this.stack.l2?.get(key, options)
-    if (this.#isItemValid(remoteItem)) {
+    if (remoteItem?.isGraced === false) {
       return this.#returnRemoteCacheValue(key, remoteItem, options)
     }
 
@@ -126,7 +121,7 @@ export class SingleTierHandler {
      * already set the value
      */
     remoteItem = await this.stack.l2?.get(key, options)
-    if (this.#isItemValid(remoteItem)) {
+    if (remoteItem?.isGraced === false) {
       this.#locks.release(key, releaser)
       return this.#returnRemoteCacheValue(key, remoteItem, options)
     }