From b9208563d8304a9297aa05aecd4938bf31a4976f Mon Sep 17 00:00:00 2001 From: Hendrik Liebau Date: Thu, 18 Jul 2024 13:18:40 +0200 Subject: [PATCH 1/6] Use a fixed indentation for logged fetch calls The time-based indentation could easily be confused with a hierarchy, and that wouldn't make sense. --- packages/next/src/server/next-server.ts | 38 ++----------------- .../e2e/app-dir/logging/fetch-logging.test.ts | 12 ++++-- 2 files changed, 11 insertions(+), 39 deletions(-) diff --git a/packages/next/src/server/next-server.ts b/packages/next/src/server/next-server.ts index 8fa318689be82..4c7d9cea8a859 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' @@ -1167,26 +1166,6 @@ export default class NextNodeServer extends BaseServer< ) 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 } = metric @@ -1229,26 +1208,15 @@ export default class NextNodeServer extends BaseServer< } const status = cacheColor(`(cache ${cacheStatus})`) - const newLineLeadingChar = '│' - const nestedIndent = calcNestedLevel( - fetchMetrics.slice(0, i + 1), - metric.start - ) + const indentation = '│ ' 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( - `${newLineLeadingChar}${nextNestedIndent}${newLineLeadingChar} ${cacheReasonStr}` - ) + writeStdoutLine(`${indentation}${indentation}${cacheReasonStr}`) } } } diff --git a/test/e2e/app-dir/logging/fetch-logging.test.ts b/test/e2e/app-dir/logging/fetch-logging.test.ts index 04df20d2699dd..0d79f94ff5021 100644 --- a/test/e2e/app-dir/logging/fetch-logging.test.ts +++ b/test/e2e/app-dir/logging/fetch-logging.test.ts @@ -128,10 +128,14 @@ describe('app-dir - logging', () => { 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 ') + + const expectedUrl = withFullUrlFetches + ? 'https://next-data-api-endpoint.vercel.app/api/random' + : 'https://next-data-api-en../api/random' + + expect(logs).toIncludeRepeated(' GET /default-cache', 1) + expect(logs).toIncludeRepeated(` │ GET ${expectedUrl}`, 7) + expect(logs).toIncludeRepeated(' │ │ Cache skipped reason', 3) }) }) From 995f1a60a320630416f86b8a4532ca229c366bab Mon Sep 17 00:00:00 2001 From: Hendrik Liebau Date: Thu, 18 Jul 2024 16:22:31 +0200 Subject: [PATCH 2/6] Co-locate fetch warnings with fetch metric logs As a result, fetch warnings are now only logged in dev mode, which I don't think is a bad change. --- packages/next/src/server/base-http/index.ts | 1 + packages/next/src/server/lib/patch-fetch.ts | 8 +- packages/next/src/server/next-server.ts | 113 ++++++++++-------- .../e2e/app-dir/logging/fetch-warning.test.ts | 65 +++++----- 4 files changed, 107 insertions(+), 80 deletions(-) diff --git a/packages/next/src/server/base-http/index.ts b/packages/next/src/server/base-http/index.ts index ad7c0ad0c2fb4..2bf47bc094748 100644 --- a/packages/next/src/server/base-http/index.ts +++ b/packages/next/src/server/base-http/index.ts @@ -20,6 +20,7 @@ export type FetchMetric = { status: number cacheReason: string cacheStatus: 'hit' | 'miss' | 'skip' + 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..3cd8aa0571245 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', }) @@ -713,6 +712,7 @@ function createPatchedFetcher( url: fetchUrl, cacheReason, cacheStatus: '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 4c7d9cea8a859..6f7cb3a5c163c 100644 --- a/packages/next/src/server/next-server.ts +++ b/packages/next/src/server/next-server.ts @@ -1122,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 @@ -1158,6 +1158,7 @@ export default class NextNodeServer extends BaseServer< const loggingUrl = isRSC ? stripNextRscUnionQuery(requestUrl) : requestUrl + const indentation = '│ ' writeStdoutLine( `${method} ${loggingUrl} ${color( @@ -1165,58 +1166,76 @@ export default class NextNodeServer extends BaseServer< )} in ${reqDuration}ms` ) - if (fetchMetrics.length && enabledVerboseLogging) { + if (fetchMetrics.length) { for (let i = 0; i < fetchMetrics.length; i++) { const metric = fetchMetrics[i] - let { cacheStatus, cacheReason } = metric - let cacheReasonStr = '' - - let cacheColor - const duration = metric.end - metric.start - if (cacheStatus === 'hit') { - cacheColor = green - } else { - cacheColor = yellow - const status = cacheStatus === 'skip' ? 'skipped' : 'missed' - cacheReasonStr = gray( - `Cache ${status} reason: (${white(cacheReason)})` + let { cacheStatus, cacheReason, cacheWarning, url } = metric + + if (enabledVerboseLogging) { + let cacheReasonStr = '' + + let cacheColor + const duration = metric.end - metric.start + if (cacheStatus === 'hit') { + cacheColor = green + } else { + cacheColor = yellow + const status = cacheStatus === 'skip' ? 'skipped' : 'missed' + cacheReasonStr = gray( + `Cache ${status} reason: (${white(cacheReason)})` + ) + } + + if (url.length > 48) { + const parsed = new URL(url) + const truncatedHost = formatRequestUrl( + parsed.host, + shouldTruncateUrl ? 16 : undefined + ) + const truncatedPath = formatRequestUrl( + parsed.pathname, + shouldTruncateUrl ? 24 : undefined + ) + const truncatedSearch = formatRequestUrl( + parsed.search, + shouldTruncateUrl ? 16 : undefined + ) + + url = + parsed.protocol + + '//' + + truncatedHost + + truncatedPath + + truncatedSearch + } + + const status = cacheColor(`(cache ${cacheStatus})`) + + writeStdoutLine( + `${indentation}${white( + metric.method + )} ${white(url)} ${metric.status} in ${duration}ms ${status}` ) - } - let url = metric.url - if (url.length > 48) { - const parsed = new URL(url) - const truncatedHost = formatRequestUrl( - parsed.host, - shouldTruncateUrl ? 16 : undefined - ) - const truncatedPath = formatRequestUrl( - parsed.pathname, - shouldTruncateUrl ? 24 : undefined - ) - const truncatedSearch = formatRequestUrl( - parsed.search, - shouldTruncateUrl ? 16 : undefined + if (cacheReasonStr) { + writeStdoutLine( + `${indentation}${indentation}${cacheReasonStr}` + ) + } + + if (cacheWarning) { + writeStdoutLine( + `${indentation}${indentation}${yellow(bold('⚠'))} ${white(cacheWarning)}` + ) + } + } else if (cacheWarning) { + writeStdoutLine( + `${indentation}${white(metric.method)} ${white(url)}` ) - url = - parsed.protocol + - '//' + - truncatedHost + - truncatedPath + - truncatedSearch - } - - const status = cacheColor(`(cache ${cacheStatus})`) - const indentation = '│ ' - - writeStdoutLine( - `${indentation}${white( - metric.method - )} ${white(url)} ${metric.status} in ${duration}ms ${status}` - ) - if (cacheReasonStr) { - writeStdoutLine(`${indentation}${indentation}${cacheReasonStr}`) + writeStdoutLine( + `${indentation}${indentation}${yellow(bold('⚠'))} ${white(cacheWarning)}` + ) } } } diff --git a/test/e2e/app-dir/logging/fetch-warning.test.ts b/test/e2e/app-dir/logging/fetch-warning.test.ts index c48f221dbb136..8abbec549740d 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,40 @@ 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.' + ) + }) + }) + } }) From 20529eb8b7e0de879da911b309489b942c02ab21 Mon Sep 17 00:00:00 2001 From: Hendrik Liebau Date: Thu, 18 Jul 2024 17:17:24 +0200 Subject: [PATCH 3/6] Log fetch requests during client-side navigations --- .../next/src/server/app-render/app-render.tsx | 4 ++- .../server/app-render/flight-render-result.ts | 9 ++++--- .../e2e/app-dir/logging/fetch-logging.test.ts | 25 +++++++++++++++---- 3 files changed, 29 insertions(+), 9 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/test/e2e/app-dir/logging/fetch-logging.test.ts b/test/e2e/app-dir/logging/fetch-logging.test.ts index 0d79f94ff5021..c04edd9d23bc8 100644 --- a/test/e2e/app-dir/logging/fetch-logging.test.ts +++ b/test/e2e/app-dir/logging/fetch-logging.test.ts @@ -126,13 +126,12 @@ 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)) - - const expectedUrl = withFullUrlFetches - ? 'https://next-data-api-endpoint.vercel.app/api/random' - : 'https://next-data-api-en../api/random' - expect(logs).toIncludeRepeated(' GET /default-cache', 1) expect(logs).toIncludeRepeated(` │ GET ${expectedUrl}`, 7) expect(logs).toIncludeRepeated(' │ │ Cache skipped reason', 3) @@ -195,6 +194,22 @@ 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) + }) + }) } } else { // No fetches logging enabled From 4c8eec32c26f488e60f6c5a2ec02c126683e914b Mon Sep 17 00:00:00 2001 From: Hendrik Liebau Date: Thu, 18 Jul 2024 21:41:59 +0200 Subject: [PATCH 4/6] Do not log fetch requests during HMR refreshes --- packages/next/src/server/base-http/index.ts | 2 +- packages/next/src/server/lib/patch-fetch.ts | 5 +- packages/next/src/server/next-server.ts | 125 +++++++++--------- .../e2e/app-dir/logging/fetch-logging.test.ts | 18 +++ test/lib/next-modes/base.ts | 22 ++- test/lib/next-modes/next-dev.ts | 27 ++-- 6 files changed, 121 insertions(+), 78 deletions(-) diff --git a/packages/next/src/server/base-http/index.ts b/packages/next/src/server/base-http/index.ts index 2bf47bc094748..8181508e61fa7 100644 --- a/packages/next/src/server/base-http/index.ts +++ b/packages/next/src/server/base-http/index.ts @@ -19,7 +19,7 @@ export type FetchMetric = { method: string status: number cacheReason: string - cacheStatus: 'hit' | 'miss' | 'skip' + cacheStatus: 'hit' | 'miss' | 'skip' | 'hmr' cacheWarning?: string } diff --git a/packages/next/src/server/lib/patch-fetch.ts b/packages/next/src/server/lib/patch-fetch.ts index 3cd8aa0571245..d2e3547216d2e 100644 --- a/packages/next/src/server/lib/patch-fetch.ts +++ b/packages/next/src/server/lib/patch-fetch.ts @@ -646,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 @@ -656,6 +657,8 @@ function createPatchedFetcher( ) { cachedFetchData = requestStore.serverComponentsHmrCache.get(cacheKey) + + isHmrRefreshCache = true } if (isCacheableRevalidate && !cachedFetchData) { @@ -711,7 +714,7 @@ 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 6f7cb3a5c163c..93903b464776b 100644 --- a/packages/next/src/server/next-server.ts +++ b/packages/next/src/server/next-server.ts @@ -1166,77 +1166,78 @@ export default class NextNodeServer extends BaseServer< )} in ${reqDuration}ms` ) - if (fetchMetrics.length) { - for (let i = 0; i < fetchMetrics.length; i++) { - const metric = fetchMetrics[i] - let { cacheStatus, cacheReason, cacheWarning, url } = metric - - if (enabledVerboseLogging) { - let cacheReasonStr = '' - - let cacheColor - const duration = metric.end - metric.start - if (cacheStatus === 'hit') { - cacheColor = green - } else { - cacheColor = yellow - const status = cacheStatus === 'skip' ? 'skipped' : 'missed' - cacheReasonStr = gray( - `Cache ${status} reason: (${white(cacheReason)})` - ) - } - - if (url.length > 48) { - const parsed = new URL(url) - const truncatedHost = formatRequestUrl( - parsed.host, - shouldTruncateUrl ? 16 : undefined - ) - const truncatedPath = formatRequestUrl( - parsed.pathname, - shouldTruncateUrl ? 24 : undefined - ) - const truncatedSearch = formatRequestUrl( - parsed.search, - shouldTruncateUrl ? 16 : undefined - ) - - url = - parsed.protocol + - '//' + - truncatedHost + - truncatedPath + - truncatedSearch - } - - const status = cacheColor(`(cache ${cacheStatus})`) + for (let i = 0; i < fetchMetrics.length; i++) { + const metric = fetchMetrics[i] + let { cacheStatus, cacheReason, cacheWarning, url } = metric - writeStdoutLine( - `${indentation}${white( - metric.method - )} ${white(url)} ${metric.status} in ${duration}ms ${status}` + if (cacheStatus === 'hmr') { + // Cache hits during HMR refreshes are intentionally not logged. + continue + } + + if (enabledVerboseLogging) { + let cacheReasonStr = '' + + let cacheColor + const duration = metric.end - metric.start + if (cacheStatus === 'hit') { + cacheColor = green + } else { + cacheColor = yellow + const status = cacheStatus === 'skip' ? 'skipped' : 'missed' + cacheReasonStr = gray( + `Cache ${status} reason: (${white(cacheReason)})` ) + } - if (cacheReasonStr) { - writeStdoutLine( - `${indentation}${indentation}${cacheReasonStr}` - ) - } - - if (cacheWarning) { - writeStdoutLine( - `${indentation}${indentation}${yellow(bold('⚠'))} ${white(cacheWarning)}` - ) - } - } else if (cacheWarning) { - writeStdoutLine( - `${indentation}${white(metric.method)} ${white(url)}` + if (url.length > 48) { + const parsed = new URL(url) + const truncatedHost = formatRequestUrl( + parsed.host, + shouldTruncateUrl ? 16 : undefined + ) + const truncatedPath = formatRequestUrl( + parsed.pathname, + shouldTruncateUrl ? 24 : undefined + ) + const truncatedSearch = formatRequestUrl( + parsed.search, + shouldTruncateUrl ? 16 : undefined ) + url = + parsed.protocol + + '//' + + truncatedHost + + truncatedPath + + truncatedSearch + } + + const status = cacheColor(`(cache ${cacheStatus})`) + + writeStdoutLine( + `${indentation}${white( + metric.method + )} ${white(url)} ${metric.status} in ${duration}ms ${status}` + ) + + if (cacheReasonStr) { + writeStdoutLine(`${indentation}${indentation}${cacheReasonStr}`) + } + + if (cacheWarning) { writeStdoutLine( `${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/logging/fetch-logging.test.ts b/test/e2e/app-dir/logging/fetch-logging.test.ts index c04edd9d23bc8..1bfbedbe2ef87 100644 --- a/test/e2e/app-dir/logging/fetch-logging.test.ts +++ b/test/e2e/app-dir/logging/fetch-logging.test.ts @@ -210,6 +210,24 @@ describe('app-dir - logging', () => { 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/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 } } From a8bf119b6d5daa7cfdbab0be86da11e482586cce Mon Sep 17 00:00:00 2001 From: Hendrik Liebau Date: Thu, 18 Jul 2024 22:26:17 +0200 Subject: [PATCH 5/6] Fix string expectations in "app-dir - fetch warnings" test --- test/e2e/app-dir/logging/fetch-warning.test.ts | 15 ++++++--------- 1 file changed, 6 insertions(+), 9 deletions(-) diff --git a/test/e2e/app-dir/logging/fetch-warning.test.ts b/test/e2e/app-dir/logging/fetch-warning.test.ts index 8abbec549740d..104e80d16d63c 100644 --- a/test/e2e/app-dir/logging/fetch-warning.test.ts +++ b/test/e2e/app-dir/logging/fetch-warning.test.ts @@ -24,27 +24,24 @@ describe('app-dir - fetch warnings', () => { 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. - `) + │ 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 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. - `) + │ 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 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. - `) + │ 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 { From 2808880029045ccfeb2775e2aa0551156a572752 Mon Sep 17 00:00:00 2001 From: Hendrik Liebau Date: Thu, 18 Jul 2024 22:36:20 +0200 Subject: [PATCH 6/6] Update log expectation in "app-dir static/dynamic handling" test --- .../e2e/app-dir/app-static/app-static.test.ts | 19 ++++++++++++------- 1 file changed, 12 insertions(+), 7 deletions(-) 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.`) + }) } })