Log fetch requests during client-side navigation

packages/next/src/server/app-render/app-render.tsx

@@ -435,7 +435,9 @@ async function generateDynamicFlightRenderResult(
     }
   )
 
-  return new FlightRenderResult(flightReadableStream)
+  return new FlightRenderResult(flightReadableStream, {
+    fetchMetrics: ctx.staticGenerationStore.fetchMetrics,
+  })
 }
 
 type RenderToStreamResult = {

packages/next/src/server/app-render/flight-render-result.ts

@@ -1,11 +1,14 @@
 import { RSC_CONTENT_TYPE_HEADER } from '../../client/components/app-router-headers'
-import RenderResult from '../render-result'
+import RenderResult, { type RenderResultMetadata } from '../render-result'
 
 /**
  * Flight Response is always set to RSC_CONTENT_TYPE_HEADER to ensure it does not get interpreted as HTML.
  */
 export class FlightRenderResult extends RenderResult {
-  constructor(response: string | ReadableStream<Uint8Array>) {
-    super(response, { contentType: RSC_CONTENT_TYPE_HEADER, metadata: {} })
+  constructor(
+    response: string | ReadableStream<Uint8Array>,
+    metadata: RenderResultMetadata = {}
+  ) {
+    super(response, { contentType: RSC_CONTENT_TYPE_HEADER, metadata })
   }
 }

packages/next/src/server/base-http/index.ts

@@ -19,7 +19,8 @@ export type FetchMetric = {
   method: string
   status: number
   cacheReason: string
-  cacheStatus: 'hit' | 'miss' | 'skip'
+  cacheStatus: 'hit' | 'miss' | 'skip' | 'hmr'
+  cacheWarning?: string
 }
 
 export type FetchMetrics = Array<FetchMetric>

packages/next/src/server/lib/patch-fetch.ts

@@ -11,7 +11,6 @@ import {
   NEXT_CACHE_TAG_MAX_ITEMS,
   NEXT_CACHE_TAG_MAX_LENGTH,
 } from '../../lib/constants'
-import * as Log from '../../build/output/log'
 import { markCurrentScopeAsDynamic } from '../app-render/dynamic-rendering'
 import type { FetchMetric } from '../base-http'
 import { createDedupeFetch } from './dedupe-fetch'
@@ -328,6 +327,7 @@ function createPatchedFetcher(
 
         let currentFetchCacheConfig = getRequestMeta('cache')
         let cacheReason = ''
+        let cacheWarning: string | undefined
 
         if (
           typeof currentFetchCacheConfig === 'string' &&
@@ -336,9 +336,7 @@ function createPatchedFetcher(
           // when providing fetch with a Request input, it'll automatically set a cache value of 'default'
           // we only want to warn if the user is explicitly setting a cache value
           if (!(isRequestInput && currentFetchCacheConfig === 'default')) {
-            Log.warn(
-              `fetch for ${fetchUrl} on ${staticGenerationStore.route} specified "cache: ${currentFetchCacheConfig}" and "revalidate: ${currentFetchRevalidate}", only one should be specified.`
-            )
+            cacheWarning = `Specified "cache: ${currentFetchCacheConfig}" and "revalidate: ${currentFetchRevalidate}", only one should be specified.`
           }
           currentFetchCacheConfig = undefined
         }
@@ -587,6 +585,7 @@ function createPatchedFetcher(
                   finalRevalidate === 0 || cacheReasonOverride
                     ? 'skip'
                     : 'miss',
+                cacheWarning,
                 status: res.status,
                 method: clonedInit.method || 'GET',
               })
@@ -647,6 +646,7 @@ function createPatchedFetcher(
         let handleUnlock = () => Promise.resolve()
         let cacheReasonOverride
         let isForegroundRevalidate = false
+        let isHmrRefreshCache = false
 
         if (cacheKey && staticGenerationStore.incrementalCache) {
           let cachedFetchData: CachedFetchData | undefined
@@ -657,6 +657,8 @@ function createPatchedFetcher(
           ) {
             cachedFetchData =
               requestStore.serverComponentsHmrCache.get(cacheKey)
+
+            isHmrRefreshCache = true
           }
 
           if (isCacheableRevalidate && !cachedFetchData) {
@@ -712,7 +714,8 @@ function createPatchedFetcher(
               start: fetchStart,
               url: fetchUrl,
               cacheReason,
-              cacheStatus: 'hit',
+              cacheStatus: isHmrRefreshCache ? 'hmr' : 'hit',
+              cacheWarning,
               status: cachedFetchData.status || 200,
               method: init?.method || 'GET',
             })

packages/next/src/server/next-server.ts

@@ -12,7 +12,6 @@ import type { MiddlewareManifest } from '../build/webpack/plugins/middleware-plu
 import type RenderResult from './render-result'
 import type { FetchEventResult } from './web/types'
 import type { PrerenderManifest } from '../build'
-import type { FetchMetric } from './base-http'
 import type { PagesManifest } from '../build/webpack/plugins/pages-manifest-plugin'
 import type { NextParsedUrlQuery, NextUrlWithParsedQuery } from './request-meta'
 import type { Params } from '../shared/lib/router/utils/route-matcher'
@@ -1123,7 +1122,7 @@ export default class NextNodeServer extends BaseServer<
       const shouldTruncateUrl = !loggingFetchesConfig?.fullUrl
 
       if (this.renderOpts.dev) {
-        const { blue, green, yellow, red, gray, white } =
+        const { blue, green, yellow, red, gray, white, bold } =
           require('../lib/picocolors') as typeof import('../lib/picocolors')
 
         const { originalResponse } = normalizedRes
@@ -1159,37 +1158,24 @@ export default class NextNodeServer extends BaseServer<
           const loggingUrl = isRSC
             ? stripNextRscUnionQuery(requestUrl)
             : requestUrl
+          const indentation = '│ '
 
           writeStdoutLine(
             `${method} ${loggingUrl} ${color(
               res.statusCode.toString()
             )} in ${reqDuration}ms`
           )
 
-          if (fetchMetrics.length && enabledVerboseLogging) {
-            const calcNestedLevel = (
-              prevMetrics: FetchMetric[],
-              start: number
-            ): string => {
-              let nestedLevel = 0
-
-              for (let i = 0; i < prevMetrics.length; i++) {
-                const metric = prevMetrics[i]
-                const prevMetric = prevMetrics[i - 1]
-
-                if (
-                  metric.end <= start &&
-                  !(prevMetric && prevMetric.start < metric.end)
-                ) {
-                  nestedLevel += 1
-                }
-              }
-              return nestedLevel === 0 ? ' ' : ' │ '.repeat(nestedLevel)
+          for (let i = 0; i < fetchMetrics.length; i++) {
+            const metric = fetchMetrics[i]
+            let { cacheStatus, cacheReason, cacheWarning, url } = metric
+
+            if (cacheStatus === 'hmr') {
+              // Cache hits during HMR refreshes are intentionally not logged.
+              continue
             }
 
-            for (let i = 0; i < fetchMetrics.length; i++) {
-              const metric = fetchMetrics[i]
-              let { cacheStatus, cacheReason } = metric
+            if (enabledVerboseLogging) {
               let cacheReasonStr = ''
 
               let cacheColor
@@ -1203,7 +1189,6 @@ export default class NextNodeServer extends BaseServer<
                   `Cache ${status} reason: (${white(cacheReason)})`
                 )
               }
-              let url = metric.url
 
               if (url.length > 48) {
                 const parsed = new URL(url)
@@ -1229,27 +1214,30 @@ export default class NextNodeServer extends BaseServer<
               }
 
               const status = cacheColor(`(cache ${cacheStatus})`)
-              const newLineLeadingChar = '│'
-              const nestedIndent = calcNestedLevel(
-                fetchMetrics.slice(0, i + 1),
-                metric.start
-              )
 
               writeStdoutLine(
-                `${newLineLeadingChar}${nestedIndent}${white(
+                `${indentation}${white(
                   metric.method
                 )} ${white(url)} ${metric.status} in ${duration}ms ${status}`
               )
+
               if (cacheReasonStr) {
-                const nextNestedIndent = calcNestedLevel(
-                  fetchMetrics.slice(0, i + 1),
-                  metric.start
-                )
+                writeStdoutLine(`${indentation}${indentation}${cacheReasonStr}`)
+              }
 
+              if (cacheWarning) {
                 writeStdoutLine(
-                  `${newLineLeadingChar}${nextNestedIndent}${newLineLeadingChar} ${cacheReasonStr}`
+                  `${indentation}${indentation}${yellow(bold('⚠'))} ${white(cacheWarning)}`
                 )
               }
+            } else if (cacheWarning) {
+              writeStdoutLine(
+                `${indentation}${white(metric.method)} ${white(url)}`
+              )
+
+              writeStdoutLine(
+                `${indentation}${indentation}${yellow(bold('⚠'))} ${white(cacheWarning)}`
+              )
             }
           }
           delete normalizedReq.fetchMetrics

test/e2e/app-dir/app-static/app-static.test.ts

@@ -2237,8 +2237,9 @@ describe('app-dir static/dynamic handling', () => {
 
     let prevHtml = await res.text()
     let prev$ = cheerio.load(prevHtml)
+    const cliOutputLength = next.cliOutput.length
 
-    await check(async () => {
+    await retry(async () => {
       const curRes = await next.fetch('/force-cache')
       expect(curRes.status).toBe(200)
 
@@ -2258,14 +2259,18 @@ describe('app-dir static/dynamic handling', () => {
       expect(cur$('#data-auto-cache').text()).toBe(
         prev$('#data-auto-cache').text()
       )
+    })
 
-      return 'success'
-    }, 'success')
+    if (isNextDev) {
+      await retry(() => {
+        const cliOutput = next.cliOutput
+          .slice(cliOutputLength)
+          .replace(/in \d+ms/g, 'in 0ms') // stub request durations
 
-    if (!isNextDeploy) {
-      expect(next.cliOutput).toContain(
-        'fetch for https://next-data-api-endpoint.vercel.app/api/random?d4 on /force-cache specified "cache: force-cache" and "revalidate: 3", only one should be specified.'
-      )
+        expect(stripAnsi(cliOutput)).toContain(`
+ │ GET https://next-data-api-en../api/random?d4 200 in 0ms (cache hit)
+ │ │ ⚠ Specified "cache: force-cache" and "revalidate: 3", only one should be specified.`)
+      })
     }
   })
 

test/e2e/app-dir/logging/fetch-logging.test.ts

@@ -126,12 +126,15 @@ describe('app-dir - logging', () => {
           const outputIndex = next.cliOutput.length
           await next.fetch('/default-cache')
 
+          const expectedUrl = withFullUrlFetches
+            ? 'https://next-data-api-endpoint.vercel.app/api/random'
+            : 'https://next-data-api-en../api/random'
+
           await retry(() => {
             const logs = stripAnsi(next.cliOutput.slice(outputIndex))
-            expect(logs).toContain(' GET /default-cache')
-            expect(logs).toContain(' │ GET ')
-            expect(logs).toContain(' │ │ Cache skipped reason')
-            expect(logs).toContain(' │ │ GET ')
+            expect(logs).toIncludeRepeated(' GET /default-cache', 1)
+            expect(logs).toIncludeRepeated(` │ GET ${expectedUrl}`, 7)
+            expect(logs).toIncludeRepeated(' │ │ Cache skipped reason', 3)
           })
         })
 
@@ -191,6 +194,40 @@ describe('app-dir - logging', () => {
           expect(logs).not.toContain('/_next/static')
           expect(logs).not.toContain('?_rsc')
         })
+
+        it('should log requests for client-side navigations', async () => {
+          const outputIndex = next.cliOutput.length
+          const browser = await next.browser('/')
+          await browser.elementById('nav-default-cache').click()
+          await browser.waitForElementByCss('h1')
+
+          const expectedUrl = withFullUrlFetches
+            ? 'https://next-data-api-endpoint.vercel.app/api/random'
+            : 'https://next-data-api-en../api/random'
+
+          await retry(() => {
+            const logs = stripAnsi(next.cliOutput.slice(outputIndex))
+            expect(logs).toIncludeRepeated(` │ GET ${expectedUrl}`, 7)
+          })
+        })
+
+        it('should not log requests for HMR refreshes', async () => {
+          const browser = await next.browser('/default-cache')
+          let headline = await browser.waitForElementByCss('h1').text()
+          expect(headline).toBe('Default Cache')
+          const outputIndex = next.cliOutput.length
+
+          await next.patchFile(
+            'app/default-cache/page.js',
+            (content) => content.replace('Default Cache', 'Hello!'),
+            async () => {
+              headline = await browser.waitForElementByCss('h1').text()
+              expect(headline).toBe('Hello!')
+              const logs = stripAnsi(next.cliOutput.slice(outputIndex))
+              expect(logs).not.toInclude(` │ GET `)
+            }
+          )
+        })
       }
     } else {
       // No fetches logging enabled

test/e2e/app-dir/logging/fetch-warning.test.ts

@@ -1,8 +1,8 @@
-import { check } from 'next-test-utils'
+import { retry } from 'next-test-utils'
 import { nextTestSetup } from 'e2e-utils'
 
 describe('app-dir - fetch warnings', () => {
-  const { next, skipped } = nextTestSetup({
+  const { next, skipped, isNextDev } = nextTestSetup({
     skipDeployment: true,
     files: __dirname,
   })
@@ -20,33 +20,37 @@ describe('app-dir - fetch warnings', () => {
     await next.fetch('/cache-revalidate')
   })
 
-  it('should log when request input is a string', async () => {
-    await check(() => {
-      return next.cliOutput.includes(
-        'fetch for https://next-data-api-endpoint.vercel.app/api/random?request-string on /cache-revalidate specified "cache: force-cache" and "revalidate: 3", only one should be specified'
-      )
-        ? 'success'
-        : 'fail'
-    }, 'success')
-  })
+  if (isNextDev) {
+    it('should log when request input is a string', async () => {
+      await retry(() => {
+        expect(next.cliOutput).toInclude(`
+ │ GET https://next-data-api-endpoint.vercel.app/api/random?request-string
+ │ │ ⚠ Specified "cache: force-cache" and "revalidate: 3", only one should be specified.`)
+      })
+    })
 
-  it('should log when request input is a Request instance', async () => {
-    await check(() => {
-      return next.cliOutput.includes(
-        'fetch for https://next-data-api-endpoint.vercel.app/api/random?request-input-cache-override on /cache-revalidate specified "cache: force-cache" and "revalidate: 3", only one should be specified.'
-      )
-        ? 'success'
-        : 'fail'
-    }, 'success')
-  })
+    it('should log when request input is a Request instance', async () => {
+      await retry(() => {
+        expect(next.cliOutput).toInclude(`
+ │ GET https://next-data-api-endpoint.vercel.app/api/random?request-input-cache-override
+ │ │ ⚠ Specified "cache: force-cache" and "revalidate: 3", only one should be specified.`)
+      })
+    })
 
-  it('should not log when overriding cache within the Request object', async () => {
-    await check(() => {
-      return next.cliOutput.includes(
-        `fetch for https://next-data-api-endpoint.vercel.app/api/random?request-input on /cache-revalidate specified "cache: default" and "revalidate: 3", only one should be specified.`
-      )
-        ? 'fail'
-        : 'success'
-    }, 'success')
-  })
+    it('should not log when overriding cache within the Request object', async () => {
+      await retry(() => {
+        expect(next.cliOutput).not.toInclude(`
+ │ GET https://next-data-api-endpoint.vercel.app/api/random?request-input
+ │ │ ⚠ Specified "cache: force-cache" and "revalidate: 3", only one should be specified.`)
+      })
+    })
+  } else {
+    it('should not log fetch warnings in production', async () => {
+      await retry(() => {
+        expect(next.cliOutput).not.toInclude(
+          '⚠ Specified "cache: force-cache" and "revalidate: 3", only one should be specified.'
+        )
+      })
+    })
+  }
 })