Add debug logging to default cache handler and "use cache" wrapper

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:')
+  : () => {}
+
 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/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:')
+  : () => {}
+
 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
   }