From 0c3b063d09dc7ddcf9e308f2d2848f4c558c748b Mon Sep 17 00:00:00 2001 From: Hendrik Liebau Date: Fri, 19 Jul 2024 17:15:37 +0200 Subject: [PATCH] Log fetch requests during client-side navigation (#67925) When the config `logging.fetches` (see https://nextjs.org/docs/app/api-reference/next-config-js/logging) is defined, any fetch requests that are done in server components should be logged. This is currently not the case for client-side navigations in the app router. This PR fixes that, and also cleans up the log format a bit. In addition, cached requests for the purpose of HMR refreshes (see #67527) are explicitly omitted from the logs. **Before** fetch logs before **After** fetch logs after Note that warnings for conflicting fetch cache configs are now co-located with the logged fetch metrics. If `logging.fetches` is not enabled, the warnings are still logged, as was the case before. They are now only logged in dev mode though, which was not the case before. --- .../next/src/server/app-render/app-render.tsx | 4 +- .../server/app-render/flight-render-result.ts | 9 ++- packages/next/src/server/base-http/index.ts | 3 +- packages/next/src/server/lib/patch-fetch.ts | 13 ++-- packages/next/src/server/next-server.ts | 60 +++++++----------- .../e2e/app-dir/app-static/app-static.test.ts | 19 +++--- .../e2e/app-dir/logging/fetch-logging.test.ts | 45 ++++++++++++-- .../e2e/app-dir/logging/fetch-warning.test.ts | 62 ++++++++++--------- test/lib/next-modes/base.ts | 22 +++++-- test/lib/next-modes/next-dev.ts | 27 +++++--- 10 files changed, 164 insertions(+), 100 deletions(-) diff --git a/packages/next/src/server/app-render/app-render.tsx b/packages/next/src/server/app-render/app-render.tsx index 452c48210c984..69244d53675fa 100644 --- a/packages/next/src/server/app-render/app-render.tsx +++ b/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 = { diff --git a/packages/next/src/server/app-render/flight-render-result.ts b/packages/next/src/server/app-render/flight-render-result.ts index f14dfbc97b94b..d447d1680fb6f 100644 --- a/packages/next/src/server/app-render/flight-render-result.ts +++ b/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) { - super(response, { contentType: RSC_CONTENT_TYPE_HEADER, metadata: {} }) + constructor( + response: string | ReadableStream, + metadata: RenderResultMetadata = {} + ) { + super(response, { contentType: RSC_CONTENT_TYPE_HEADER, metadata }) } } diff --git a/packages/next/src/server/base-http/index.ts b/packages/next/src/server/base-http/index.ts index ad7c0ad0c2fb4..8181508e61fa7 100644 --- a/packages/next/src/server/base-http/index.ts +++ b/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 diff --git a/packages/next/src/server/lib/patch-fetch.ts b/packages/next/src/server/lib/patch-fetch.ts index 6596931950634..d2e3547216d2e 100644 --- a/packages/next/src/server/lib/patch-fetch.ts +++ b/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', }) diff --git a/packages/next/src/server/next-server.ts b/packages/next/src/server/next-server.ts index 8fa318689be82..93903b464776b 100644 --- a/packages/next/src/server/next-server.ts +++ b/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,6 +1158,7 @@ export default class NextNodeServer extends BaseServer< const loggingUrl = isRSC ? stripNextRscUnionQuery(requestUrl) : requestUrl + const indentation = '│ ' writeStdoutLine( `${method} ${loggingUrl} ${color( @@ -1166,30 +1166,16 @@ export default class NextNodeServer extends BaseServer< )} 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 diff --git a/test/e2e/app-dir/app-static/app-static.test.ts b/test/e2e/app-dir/app-static/app-static.test.ts index 266de2235a896..899cffcd29218 100644 --- a/test/e2e/app-dir/app-static/app-static.test.ts +++ b/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.`) + }) } }) diff --git a/test/e2e/app-dir/logging/fetch-logging.test.ts b/test/e2e/app-dir/logging/fetch-logging.test.ts index 04df20d2699dd..1bfbedbe2ef87 100644 --- a/test/e2e/app-dir/logging/fetch-logging.test.ts +++ b/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 diff --git a/test/e2e/app-dir/logging/fetch-warning.test.ts b/test/e2e/app-dir/logging/fetch-warning.test.ts index c48f221dbb136..104e80d16d63c 100644 --- a/test/e2e/app-dir/logging/fetch-warning.test.ts +++ b/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.' + ) + }) + }) + } }) diff --git a/test/lib/next-modes/base.ts b/test/lib/next-modes/base.ts index 2e21275aa0609..ea92f26de5b6b 100644 --- a/test/lib/next-modes/base.ts +++ b/test/lib/next-modes/base.ts @@ -8,7 +8,7 @@ import { ChildProcess } from 'child_process' import { createNextInstall } from '../create-next-install' import { Span } from 'next/dist/trace' import webdriver from '../next-webdriver' -import { renderViaHTTP, fetchViaHTTP, findPort } from 'next-test-utils' +import { renderViaHTTP, fetchViaHTTP, findPort, retry } from 'next-test-utils' import cheerio from 'cheerio' import { once } from 'events' import { BrowserInterface } from '../browsers/base' @@ -490,19 +490,31 @@ export class NextInstance { public async patchFile( filename: string, - content: string | ((contents: string) => string) + content: string | ((content: string) => string), + retryWithTempContent?: (context: { newFile: boolean }) => Promise ): Promise<{ newFile: boolean }> { const outputPath = path.join(this.testDir, filename) const newFile = !existsSync(outputPath) await fs.mkdir(path.dirname(outputPath), { recursive: true }) + const previousContent = newFile ? undefined : await this.readFile(filename) await fs.writeFile( outputPath, - typeof content === 'function' - ? content(await this.readFile(filename)) - : content + typeof content === 'function' ? content(previousContent) : content ) + if (retryWithTempContent) { + try { + await retry(() => retryWithTempContent({ newFile })) + } finally { + if (previousContent === undefined) { + await fs.rm(outputPath) + } else { + await fs.writeFile(outputPath, previousContent) + } + } + } + return { newFile } } diff --git a/test/lib/next-modes/next-dev.ts b/test/lib/next-modes/next-dev.ts index b817bc8ddfc07..facd516574790 100644 --- a/test/lib/next-modes/next-dev.ts +++ b/test/lib/next-modes/next-dev.ts @@ -152,7 +152,8 @@ export class NextDevInstance extends NextInstance { public override async patchFile( filename: string, - content: string | ((contents: string) => string) + content: string | ((contents: string) => string), + retryWithTempContent?: (context: { newFile: boolean }) => Promise ) { const isServerRunning = this.childProcess && !this.isStopping const cliOutputLength = this.cliOutput.length @@ -161,20 +162,28 @@ export class NextDevInstance extends NextInstance { await this.handleDevWatchDelayBeforeChange(filename) } - const { newFile } = await super.patchFile(filename, content) - - if (isServerRunning) { - if (newFile) { - await this.handleDevWatchDelayAfterChange(filename) - } else if (filename.startsWith('next.config')) { - await retry(() => { + const waitForChanges = async ({ newFile }: { newFile: boolean }) => { + if (isServerRunning) { + if (newFile) { + await this.handleDevWatchDelayAfterChange(filename) + } else if (filename.startsWith('next.config')) { if (!this.cliOutput.slice(cliOutputLength).includes('Ready in')) { throw new Error('Server has not finished restarting.') } - }) + } } } + if (retryWithTempContent) { + return super.patchFile(filename, content, async ({ newFile }) => { + await waitForChanges({ newFile }) + await retryWithTempContent({ newFile }) + }) + } + + const { newFile } = await super.patchFile(filename, content) + await retry(() => waitForChanges({ newFile })) + return { newFile } }