Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fetching logging on edge #56108

Merged
merged 7 commits into from
Sep 27, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -148,7 +148,11 @@ export function getRender({
const extendedRes = new WebNextResponse()

handler(extendedReq, extendedRes)
const result = await extendedRes.toResponse()

return await extendedRes.toResponse()
// fetchMetrics is attached to the web request that going through the server,
// wait for the handler result is ready and attach it back to the original request.
;(request as any).fetchMetrics = extendedReq.fetchMetrics
return result
}
}
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
import type { AsyncLocalStorage } from 'async_hooks'
import type { IncrementalCache } from '../../server/lib/incremental-cache'
import type { DynamicServerError } from './hooks-server-context'
import type { FetchMetrics } from '../../server/base-http'
import { createAsyncLocalStorage } from './async-local-storage'

export interface StaticGenerationStore {
Expand Down Expand Up @@ -36,16 +37,7 @@ export interface StaticGenerationStore {
tags?: string[]

revalidatedTags?: string[]
fetchMetrics?: Array<{
url: string
idx: number
end: number
start: number
method: string
status: number
cacheReason: string
cacheStatus: 'hit' | 'miss' | 'skip'
}>
fetchMetrics?: FetchMetrics

isDraftMode?: boolean
}
Expand Down
1 change: 1 addition & 0 deletions packages/next/src/server/app-render/app-render.tsx
Original file line number Diff line number Diff line change
Expand Up @@ -267,6 +267,7 @@ export const renderToHTMLOrFlight: AppPageRender = (
`Invariant: Render expects to have staticGenerationAsyncStorage, none found`
)
}

staticGenerationStore.fetchMetrics = []
extraRenderResultMeta.fetchMetrics = staticGenerationStore.fetchMetrics

Expand Down
11 changes: 11 additions & 0 deletions packages/next/src/server/base-http/index.ts
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,17 @@ export interface BaseNextRequestConfig {
trailingSlash?: boolean | undefined
}

export type FetchMetrics = Array<{
url: string
idx: number
end: number
start: number
method: string
status: number
cacheReason: string
cacheStatus: 'hit' | 'miss' | 'skip'
}>

export abstract class BaseNextRequest<Body = any> {
protected _cookies: NextApiRequestCookies | undefined
public abstract headers: IncomingHttpHeaders
Expand Down
3 changes: 2 additions & 1 deletion packages/next/src/server/base-http/web.ts
Original file line number Diff line number Diff line change
@@ -1,11 +1,12 @@
import type { IncomingHttpHeaders, OutgoingHttpHeaders } from 'http'
import type { FetchMetrics } from './index'
import { toNodeOutgoingHttpHeaders } from '../web/utils'

import { BaseNextRequest, BaseNextResponse } from './index'

export class WebNextRequest extends BaseNextRequest<ReadableStream | null> {
public request: Request
public headers: IncomingHttpHeaders
public fetchMetrics?: FetchMetrics

constructor(request: Request) {
const url = new URL(request.url)
Expand Down
4 changes: 4 additions & 0 deletions packages/next/src/server/next-server.ts
Original file line number Diff line number Diff line change
Expand Up @@ -1845,6 +1845,10 @@ export default class NextNodeServer extends BaseServer {
getRequestMeta(params.req, '_nextIncrementalCache'),
})

if (result.fetchMetrics) {
;(params.req as any).fetchMetrics = result.fetchMetrics
}

if (!params.res.statusCode || params.res.statusCode < 400) {
params.res.statusCode = result.response.status
params.res.statusMessage = result.response.statusText
Expand Down
2 changes: 2 additions & 0 deletions packages/next/src/server/web/adapter.ts
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,7 @@ import { PrerenderManifest } from '../../build'

class NextRequestHint extends NextRequest {
sourcePage: string
fetchMetrics?: FetchEventResult['fetchMetrics']

constructor(params: {
init: RequestInit
Expand Down Expand Up @@ -329,5 +330,6 @@ export async function adapter(
return {
response: finalResponse,
waitUntil: Promise.all(event[waitUntilSymbol]),
fetchMetrics: request.fetchMetrics,
}
}
2 changes: 2 additions & 0 deletions packages/next/src/server/web/types.ts
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@ import type { NextFetchEvent } from './spec-extension/fetch-event'
import type { NextResponse } from './spec-extension/response'
import type { CloneableBody } from '../body-streams'
import type { OutgoingHttpHeaders } from 'http'
import type { FetchMetrics } from '../base-http'

export interface RequestData {
geo?: {
Expand Down Expand Up @@ -37,6 +38,7 @@ export type NodejsRequestData = Omit<RequestData, 'body'> & {
export interface FetchEventResult {
response: Response
waitUntil: Promise<any>
fetchMetrics?: FetchMetrics
}

export type NextMiddlewareResult =
Expand Down
156 changes: 90 additions & 66 deletions test/e2e/app-dir/app-static/app-fetch-logging.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -49,102 +49,126 @@ createNextDescribe(
},
},
({ next, isNextDev }) => {
describe('with verbose logging', () => {
it('should only log requests in dev mode', async () => {
const outputIndex = next.cliOutput.length
await next.fetch('/default-cache')

await check(() => {
const logs = stripAnsi(next.cliOutput.slice(outputIndex))
const hasLogs = logs.includes('GET /default-cache 200')

if (isNextDev && hasLogs) {
return 'success'
}

if (!isNextDev && !hasLogs) {
return 'success'
}
}, 'success')
})

if (isNextDev) {
it("should log 'skip' cache status with a reason when cache: 'no-cache' is used", async () => {
function runTests({ hasLogging }: { hasLogging: boolean }) {
if (hasLogging) {
it('should only log requests in dev mode', async () => {
const outputIndex = next.cliOutput.length
await next.fetch('/default-cache')

await check(() => {
const logs = parseLogsFromCli(next.cliOutput.slice(outputIndex))

const logEntry = logs.find((log) =>
log.url.includes('api/random?no-cache')
)
const logs = stripAnsi(next.cliOutput.slice(outputIndex))
const hasLogs = logs.includes('GET /default-cache 200')

// expend full url
expect(logs.every((log) => log.url.includes('..'))).toBe(false)
if (isNextDev && hasLogs) {
return 'success'
}

if (logEntry?.cache === 'cache: no-cache') {
if (!isNextDev && !hasLogs) {
return 'success'
}
}, 'success')
})

it("should log 'skip' cache status with a reason when revalidate: 0 is used", async () => {
const outputIndex = next.cliOutput.length
await next.fetch('/default-cache')
await check(() => {
const logs = parseLogsFromCli(next.cliOutput.slice(outputIndex))
if (isNextDev) {
it("should log 'skip' cache status with a reason when cache: 'no-cache' is used", async () => {
const outputIndex = next.cliOutput.length
await next.fetch('/default-cache')

const logEntry = logs.find((log) =>
log.url.includes('api/random?revalidate-0')
)
await check(() => {
const logs = parseLogsFromCli(next.cliOutput.slice(outputIndex))

if (logEntry?.cache === 'revalidate: 0') {
return 'success'
}
}, 'success')
})
const logEntry = logs.find((log) =>
log.url.includes('api/random?no-cache')
)

it("should log 'skip' cache status with a reason when the browser indicates caching should be ignored", async () => {
const outputIndex = next.cliOutput.length
await next.fetch('/default-cache', {
headers: { 'Cache-Control': 'no-cache' },
// expend full url
expect(logs.every((log) => log.url.includes('..'))).toBe(false)

if (logEntry?.cache === 'cache: no-cache') {
return 'success'
}
}, 'success')
})
await check(() => {
const logs = parseLogsFromCli(next.cliOutput.slice(outputIndex))

const logEntry = logs.find((log) =>
log.url.includes('api/random?auto-cache')
)
it("should log 'skip' cache status with a reason when revalidate: 0 is used", async () => {
const outputIndex = next.cliOutput.length
await next.fetch('/default-cache')
await check(() => {
const logs = parseLogsFromCli(next.cliOutput.slice(outputIndex))

if (logEntry?.cache === 'cache-control: no-cache (hard refresh)') {
return 'success'
const logEntry = logs.find((log) =>
log.url.includes('api/random?revalidate-0')
)

if (logEntry?.cache === 'revalidate: 0') {
return 'success'
}
}, 'success')
})

it("should log 'skip' cache status with a reason when the browser indicates caching should be ignored", async () => {
const outputIndex = next.cliOutput.length
await next.fetch('/default-cache', {
headers: { 'Cache-Control': 'no-cache' },
})
await check(() => {
const logs = parseLogsFromCli(next.cliOutput.slice(outputIndex))

const logEntry = logs.find((log) =>
log.url.includes('api/random?auto-cache')
)

if (
logEntry?.cache === 'cache-control: no-cache (hard refresh)'
) {
return 'success'
}
}, 'success')
})
}
} else {
it('should not log fetch requests at all', async () => {
const outputIndex = next.cliOutput.length
await next.fetch('/default-cache')

await check(() => {
const logs = stripAnsi(next.cliOutput.slice(outputIndex))
if (logs.includes('GET /default-cache 200')) {
return 'fail'
}

return 'success'
}, 'success')
})
}
}

describe('with verbose logging', () => {
runTests({ hasLogging: true })
})

describe('with default logging', () => {
describe('with verbose logging for edge runtime', () => {
beforeAll(async () => {
await next.stop()
await next.deleteFile('next.config.js')
const layoutContent = await next.readFile('app/layout.js')
await next.patchFile(
'app/layout.js',
layoutContent + `\nexport const runtime = 'edge'`
)
await next.start()
})

it('should not log fetch requests at all', async () => {
const outputIndex = next.cliOutput.length
await next.fetch('/default-cache')

await check(() => {
const logs = stripAnsi(next.cliOutput.slice(outputIndex))
if (logs.includes('GET /default-cache 200')) {
return 'fail'
}
runTests({ hasLogging: false })
})

return 'success'
}, 'success')
describe('with default logging', () => {
beforeAll(async () => {
await next.stop()
await next.deleteFile('next.config.js')
await next.start()
})

runTests({ hasLogging: false })
})
}
)
Loading