feat: rework logging system (#55)

* feat: prepare better logging + add new logs

* feat: rework logging system

* chore: add changeset

* chore: update lockfile

Author: Julien-R44

.changeset/tasty-shirts-judge.md

@@ -0,0 +1,5 @@
+---
+'bentocache': minor
+---
+
+Rework the logs issued by bentocache to make them much cleaner, more consistent and make debug easier

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_options.ts

@@ -3,16 +3,11 @@ import lodash from '@poppinss/utils/lodash'
 import string from '@poppinss/utils/string'
 import { noopLogger } from '@julr/utils/logger'
 
+import { Logger } from './logger.js'
 import { resolveTtl } from './helpers.js'
 import type { FactoryError } from './errors.js'
 import { JsonSerializer } from './serializers/json.js'
-import type {
-  CacheSerializer,
-  Duration,
-  Emitter,
-  Logger,
-  RawBentoCacheOptions,
-} from './types/main.js'
+import type { CacheSerializer, Duration, Emitter, RawBentoCacheOptions } from './types/main.js'
 
 const defaultSerializer = new JsonSerializer()
 
@@ -57,7 +52,7 @@ export class BentoCacheOptions {
   /**
    * The logger used throughout the library
    */
-  logger: Logger = noopLogger()
+  logger: Logger
 
   /**
    * The emitter used throughout the library
@@ -102,7 +97,7 @@ export class BentoCacheOptions {
     this.serializer = this.#options.serializer ?? defaultSerializer
     this.l2CircuitBreakerDuration = resolveTtl(this.#options.l2CircuitBreakerDuration, null)
 
-    this.logger = this.#options.logger!.child({ pkg: 'bentocache' })
+    this.logger = new Logger(this.#options.logger ?? noopLogger())
     this.onFactoryError = this.#options.onFactoryError
   }
 

packages/bentocache/src/bus/bus.ts

@@ -1,10 +1,11 @@
 import { Bus as BoringBus } from '@boringnode/bus'
 import type { Transport } from '@boringnode/bus/types/main'
 
+import type { Logger } from '../logger.js'
 import { busEvents } from '../events/bus_events.js'
 import { CacheBusMessageType } from '../types/bus.js'
 import type { LocalCache } from '../cache/facades/local_cache.js'
-import type { BusOptions, CacheBusMessage, Emitter, Logger } from '../types/main.js'
+import type { BusOptions, CacheBusMessage, Emitter } from '../types/main.js'
 
 /**
  * The bus is used to notify other processes about cache changes.

packages/bentocache/src/cache/cache.ts

@@ -5,6 +5,7 @@ import { CacheBusMessageType } from '../types/main.js'
 import { cacheEvents } from '../events/cache_events.js'
 import type { CacheProvider } from '../types/provider.js'
 import { GetSetHandler } from './get_set/get_set_handler.js'
+import type { BentoCacheOptions } from '../bento_cache_options.js'
 import type {
   Factory,
   ClearOptions,
@@ -25,11 +26,13 @@ export class Cache implements CacheProvider {
 
   #getSetHandler: GetSetHandler
   #stack: CacheStack
+  #options: BentoCacheOptions
 
   constructor(name: string, stack: CacheStack) {
     this.name = name
 
     this.#stack = stack
+    this.#options = stack.options
     this.#getSetHandler = new GetSetHandler(this.#stack)
   }
 
@@ -45,54 +48,61 @@ export class Cache implements CacheProvider {
   }
 
   get<T = any>(options: GetOptions<T>): Promise<T>
-  async get<T = any>(keyOrOptions: GetOptions<T>): Promise<T | undefined | null> {
-    const key = keyOrOptions.key
-    const providedOptions = keyOrOptions
-    const defaultValueFn = this.#resolveDefaultValue(keyOrOptions.defaultValue)
+  async get<T = any>(rawOptions: GetOptions<T>): Promise<T | undefined | null> {
+    const key = rawOptions.key
+    const defaultValueFn = this.#resolveDefaultValue(rawOptions.defaultValue)
 
-    const options = this.#stack.defaultOptions.cloneWith(providedOptions)
-    const localItem = this.#stack.l1?.get(key, options)
+    const options = this.#stack.defaultOptions.cloneWith(rawOptions)
+    this.#options.logger.logMethod({ method: 'get', key, options, cacheName: this.name })
 
-    if (localItem !== undefined && !localItem.isLogicallyExpired()) {
-      this.#stack.emit(cacheEvents.hit(key, localItem.getValue(), this.name))
-      return localItem.getValue()
+    const localItem = this.#stack.l1?.get(key, options)
+    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.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))
-      return remoteItem.getValue()
-    }
-
-    if (!options.isGraceEnabled()) {
-      this.#stack.emit(cacheEvents.miss(key, this.name))
-      return this.#resolveDefaultValue(defaultValueFn)
+    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.entry.getValue()
     }
 
-    if (remoteItem) {
-      this.#stack.l1?.set(key, remoteItem.serialize(), options)
-      this.#stack.emit(cacheEvents.hit(key, remoteItem.serialize(), this.name, true))
-      return remoteItem.getValue()
+    if (remoteItem && options.isGraceEnabled()) {
+      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.entry.getValue()
     }
 
-    if (localItem) {
-      this.#stack.emit(cacheEvents.hit(key, localItem.serialize(), this.name, true))
-      return localItem.getValue()
+    if (localItem && options.isGraceEnabled()) {
+      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.entry.getValue()
     }
 
     this.#stack.emit(cacheEvents.miss(key, this.name))
+    this.#options.logger.debug({ key, cacheName: this.name }, 'cache miss. using default value')
     return this.#resolveDefaultValue(defaultValueFn)
   }
 
   /**
    * Set a value in the cache
    * Returns true if the value was set, false otherwise
    */
-  set(options: SetOptions) {
-    const cacheOptions = this.#stack.defaultOptions.cloneWith(options)
-    return this.#stack.set(options.key, options.value, cacheOptions)
+  set(rawOptions: SetOptions) {
+    const options = this.#stack.defaultOptions.cloneWith(rawOptions)
+    this.#options.logger.logMethod({
+      method: 'set',
+      options,
+      key: rawOptions.key,
+      cacheName: this.name,
+    })
+
+    return this.#stack.set(rawOptions.key, rawOptions.value, options)
   }
 
   /**
@@ -107,28 +117,41 @@ export class Cache implements CacheProvider {
    * Retrieve an item from the cache if it exists, otherwise store the value
    * provided by the factory and return it
    */
-  getOrSet<T>(options: GetOrSetOptions<T>): Promise<T> {
-    const cacheOptions = this.#stack.defaultOptions.cloneWith(options)
-    return this.#getSetHandler.handle(options.key, options.factory, cacheOptions)
+  getOrSet<T>(rawOptions: GetOrSetOptions<T>): Promise<T> {
+    const options = this.#stack.defaultOptions.cloneWith(rawOptions)
+    this.#options.logger.logMethod({
+      method: 'getOrSet',
+      key: rawOptions.key,
+      cacheName: this.name,
+      options,
+    })
+
+    return this.#getSetHandler.handle(rawOptions.key, rawOptions.factory, options)
   }
 
   /**
    * Retrieve an item from the cache if it exists, otherwise store the value
    * provided by the factory forever and return it
    */
-  getOrSetForever<T>(options: GetOrSetForeverOptions<T>): Promise<T> {
-    const cacheOptions = this.#stack.defaultOptions.cloneWith({ ttl: null, ...options })
-    return this.#getSetHandler.handle(options.key, options.factory, cacheOptions)
+  getOrSetForever<T>(rawOptions: GetOrSetForeverOptions<T>): Promise<T> {
+    const options = this.#stack.defaultOptions.cloneWith({ ttl: null, ...rawOptions })
+    return this.#getSetHandler.handle(rawOptions.key, rawOptions.factory, options)
   }
 
   /**
    * Check if a key exists in the cache
    */
   async has(options: HasOptions) {
     const key = options.key
-    const cacheOptions = this.#stack.defaultOptions.cloneWith(options)
-
-    const inRemote = await this.#stack.l2?.has(key, cacheOptions)
+    const entryOptions = this.#stack.defaultOptions.cloneWith(options)
+    this.#options.logger.logMethod({
+      method: 'has',
+      key,
+      cacheName: this.name,
+      options: entryOptions,
+    })
+
+    const inRemote = await this.#stack.l2?.has(key, entryOptions)
     const inLocal = this.#stack.l1?.has(key)
 
     return !!(inRemote || inLocal)
@@ -155,12 +178,13 @@ export class Cache implements CacheProvider {
    * Delete a key from the cache, emit cache:deleted event and
    * publish invalidation through the bus
    */
-  async delete(options: DeleteOptions): Promise<boolean> {
-    const key = options.key
-    const cacheOptions = this.#stack.defaultOptions.cloneWith(options)
+  async delete(rawOptions: DeleteOptions): Promise<boolean> {
+    const key = rawOptions.key
+    const options = this.#stack.defaultOptions.cloneWith(rawOptions)
+    this.#options.logger.logMethod({ method: 'delete', key, cacheName: this.name, options })
 
-    this.#stack.l1?.delete(key, cacheOptions)
-    await this.#stack.l2?.delete(key, cacheOptions)
+    this.#stack.l1?.delete(key, options)
+    await this.#stack.l2?.delete(key, options)
 
     this.#stack.emit(cacheEvents.deleted(key, this.name))
     await this.#stack.publish({ type: CacheBusMessageType.Delete, keys: [key] })
@@ -173,12 +197,18 @@ export class Cache implements CacheProvider {
    * Then emit cache:deleted events for each key
    * And finally publish invalidation through the bus
    */
-  async deleteMany(options: DeleteManyOptions): Promise<boolean> {
-    const keys = options.keys
-    const cacheOptions = this.#stack.defaultOptions.cloneWith(options)
-
-    this.#stack.l1?.deleteMany(keys, cacheOptions)
-    await this.#stack.l2?.deleteMany(keys, cacheOptions)
+  async deleteMany(rawOptions: DeleteManyOptions): Promise<boolean> {
+    const keys = rawOptions.keys
+    const options = this.#stack.defaultOptions.cloneWith(rawOptions)
+    this.#options.logger.logMethod({
+      method: 'deleteMany',
+      key: keys,
+      cacheName: this.name,
+      options,
+    })
+
+    this.#stack.l1?.deleteMany(keys, options)
+    await this.#stack.l2?.deleteMany(keys, options)
 
     keys.forEach((key) => this.#stack.emit(cacheEvents.deleted(key, this.name)))
     await this.#stack.publish({ type: CacheBusMessageType.Delete, keys })
@@ -189,12 +219,13 @@ export class Cache implements CacheProvider {
   /**
    * Remove all items from the cache
    */
-  async clear(options?: ClearOptions) {
-    const cacheOptions = this.#stack.defaultOptions.cloneWith(options)
+  async clear(rawOptions?: ClearOptions) {
+    const options = this.#stack.defaultOptions.cloneWith(rawOptions)
+    this.#options.logger.logMethod({ method: 'clear', cacheName: this.name, options })
 
     await Promise.all([
       this.#stack.l1?.clear(),
-      this.#stack.l2?.clear(cacheOptions),
+      this.#stack.l2?.clear(options),
       this.#stack.publish({ type: CacheBusMessageType.Clear, keys: [] }),
     ])
 

packages/bentocache/src/cache/cache_stack.ts

@@ -2,6 +2,7 @@ import { is } from '@julr/utils/is'
 import lodash from '@poppinss/utils/lodash'
 
 import { Bus } from '../bus/bus.js'
+import type { Logger } from '../logger.js'
 import { UndefinedValueError } from '../errors.js'
 import { LocalCache } from './facades/local_cache.js'
 import { BaseDriver } from '../drivers/base_driver.js'
@@ -15,7 +16,6 @@ import {
   type CacheEvent,
   type CacheStackDrivers,
   type CacheBusMessage,
-  type Logger,
   CacheBusMessageType,
 } from '../types/main.js'
 
@@ -65,9 +65,8 @@ export class CacheStack extends BaseDriver {
       { retryQueue: { enabled: true, maxSize: undefined } },
       busOptions,
     )
-    const newBus = new Bus(this.name, this.#busDriver, this.logger, this.emitter, this.#busOptions)
 
-    return newBus
+    return new Bus(this.name, this.#busDriver, this.logger, this.emitter, this.#busOptions)
   }
 
   namespace(namespace: string): CacheStack {

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

@@ -1,6 +1,7 @@
+import type { Logger } from '../../logger.js'
 import { CacheEntry } from '../cache_entry/cache_entry.js'
+import type { L1CacheDriver, CacheSerializer } from '../../types/main.js'
 import type { CacheEntryOptions } from '../cache_entry/cache_entry_options.js'
-import type { Logger, L1CacheDriver, CacheSerializer } from '../../types/main.js'
 
 /**
  * LocalCache is a wrapper around a CacheDriver that provides a
@@ -14,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' })
   }
 
   /**
@@ -24,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 }
   }
 
   /**
@@ -53,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)
   }
 
@@ -73,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
@@ -86,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)
   }