Add debug logging to default cache handler and "use cache" wrapper (#77827)

When the env variable `NEXT_PRIVATE_DEBUG_CACHE` is defined (see https://nextjs.org/docs/app/building-your-application/data-fetching/incremental-static-regeneration#verifying-correct-production-behavior), the default cache handler and the `"use cache"` wrapper will now emit debug logs.

Note: This variable can already be used for `"use cache"` debug logging when deploying to Vercel.

Author: unstubbable

packages/next/src/server/lib/cache-handlers/default.ts

@@ -41,13 +41,23 @@ const memoryCache = new LRUCache<PrivateCacheEntry>(
 )
 const pendingSets = new Map<string, Promise<void>>()
 
+const debug = process.env.NEXT_PRIVATE_DEBUG_CACHE
+  ? console.debug.bind(console, 'DefaultCacheHandler:')
+  : undefined
+
 const DefaultCacheHandler: CacheHandlerV2 = {
   async get(cacheKey) {
-    await pendingSets.get(cacheKey)
+    const pendingPromise = pendingSets.get(cacheKey)
+
+    if (pendingPromise) {
+      debug?.('get', cacheKey, 'pending')
+      await pendingPromise
+    }
 
     const privateEntry = memoryCache.get(cacheKey)
 
     if (!privateEntry) {
+      debug?.('get', cacheKey, 'not found')
       return undefined
     }
 
@@ -59,22 +69,35 @@ const DefaultCacheHandler: CacheHandlerV2 = {
       // In-memory caches should expire after revalidate time because it is
       // unlikely that a new entry will be able to be used before it is dropped
       // from the cache.
+      debug?.('get', cacheKey, 'expired')
+
       return undefined
     }
 
     if (isStale(entry.tags, entry.timestamp)) {
+      debug?.('get', cacheKey, 'had stale tag')
+
       return undefined
     }
     const [returnStream, newSaved] = entry.value.tee()
     entry.value = newSaved
 
+    debug?.('get', cacheKey, 'found', {
+      tags: entry.tags,
+      timestamp: entry.timestamp,
+      revalidate: entry.revalidate,
+      expire: entry.expire,
+    })
+
     return {
       ...entry,
       value: returnStream,
     }
   },
 
   async set(cacheKey, pendingEntry) {
+    debug?.('set', cacheKey, 'start')
+
     let resolvePending: () => void = () => {}
     const pendingPromise = new Promise<void>((resolve) => {
       resolvePending = resolve
@@ -100,8 +123,11 @@ const DefaultCacheHandler: CacheHandlerV2 = {
         errorRetryCount: 0,
         size,
       })
-    } catch {
+
+      debug?.('set', cacheKey, 'done')
+    } catch (err) {
       // TODO: store partial buffer with error after we retry 3 times
+      debug?.('set', cacheKey, 'failed', err)
     } finally {
       resolvePending()
       pendingSets.delete(cacheKey)
@@ -113,11 +139,18 @@ const DefaultCacheHandler: CacheHandlerV2 = {
   },
 
   async getExpiration(...tags) {
-    return Math.max(...tags.map((tag) => tagsManifest.get(tag) ?? 0))
+    const expiration = Math.max(
+      ...tags.map((tag) => tagsManifest.get(tag) ?? 0)
+    )
+
+    debug?.('getExpiration', { tags, expiration })
+
+    return expiration
   },
 
   async expireTags(...tags) {
     const timestamp = Math.round(performance.timeOrigin + performance.now())
+    debug?.('expireTags', { tags, timestamp })
 
     for (const tag of tags) {
       // TODO: update file-system-cache?

packages/next/src/server/use-cache/handlers.ts

@@ -5,7 +5,7 @@ const debug = process.env.NEXT_PRIVATE_DEBUG_CACHE
   ? (message: string, ...args: any[]) => {
       console.log(`use-cache: ${message}`, ...args)
     }
-  : () => {}
+  : undefined
 
 const handlersSymbol = Symbol.for('@next/cache-handlers')
 const handlersMapSymbol = Symbol.for('@next/cache-handlers-map')
@@ -32,40 +32,40 @@ const reference: typeof globalThis & {
 export function initializeCacheHandlers(): boolean {
   // If the cache handlers have already been initialized, don't do it again.
   if (reference[handlersMapSymbol]) {
-    debug('cache handlers already initialized')
+    debug?.('cache handlers already initialized')
     return false
   }
 
-  debug('initializing cache handlers')
+  debug?.('initializing cache handlers')
   reference[handlersMapSymbol] = new Map<string, CacheHandlerCompat>()
 
   // Initialize the cache from the symbol contents first.
   if (reference[handlersSymbol]) {
     let fallback: CacheHandlerCompat
     if (reference[handlersSymbol].DefaultCache) {
-      debug('setting "default" cache handler from symbol')
+      debug?.('setting "default" cache handler from symbol')
       fallback = reference[handlersSymbol].DefaultCache
     } else {
-      debug('setting "default" cache handler from default')
+      debug?.('setting "default" cache handler from default')
       fallback = DefaultCacheHandler
     }
 
     reference[handlersMapSymbol].set('default', fallback)
 
     if (reference[handlersSymbol].RemoteCache) {
-      debug('setting "remote" cache handler from symbol')
+      debug?.('setting "remote" cache handler from symbol')
       reference[handlersMapSymbol].set(
         'remote',
         reference[handlersSymbol].RemoteCache
       )
     } else {
-      debug('setting "remote" cache handler from default')
+      debug?.('setting "remote" cache handler from default')
       reference[handlersMapSymbol].set('remote', fallback)
     }
   } else {
-    debug('setting "default" cache handler from default')
+    debug?.('setting "default" cache handler from default')
     reference[handlersMapSymbol].set('default', DefaultCacheHandler)
-    debug('setting "remote" cache handler from default')
+    debug?.('setting "remote" cache handler from default')
     reference[handlersMapSymbol].set('remote', DefaultCacheHandler)
   }
 
@@ -135,7 +135,7 @@ export function setCacheHandler(
     throw new Error('Cache handlers not initialized')
   }
 
-  debug('setting cache handler for "%s"', kind)
+  debug?.('setting cache handler for "%s"', kind)
   reference[handlersMapSymbol].set(kind, cacheHandler)
   reference[handlersSetSymbol].add(cacheHandler)
 }

packages/next/src/server/use-cache/use-cache-wrapper.ts

@@ -66,6 +66,10 @@ export interface UseCachePageComponentProps {
 
 const isEdgeRuntime = process.env.NEXT_RUNTIME === 'edge'
 
+const debug = process.env.NEXT_PRIVATE_DEBUG_CACHE
+  ? console.debug.bind(console, 'use-cache:')
+  : undefined
+
 function generateCacheEntry(
   workStore: WorkStore,
   outerWorkUnitStore: WorkUnitStore | undefined,
@@ -716,6 +720,7 @@ export function cache(
           entry &&
           (await shouldDiscardCacheEntry(entry, workStore, implicitTags))
         ) {
+          debug?.('discarding stale entry', serializedCacheKey)
           entry = undefined
         }
 
@@ -756,6 +761,19 @@ export function cache(
           // Note: It is important that we await at least once before this because it lets us
           // pop out of any stack specific contexts as well - aka "Sync" Local Storage.
 
+          if (entry) {
+            if (currentTime > entry.timestamp + entry.expire * 1000) {
+              debug?.('entry is expired', serializedCacheKey)
+            }
+
+            if (
+              workStore.isStaticGeneration &&
+              currentTime > entry.timestamp + entry.revalidate * 1000
+            ) {
+              debug?.('static generation, entry is stale', serializedCacheKey)
+            }
+          }
+
           const [newStream, pendingCacheEntry] = await generateCacheEntry(
             workStore,
             workUnitStore,
@@ -942,6 +960,13 @@ async function shouldDiscardCacheEntry(
     // If the cache entry was created before any of the implicit tags were
     // revalidated last, we also need to discard it.
     if (entry.timestamp <= (await implicitTags.expiration)) {
+      debug?.(
+        'entry was created at',
+        entry.timestamp,
+        'before implicit tags were revalidated at',
+        implicitTags.expiration
+      )
+
       return true
     }
 
@@ -962,13 +987,17 @@ function isRecentlyRevalidatedTag(tag: string, workStore: WorkStore): boolean {
 
   // Was the tag previously revalidated (e.g. by a redirecting server action)?
   if (previouslyRevalidatedTags.includes(tag)) {
+    debug?.('tag', tag, 'was previously revalidated')
+
     return true
   }
 
   // It could also have been revalidated by the currently running server action.
   // In this case the revalidation might not have been propagated to the cache
   // handler yet, so we read it from the pending tags in the work store.
   if (pendingRevalidatedTags?.includes(tag)) {
+    debug?.('tag', tag, 'was just revalidated')
+
     return true
   }