fix: filter out middleware requests in logging

[huozhi]

What

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

[ijjk]

Tests Passed

[ijjk]

Stats from current PR

Default Build

General Overall increase ⚠️

	vercel/next.js canary	vercel/next.js fix/duplicated-middleware-log	Change
buildDuration	15.9s	16s	N/A
buildDurationCached	8.8s	7.4s	N/A
nodeModulesSize	199 MB	199 MB	⚠️ +852 B
nextStartRea..uration (ms)	431ms	437ms	N/A

Client Bundles (main, webpack)

	vercel/next.js canary	vercel/next.js fix/duplicated-middleware-log	Change
2453-HASH.js gzip	31.4 kB	31.4 kB	N/A
3304.HASH.js gzip	181 B	181 B	✓
3f784ff6-HASH.js gzip	53.7 kB	53.7 kB	✓
8299-HASH.js gzip	5.1 kB	5.1 kB	N/A
framework-HASH.js gzip	45.2 kB	45.2 kB	✓
main-app-HASH.js gzip	242 B	242 B	✓
main-HASH.js gzip	29.6 kB	29.7 kB	N/A
webpack-HASH.js gzip	1.68 kB	1.68 kB	N/A
Overall change	99.3 kB	99.3 kB	✓

Legacy Client Bundles (polyfills)

	vercel/next.js canary	vercel/next.js fix/duplicated-middleware-log	Change
polyfills-HASH.js gzip	31 kB	31 kB	✓
Overall change	31 kB	31 kB	✓

Client Pages

	vercel/next.js canary	vercel/next.js fix/duplicated-middleware-log	Change
_app-HASH.js gzip	196 B	197 B	N/A
_error-HASH.js gzip	184 B	184 B	✓
amp-HASH.js gzip	505 B	505 B	✓
css-HASH.js gzip	324 B	325 B	N/A
dynamic-HASH.js gzip	2.5 kB	2.5 kB	N/A
edge-ssr-HASH.js gzip	258 B	258 B	✓
head-HASH.js gzip	352 B	352 B	✓
hooks-HASH.js gzip	370 B	371 B	N/A
image-HASH.js gzip	4.27 kB	4.27 kB	✓
index-HASH.js gzip	259 B	259 B	✓
link-HASH.js gzip	2.67 kB	2.67 kB	N/A
routerDirect..HASH.js gzip	314 B	312 B	N/A
script-HASH.js gzip	386 B	386 B	✓
withRouter-HASH.js gzip	309 B	309 B	✓
1afbb74e6ecf..834.css gzip	106 B	106 B	✓
Overall change	6.63 kB	6.63 kB	✓

Client Build Manifests

	vercel/next.js canary	vercel/next.js fix/duplicated-middleware-log	Change
_buildManifest.js gzip	483 B	485 B	N/A
Overall change	0 B	0 B	✓

Rendered Page Sizes

	vercel/next.js canary	vercel/next.js fix/duplicated-middleware-log	Change
index.html gzip	529 B	529 B	✓
link.html gzip	542 B	542 B	✓
withRouter.html gzip	524 B	524 B	✓
Overall change	1.59 kB	1.59 kB	✓

Edge SSR bundle Size

	vercel/next.js canary	vercel/next.js fix/duplicated-middleware-log	Change
edge-ssr.js gzip	95.5 kB	95.5 kB	N/A
page.js gzip	3.05 kB	3.05 kB	N/A
Overall change	0 B	0 B	✓

Middleware size

	vercel/next.js canary	vercel/next.js fix/duplicated-middleware-log	Change
middleware-b..fest.js gzip	623 B	625 B	N/A
middleware-r..fest.js gzip	155 B	156 B	N/A
middleware.js gzip	25.5 kB	25.5 kB	N/A
edge-runtime..pack.js gzip	839 B	839 B	✓
Overall change	839 B	839 B	✓

Next Runtimes

	vercel/next.js canary	vercel/next.js fix/duplicated-middleware-log	Change
app-page-exp...dev.js gzip	171 kB	171 kB	✓
app-page-exp..prod.js gzip	97.5 kB	97.5 kB	✓
app-page-tur..prod.js gzip	99.2 kB	99.2 kB	✓
app-page-tur..prod.js gzip	93.5 kB	93.5 kB	✓
app-page.run...dev.js gzip	145 kB	145 kB	✓
app-page.run..prod.js gzip	92 kB	92 kB	✓
app-route-ex...dev.js gzip	21.5 kB	21.5 kB	✓
app-route-ex..prod.js gzip	15.2 kB	15.2 kB	✓
app-route-tu..prod.js gzip	15.2 kB	15.2 kB	✓
app-route-tu..prod.js gzip	14.9 kB	14.9 kB	✓
app-route.ru...dev.js gzip	21.1 kB	21.1 kB	✓
app-route.ru..prod.js gzip	14.9 kB	14.9 kB	✓
pages-api-tu..prod.js gzip	9.55 kB	9.55 kB	✓
pages-api.ru...dev.js gzip	9.82 kB	9.82 kB	✓
pages-api.ru..prod.js gzip	9.55 kB	9.55 kB	✓
pages-turbo...prod.js gzip	22.5 kB	22.5 kB	✓
pages.runtim...dev.js gzip	23.1 kB	23.1 kB	✓
pages.runtim..prod.js gzip	22.5 kB	22.5 kB	✓
server.runti..prod.js gzip	51.5 kB	51.5 kB	✓
Overall change	949 kB	949 kB	✓

build cache

	vercel/next.js canary	vercel/next.js fix/duplicated-middleware-log	Change
0.pack gzip	1.59 MB	1.59 MB	N/A
index.pack gzip	107 kB	107 kB	N/A
Overall change	0 B	0 B	✓

Diff details

Diff for middleware.js

Diff too large to display

Commit: 264d1d9

[eps1lon]

Why does the PR say it's related to middleware request logging but then we add a test for logging page requests only once? I'm not familiar with the intended behavior so I probably missed something.

[huozhi]

It's because in that testing project we have a middleware.js

So a request goes like req -> middleware -> request handler. And it will pass through the handling in next-server twice. We logged in both middleware phase and the final request handler phase. So we checked the header if the 1st request is for middleware. Then when you request a path like GET /foo you won't see it's logged in next-server twice.

[eps1lon]

I believe I get it now 😄