From afa9f965157ce60b5d65d1b3d8981e57b06d8e9b Mon Sep 17 00:00:00 2001 From: Zack Tanner Date: Fri, 28 Jul 2023 13:01:31 -0700 Subject: [PATCH] add a "skip" cache type to verbose logging mode (#53275) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit When verbose logging is enabled and a cache MISS is logged due to either `revalidate: 0`,`cache: no-store` or `cache-control: no-store`, this logs a slightly different message, ie: ``` - GET / 200 in 804ms ├─── GET in 205ms (cache: SKIP, reason: cache: no-cache) ├────── GET 200 in 0ms (cache: HIT) ├────── GET 200 in 373ms (cache: SKIP, reason: revalidate: 0) └────── GET 200 in 111ms (cache: SKIP, reason: cache-control: no-cache (hard refresh)) ``` Closes NEXT-1412 --- .../static-generation-async-storage.ts | 3 +- packages/next/src/server/lib/patch-fetch.ts | 22 +++-- packages/next/src/server/next-server.ts | 5 +- .../app-static/app-fetch-logging.test.ts | 93 +++++++++++++++++-- .../app-static/app/default-cache/page.js | 20 +++- 5 files changed, 120 insertions(+), 23 deletions(-) diff --git a/packages/next/src/client/components/static-generation-async-storage.ts b/packages/next/src/client/components/static-generation-async-storage.ts index 288f64d363..9f481c4b4e 100644 --- a/packages/next/src/client/components/static-generation-async-storage.ts +++ b/packages/next/src/client/components/static-generation-async-storage.ts @@ -43,7 +43,8 @@ export interface StaticGenerationStore { start: number method: string status: number - cacheStatus: 'hit' | 'miss' + cacheReason: string + cacheStatus: 'hit' | 'miss' | 'skip' }> isDraftMode?: boolean diff --git a/packages/next/src/server/lib/patch-fetch.ts b/packages/next/src/server/lib/patch-fetch.ts index f8fd844808..218c250514 100644 --- a/packages/next/src/server/lib/patch-fetch.ts +++ b/packages/next/src/server/lib/patch-fetch.ts @@ -33,7 +33,7 @@ function trackFetchMetric( status: number method: string cacheReason: string - cacheStatus: 'hit' | 'miss' + cacheStatus: 'hit' | 'miss' | 'skip' start: number } ) { @@ -56,6 +56,7 @@ function trackFetchMetric( staticGenerationStore.fetchMetrics.push({ url: ctx.url, cacheStatus: ctx.cacheStatus, + cacheReason: ctx.cacheReason, status: ctx.status, method: ctx.method, start: ctx.start, @@ -176,6 +177,7 @@ export function patchFetch({ staticGenerationStore.fetchCache === 'force-no-store' let _cache = getRequestMeta('cache') + let cacheReason = '' if ( typeof _cache === 'string' && @@ -192,12 +194,12 @@ export function patchFetch({ } if (['no-cache', 'no-store'].includes(_cache || '')) { curRevalidate = 0 + cacheReason = `cache: ${_cache}` } if (typeof curRevalidate === 'number' || curRevalidate === false) { revalidate = curRevalidate } - let cacheReason = '' const _headers = getRequestMeta('headers') const initHeaders: Headers = typeof _headers?.get === 'function' @@ -342,7 +344,10 @@ export function patchFetch({ const normalizedRevalidate = typeof revalidate !== 'number' ? CACHE_ONE_YEAR : revalidate - const doOriginalFetch = async (isStale?: boolean) => { + const doOriginalFetch = async ( + isStale?: boolean, + cacheReasonOverride?: string + ) => { // add metadata to init without editing the original const clonedInit = { ...init, @@ -354,8 +359,9 @@ export function patchFetch({ trackFetchMetric(staticGenerationStore, { start: fetchStart, url: fetchUrl, - cacheReason, - cacheStatus: 'miss', + cacheReason: cacheReasonOverride || cacheReason, + cacheStatus: + revalidate === 0 || cacheReasonOverride ? 'skip' : 'miss', status: res.status, method: clonedInit.method || 'GET', }) @@ -403,6 +409,7 @@ export function patchFetch({ } let handleUnlock = () => Promise.resolve() + let cacheReasonOverride if (cacheKey && staticGenerationStore.incrementalCache) { handleUnlock = await staticGenerationStore.incrementalCache.lock( @@ -421,6 +428,9 @@ export function patchFetch({ if (entry) { await handleUnlock() + } else { + // in dev, incremental cache response will be null in case the browser adds `cache-control: no-cache` in the request headers + cacheReasonOverride = 'cache-control: no-cache (hard refresh)' } if (entry?.value && entry.value.kind === 'FETCH') { @@ -545,7 +555,7 @@ export function patchFetch({ } } - return doOriginalFetch().finally(handleUnlock) + return doOriginalFetch(false, cacheReasonOverride).finally(handleUnlock) } ) } diff --git a/packages/next/src/server/next-server.ts b/packages/next/src/server/next-server.ts index fa9ec4243e..92817d7100 100644 --- a/packages/next/src/server/next-server.ts +++ b/packages/next/src/server/next-server.ts @@ -1125,11 +1125,14 @@ export default class NextNodeServer extends BaseServer { for (let i = 0; i < fetchMetrics.length; i++) { const metric = fetchMetrics[i] const lastItem = i === fetchMetrics.length - 1 - let cacheStatus = metric.cacheStatus + let { cacheStatus, cacheReason } = metric + const duration = metric.end - metric.start if (cacheStatus === 'hit') { cacheStatus = chalk.green('HIT') + } else if (cacheStatus === 'skip') { + cacheStatus = `${chalk.yellow('SKIP')}, reason: ${cacheReason}` } else { cacheStatus = chalk.yellow('MISS') } diff --git a/test/e2e/app-dir/app-static/app-fetch-logging.test.ts b/test/e2e/app-dir/app-static/app-fetch-logging.test.ts index 188e9a6a02..360dc3f191 100644 --- a/test/e2e/app-dir/app-static/app-fetch-logging.test.ts +++ b/test/e2e/app-dir/app-static/app-fetch-logging.test.ts @@ -1,7 +1,30 @@ import path from 'path' -import { createNextDescribe, FileRef } from 'e2e-utils' +import { createNextDescribe, FileRef } from '../../../lib/e2e-utils' import stripAnsi from 'strip-ansi' +function parseLogsFromCli(cliOutput: string) { + return stripAnsi(cliOutput) + .split('\n') + .filter((log) => log.includes('cache:')) + .map((log) => { + const trimmedLog = log.replace(/^[^a-zA-Z]+/, '') + const parts = trimmedLog.split(' ') + const method = parts[0] + const url = parts[1] + const statusCode = parseInt(parts[2]) + const responseTime = parseInt(parts[4]) + const cache = parts.slice(5).join(' ') + + return { + method, + url, + statusCode, + responseTime, + cache, + } + }) +} + createNextDescribe( 'app-dir - data fetching with cache logging', { @@ -15,21 +38,65 @@ createNextDescribe( }, }, ({ next, isNextDev }) => { - function runTests({ isVerbose }: { isVerbose: boolean }) { - it('should not log fetching hits in dev mode by default', async () => { + describe('with verbose logging', () => { + it('should only log requests in dev mode', async () => { await next.fetch('/default-cache') - const logs = stripAnsi(next.cliOutput) - if (isVerbose && isNextDev) { + + if (isNextDev) { expect(logs).toContain('GET /default-cache 200') } else { expect(logs).not.toContain('GET /default-cache 200') } - }) - } - describe('with logging verbose', () => { - runTests({ isVerbose: true }) + await next.stop() + }) + + if (isNextDev) { + it("should log 'skip' cache status with a reason when cache: 'no-cache' is used", async () => { + await next.start() + await next.fetch('/default-cache') + const logs = parseLogsFromCli(next.cliOutput) + const logEntry = logs.find((log) => + log.url.includes('api/random?no-cache') + ) + + expect(logEntry?.cache).toMatchInlineSnapshot( + `"(cache: SKIP, reason: cache: no-cache)"` + ) + await next.stop() + }) + + it("should log 'skip' cache status with a reason when revalidate: 0 is used", async () => { + await next.start() + await next.fetch('/default-cache') + const logs = parseLogsFromCli(next.cliOutput) + const logEntry = logs.find((log) => + log.url.includes('api/random?revalidate-0') + ) + + expect(logEntry?.cache).toMatchInlineSnapshot( + `"(cache: SKIP, reason: revalidate: 0)"` + ) + await next.stop() + }) + + it("should log 'skip' cache status with a reason when the browser indicates caching should be ignored", async () => { + await next.start() + await next.fetch('/default-cache', { + headers: { 'Cache-Control': 'no-cache' }, + }) + const logs = parseLogsFromCli(next.cliOutput) + const logEntry = logs.find((log) => + log.url.includes('api/random?auto-cache') + ) + + expect(logEntry?.cache).toMatchInlineSnapshot( + `"(cache: SKIP, reason: cache-control: no-cache (hard refresh))"` + ) + await next.stop() + }) + } }) describe('with default logging', () => { @@ -38,7 +105,13 @@ createNextDescribe( await next.deleteFile('next.config.js') await next.start() }) - runTests({ isVerbose: false }) + + it('should not log fetch requests at all', async () => { + await next.fetch('/default-cache') + const logs = stripAnsi(next.cliOutput) + + expect(logs).not.toContain('GET /default-cache 200') + }) }) } ) diff --git a/test/e2e/app-dir/app-static/app/default-cache/page.js b/test/e2e/app-dir/app-static/app/default-cache/page.js index c9935caeec..aee6e7fdab 100644 --- a/test/e2e/app-dir/app-static/app/default-cache/page.js +++ b/test/e2e/app-dir/app-static/app/default-cache/page.js @@ -2,21 +2,30 @@ export const fetchCache = 'default-cache' export default async function Page() { const dataNoCache = await fetch( - 'https://next-data-api-endpoint.vercel.app/api/random?a1', + 'https://next-data-api-endpoint.vercel.app/api/random?no-cache', { cache: 'no-cache', } ).then((res) => res.text()) const dataForceCache = await fetch( - 'https://next-data-api-endpoint.vercel.app/api/random?b2', + 'https://next-data-api-endpoint.vercel.app/api/random?force-cache', { cache: 'force-cache', } ).then((res) => res.text()) + const dataRevalidate0 = await fetch( + 'https://next-data-api-endpoint.vercel.app/api/random?revalidate-0', + { + next: { + revalidate: 0, + }, + } + ).then((res) => res.text()) + const dataRevalidateCache = await fetch( - 'https://next-data-api-endpoint.vercel.app/api/random?c3', + 'https://next-data-api-endpoint.vercel.app/api/random?revalidate-3', { next: { revalidate: 3, @@ -25,7 +34,7 @@ export default async function Page() { ).then((res) => res.text()) const dataRevalidateAndFetchCache = await fetch( - 'https://next-data-api-endpoint.vercel.app/api/random?d4', + 'https://next-data-api-endpoint.vercel.app/api/random?revalidate-3-force-cache', { next: { revalidate: 3, @@ -35,7 +44,7 @@ export default async function Page() { ).then((res) => res.text()) const dataAutoCache = await fetch( - 'https://next-data-api-endpoint.vercel.app/api/random?d4' + 'https://next-data-api-endpoint.vercel.app/api/random?auto-cache' ).then((res) => res.text()) return ( @@ -43,6 +52,7 @@ export default async function Page() {

/force-cache

"cache: no-cache" {dataNoCache}

"cache: force-cache" {dataForceCache}

+

"revalidate: 0" {dataRevalidate0}

"revalidate: 3" {dataRevalidateCache}

"revalidate: 3 and cache: force-cache" {dataRevalidateAndFetchCache}