Ensure "[Fast Refresh] rebuilding" logs have a matching "[Fast Refresh] done" log

Author: eps1lon

packages/next/src/client/components/react-dev-overlay/app/hot-reloader-client.tsx

@@ -59,7 +59,6 @@ function onFastRefresh(
   updatedModules: ReadonlyArray<string>
 ) {
   dispatcher.onBuildOk()
-
   reportHmrLatency(sendMessage, updatedModules)
 
   dispatcher.onRefresh()
@@ -161,6 +160,7 @@ function tryApplyUpdates(
 ) {
   if (!isUpdateAvailable() || !canApplyUpdates()) {
     dispatcher.onBuildOk()
+    reportHmrLatency(sendMessage, [])
     return
   }
 
@@ -430,7 +430,6 @@ function processMessage(
         router.hmrRefresh()
         dispatcher.onRefresh()
       })
-      reportHmrLatency(sendMessage, [])
 
       if (process.env.__NEXT_TEST_MODE) {
         if (self.__NEXT_HMR_CB) {

test/development/app-hmr/hmr.test.ts

@@ -3,8 +3,6 @@ import { retry, waitFor } from 'next-test-utils'
 
 const envFile = '.env.development.local'
 
-const isPPREnabledByDefault = process.env.__NEXT_EXPERIMENTAL_PPR === 'true'
-
 describe(`app-dir-hmr`, () => {
   const { next } = nextTestSetup({
     files: __dirname,
@@ -73,58 +71,67 @@ describe(`app-dir-hmr`, () => {
             const fastRefreshLogs = logs.filter((log) => {
               return log.message.startsWith('[Fast Refresh]')
             })
-            // FIXME:  3+ "rebuilding" but single "done" is confusing.
+            // FIXME:  3+ "rebuilding" but no "done" is confusing.
             // There may actually be more "rebuilding" but not reliably.
             // To ignore this flakiness, we just assert on subset matches.
             // Once the  bug is fixed, each "rebuilding" should be paired with a "done in" exactly.
             expect(fastRefreshLogs).toEqual(
               expect.arrayContaining([
                 { source: 'log', message: '[Fast Refresh] rebuilding' },
                 { source: 'log', message: '[Fast Refresh] rebuilding' },
-                {
-                  source: 'log',
-                  message: expect.stringContaining('[Fast Refresh] done in '),
-                },
                 { source: 'log', message: '[Fast Refresh] rebuilding' },
               ])
             )
+            // FIXME: Turbopack should have matching "done in" for each "rebuilding"
+            expect(logs).not.toEqual(
+              expect.arrayContaining([
+                expect.objectContaining({
+                  message: expect.stringContaining('[Fast Refresh] done in'),
+                  source: 'log',
+                }),
+              ])
+            )
           })
         } else {
           await retry(
             async () => {
-              const fastRefreshLogs = logs.filter((log) => {
-                return log.message.startsWith('[Fast Refresh]')
+              const envValue = await browser.elementByCss('p').text()
+              const mpa = await browser.eval(
+                'window.__TEST_NO_RELOAD === undefined'
+              )
+              // Used to be flaky but presumably no longer is.
+              // If this flakes again, please add the received value as a commnet.
+              expect({ envValue, mpa }).toEqual({
+                envValue: 'ipad',
+                mpa: false,
               })
-              // FIXME: Should be either a single "rebuilding"+"done" or the last "rebuilding" should be followed by "done"
-              expect(fastRefreshLogs).toEqual([
-                { source: 'log', message: '[Fast Refresh] rebuilding' },
-                { source: 'log', message: '[Fast Refresh] rebuilding' },
-                {
-                  source: 'log',
-                  message: expect.stringContaining('[Fast Refresh] done in '),
-                },
-                { source: 'log', message: '[Fast Refresh] rebuilding' },
-              ])
             },
             // Very slow Hot Update for some reason.
             // May be related to receiving 3 rebuild events but only one finish event
             5000
           )
+
+          const fastRefreshLogs = logs.filter((log) => {
+            return log.message.startsWith('[Fast Refresh]')
+          })
+          expect(fastRefreshLogs).toEqual([
+            { source: 'log', message: '[Fast Refresh] rebuilding' },
+            {
+              source: 'log',
+              message: expect.stringContaining('[Fast Refresh] done in '),
+            },
+            { source: 'log', message: '[Fast Refresh] rebuilding' },
+            { source: 'log', message: '[Fast Refresh] rebuilding' },
+            {
+              source: 'log',
+              message: expect.stringContaining('[Fast Refresh] done in '),
+            },
+            {
+              source: 'log',
+              message: expect.stringContaining('[Fast Refresh] done in '),
+            },
+          ])
         }
-        const envValue = await browser.elementByCss('p').text()
-        const mpa = await browser.eval('window.__TEST_NO_RELOAD === undefined')
-        // Flaky sometimes in Webpack:
-        // A. misses update and just receives `{ envValue: 'mac', mpa: false }`
-        // B. triggers error on server resulting in MPA: `{ envValue: 'ipad', mpa: true }` and server logs: ⨯ [TypeError: Cannot read properties of undefined (reading 'polyfillFiles')] ⨯ [TypeError: Cannot read properties of null (reading 'default')]
-        // A is more common than B.
-        expect({ envValue, mpa }).toEqual({
-          envValue:
-            isPPREnabledByDefault && !process.env.TURBOPACK
-              ? // FIXME: Should be 'ipad' but PPR+Webpack swallows the update reliably
-                'mac'
-              : 'ipad',
-          mpa: false,
-        })
       } finally {
         await next.patchFile(envFile, envContent)
       }
@@ -158,14 +165,26 @@ describe(`app-dir-hmr`, () => {
           expect(await browser.elementByCss('p').text()).toBe('ipad')
         })
 
-        expect(logs).toEqual(
-          expect.arrayContaining([
-            expect.objectContaining({
-              message: expect.stringContaining('[Fast Refresh] done in'),
-              source: 'log',
-            }),
-          ])
-        )
+        if (process.env.TURBOPACK) {
+          // FIXME: Turbopack should have matching "done in" for each "rebuilding"
+          expect(logs).not.toEqual(
+            expect.arrayContaining([
+              expect.objectContaining({
+                message: expect.stringContaining('[Fast Refresh] done in'),
+                source: 'log',
+              }),
+            ])
+          )
+        } else {
+          expect(logs).toEqual(
+            expect.arrayContaining([
+              expect.objectContaining({
+                message: expect.stringContaining('[Fast Refresh] done in'),
+                source: 'log',
+              }),
+            ])
+          )
+        }
       } finally {
         await next.patchFile(envFile, envContent)
       }
@@ -198,14 +217,26 @@ describe(`app-dir-hmr`, () => {
           expect(await browser.elementByCss('p').text()).toBe('ipad')
         })
 
-        expect(logs).toEqual(
-          expect.arrayContaining([
-            expect.objectContaining({
-              message: expect.stringContaining('[Fast Refresh] done in'),
-              source: 'log',
-            }),
-          ])
-        )
+        if (process.env.TURBOPACK) {
+          // FIXME: Turbopack should have matching "done in" for each "rebuilding"
+          expect(logs).not.toEqual(
+            expect.arrayContaining([
+              expect.objectContaining({
+                message: expect.stringContaining('[Fast Refresh] done in'),
+                source: 'log',
+              }),
+            ])
+          )
+        } else {
+          expect(logs).toEqual(
+            expect.arrayContaining([
+              expect.objectContaining({
+                message: expect.stringContaining('[Fast Refresh] done in'),
+                source: 'log',
+              }),
+            ])
+          )
+        }
       } finally {
         await next.patchFile(envFile, envContent)
       }