fix: filter out middleware requests in logging (#64549)

When middleware.js is present, the logging is duplicated. We should
filter out the 1st middleware request and only log the actual one going
through request handler / renderer

Closes NEXT-3125

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

@@ -1132,12 +1132,14 @@ export default class NextNodeServer extends BaseServer {
           'originalResponse' in _res ? _res.originalResponse : _res
 
         const reqStart = Date.now()
+        const isMiddlewareRequest = req.headers['x-middleware-invoke']
 
         const reqCallback = () => {
           // we don't log for non-route requests
-          const isRouteRequest = getRequestMeta(req).match
+          const routeMatch = getRequestMeta(req).match
+
           const isRSC = isRSCRequestCheck(req)
-          if (!isRouteRequest || isRSC) return
+          if (!routeMatch || isRSC || isMiddlewareRequest) return
 
           const reqEnd = Date.now()
           const fetchMetrics = normalizedReq.fetchMetrics || []

test/e2e/app-dir/logging/app/page.js

@@ -1,3 +1,9 @@
+import Link from 'next/link'
+
 export default function Page() {
-  return 'hello world'
+  return (
+    <>
+      <Link href={'/link'}>/link</Link>
+    </>
+  )
 }

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

@@ -4,7 +4,7 @@ import stripAnsi from 'strip-ansi'
 import { retry } from 'next-test-utils'
 import { nextTestSetup } from 'e2e-utils'
 
-const cahceReasonRe = /Cache (missed|skipped) reason: /
+const cacheReasonRegex = /Cache (missed|skipped) reason: /
 
 interface ParsedLog {
   method: string
@@ -17,13 +17,13 @@ interface ParsedLog {
 function parseLogsFromCli(cliOutput: string) {
   const logs = stripAnsi(cliOutput)
     .split('\n')
-    .filter((log) => cahceReasonRe.test(log) || log.includes('GET'))
+    .filter((log) => cacheReasonRegex.test(log) || log.includes('GET'))
 
   return logs.reduce<ParsedLog[]>((parsedLogs, log) => {
-    if (cahceReasonRe.test(log)) {
+    if (cacheReasonRegex.test(log)) {
       // cache miss/skip reason
       // Example of `log`: "│ │ Cache skipped reason: (cache: no-cache)"
-      const reasonSegment = log.split(cahceReasonRe, 3)[2].trim()
+      const reasonSegment = log.split(cacheReasonRegex, 3)[2].trim()
       const reason = reasonSegment.slice(1, -1)
       parsedLogs[parsedLogs.length - 1].cache = reason
     } else {
@@ -155,15 +155,27 @@ describe('app-dir - logging', () => {
           })
         })
 
-        it('should exlucde Middleware invoked and _rsc requests', async () => {
+        it('should log each page request only once', async () => {
           const outputIndex = next.cliOutput.length
           await next.fetch('/')
+          await retry(() => {
+            const logsAfterRequest = stripAnsi(
+              next.cliOutput.slice(outputIndex)
+            )
+            // Only show `GET /` once
+            expect(logsAfterRequest.split('GET /').length).toBe(2)
+          })
+        })
+
+        it('should exlucde Middleware invoked and _rsc requests', async () => {
+          const outputIndex = next.cliOutput.length
+
           const browser = await next.browser('/link')
           await browser.elementByCss('a').click()
           await browser.waitForElementByCss('h2')
           const logs = stripAnsi(next.cliOutput.slice(outputIndex))
-          expect(logs).not.toContain('GET /_next/static')
-          expect(logs).not.toContain('GET /foo?_rsc')
+          expect(logs).not.toContain('/_next/static')
+          expect(logs).not.toContain('?_rsc')
         })
       }
     } else {