fix(dev): hold the render in flight on the panel until it lands

Author: danielroe

packages/nuxt-cli/src/dev/tui/index.ts

@@ -146,6 +146,10 @@ export function setupDevUI(context: ShortcutContext, options: DevUIOptions = {})
     update({})
   }
 
+  // Progress writes the panel state itself; going through `update` is what arms
+  // the animation for whatever it has just put there.
+  session.onProgressChange(refresh)
+
   function clearActivity(): void {
     update({ active: false })
   }
@@ -156,16 +160,22 @@ export function setupDevUI(context: ShortcutContext, options: DevUIOptions = {})
       frame: (state.frame ?? 0) + 1,
       elapsedMs: working ? Date.now() - (state.loadStartedAt ?? sessionStart) : state.elapsedMs,
       phaseElapsedMs: working && state.phaseStartedAt !== undefined ? Date.now() - state.phaseStartedAt : state.phaseElapsedMs,
+      renderingMs: state.rendering && Date.now() - state.rendering.startedAt,
     })
   }
 
-  /** Animate the mark only while the server or a task is working, on screen. */
+  /**
+   * Animate the mark only while something is in flight, on screen. A request
+   * being rendered counts: the server is not loading, but it is the only thing
+   * happening, and a still panel in front of a slow page reads as a hung one.
+   */
   function syncAnimation(): void {
-    const working = (state.status !== 'ready' && state.status !== 'error' && !openOverlay()) || (!!state.task && !openOverlay())
-    // Waiting on the first render is measured in seconds, sometimes tens of
-    // them, which is too long to spend a build's frame rate on: the panel only
-    // has to look alive.
-    const interval = state.status === 'warming' ? LOGO_FRAME_MS * WARMUP_FRAME_RATIO : LOGO_FRAME_MS
+    const busy = (state.status !== 'ready' && state.status !== 'error') || !!state.task || !!state.rendering
+    const working = busy && !openOverlay()
+    // Waiting on a render is measured in seconds, sometimes tens of them, which
+    // is too long to spend a build's frame rate on: the panel only has to look
+    // alive.
+    const interval = state.status === 'warming' || state.rendering ? LOGO_FRAME_MS * WARMUP_FRAME_RATIO : LOGO_FRAME_MS
     if (working && animation && interval !== animationInterval) {
       clearInterval(animation)
       animation = undefined
@@ -283,7 +293,10 @@ export function setupDevUI(context: ShortcutContext, options: DevUIOptions = {})
   })
 
   context.onReady(() => {
-    const warming = state.awaitingFirstRender === true
+    // Whether anything is still being waited for is progress's to say: a ready
+    // listener only knows the socket is up, and a server nobody has asked for a
+    // page yet is not warming up, it is idle.
+    const warming = state.status === 'warming'
     update({
       status: warming ? 'warming' : 'ready',
       note: warming ? state.note : undefined,
@@ -583,12 +596,10 @@ export function setupDevUI(context: ShortcutContext, options: DevUIOptions = {})
     },
     setRoutes: payload => routeOverlay.setRoutes(payload),
     setRendering: (pending) => {
-      // A build in flight is already the more interesting thing to report, and
-      // the badge it shows must not be replaced by a request that outlives it.
-      if (state.status !== 'ready') {
-        return
-      }
-      update({ note: pending ? `rendering ${pending.label}` : undefined })
+      update({
+        rendering: pending && { label: pending.label, startedAt: pending.startedAt },
+        renderingMs: pending && Date.now() - pending.startedAt,
+      })
     },
   }
 }

packages/nuxt-cli/src/dev/tui/panel.ts

@@ -94,6 +94,15 @@ export interface PanelState {
   active?: boolean
   /** Replaces the badge's standing description, for a restart reason. */
   note?: string
+  /**
+   * The request being rendered right now, and when it arrived. Held apart from
+   * `note` and `status`, which belong to the load: a request in flight is not a
+   * state of the load, and a load reporting itself ready again mid-render must
+   * not take it off the panel.
+   */
+  rendering?: { label: string, startedAt: number }
+  /** How long that render has been going, for its ticking clock. */
+  renderingMs?: number
   /**
    * Feedback in place of the badge's standing description. Passing unless it
    * carries a `label`, which marks something waiting on the user: the label
@@ -228,6 +237,13 @@ const TASK_FRAMES_ASCII = ['|', '/', '-', '\\'] as const
 /** How long a phase runs before its own elapsed time is worth a mention. */
 const PHASE_ELAPSED_THRESHOLD = 2500
 
+/**
+ * How long a render runs before its own clock is worth showing. Lower than a
+ * phase's, because a render is only reported once it has already been in flight
+ * long enough to notice, and the clock is the only thing that moves.
+ */
+const RENDER_ELAPSED_THRESHOLD = 1000
+
 function renderProgress(state: PanelState, columns: number): string {
   const fraction = Math.min(1, Math.max(0, state.progress ?? 0))
   const filled = Math.round(fraction * PROGRESS_BAR_WIDTH)
@@ -315,10 +331,31 @@ function renderStatus(state: PanelState, columns: number): string {
     )
   }
 
-  const badge = BADGES[state.status]
-  const description = state.notice ? renderNotice(state) : styleText(MUTED, decapitalise(state.note || badge.note) + renderPhaseElapsed(state))
+  // A render is only worth reporting over a server with nothing else to say;
+  // a load in flight is the more important thing and keeps the line.
+  const rendering = state.status === 'ready' || state.status === 'warming' ? state.rendering : undefined
+  const badge = rendering && state.awaitingFirstRender ? BADGES.warming : BADGES[state.status]
+  const description = state.notice
+    ? renderNotice(state)
+    : rendering
+      ? styleText(MUTED, `rendering ${rendering.label}${renderRenderElapsed(state)}`)
+      : styleText(MUTED, decapitalise(state.note || badge.note) + renderPhaseElapsed(state))
   const head = ` ${styleText(badge.style, ` ${badge.label} `)}  ${description}`
-  return truncate(head + renderTicker(state, columns - visibleWidth(head)), columns)
+  // The request in flight is the more interesting one, and it is usually the
+  // same URL as the last: printing both reads as a stutter.
+  return truncate(head + (rendering ? '' : renderTicker(state, columns - visibleWidth(head))), columns)
+}
+
+/**
+ * How long the render in flight has taken. The only thing that moves on a panel
+ * whose server is up and waiting on a page, so it is what says the wait is
+ * progressing rather than stuck.
+ */
+function renderRenderElapsed(state: PanelState): string {
+  if (state.renderingMs === undefined || state.renderingMs < RENDER_ELAPSED_THRESHOLD) {
+    return ''
+  }
+  return ` \u00B7 ${(state.renderingMs / 1000).toFixed(1)}s`
 }
 
 /**

packages/nuxt-cli/src/dev/tui/session.ts

@@ -12,6 +12,7 @@ import { consola } from 'consola'
 import { KEEPS_PROCESS_ALIVE } from '../../utils/errors'
 import { debug, isEmittingCliLog, setLoggerImpl } from '../../utils/logger'
 import { getPkgVersion } from '../../utils/pkg'
+import { READY_MESSAGE } from '../../utils/progress-snapshot'
 import { startupElapsedMs } from '../../utils/startup-clock'
 import { resolveBackground } from '../../utils/terminal-theme'
 import { currentRequest, isServingRequest } from '../serving-state'
@@ -86,6 +87,12 @@ export interface DevUISession {
   stopStartupTicker: () => void
   /** Narrate the current startup phase while the server is loading. */
   reportProgress: (snapshot: ProgressSnapshot) => void
+  /**
+   * Repaint through the controller instead of {@link render} whenever progress
+   * changes what is on the panel, so the controller can re-arm the animation it
+   * owns: a render in flight is work, and a still panel reads as a hung one.
+   */
+  onProgressChange: (listener: () => void) => void
   /**
    * Show the bound address the moment the socket answers, spinning until the
    * resolved config confirms it. The full URL block replaces it on ready.
@@ -176,22 +183,36 @@ export function beginDevUI(options: DevUISupportOptions & { version?: string, cw
     surface.render(renderPanel(state, process.stdout.columns || 80, process.stdout.rows || 24))
   }
 
+  let progressListener: (() => void) | undefined
+
+  /** Repaint through the controller where one is attached, so it sees the change. */
+  function repaint(): void {
+    if (progressListener) {
+      progressListener()
+      return
+    }
+    render()
+  }
+
   function reportProgress(snapshot: ProgressSnapshot): void {
     if (snapshot.status === 'ready') {
       // Between the server accepting requests and answering one there is
       // nothing to watch but a badge, so it says which of the two has happened.
-      // A render in flight is the only thing worth waiting for at this point,
-      // and until the first one lands nothing else is being reported at all.
-      const rendering = !!snapshot.pending && !snapshot.serving
-      state.awaitingFirstRender = rendering
-      state.note = snapshot.pending ? `rendering ${snapshot.pending.label}` : undefined
-      state.progress = rendering ? snapshot.progress : undefined
+      // Something already waiting for a page is a state of the load; the request
+      // being rendered is not, and is held separately so that a load reporting
+      // itself ready again cannot take it off the panel.
+      const waiting = !snapshot.serving && snapshot.message !== READY_MESSAGE
+      state.awaitingFirstRender = !snapshot.serving
+      state.note = waiting ? snapshot.message : undefined
+      state.progress = waiting ? snapshot.progress : undefined
+      state.rendering = snapshot.pending && { label: snapshot.pending.label, startedAt: snapshot.pending.startedAt }
+      state.renderingMs = snapshot.pending && Date.now() - snapshot.pending.startedAt
       state.phaseStartedAt = undefined
       state.phaseElapsedMs = undefined
       if (state.status === 'ready' || state.status === 'warming') {
-        state.status = rendering ? 'warming' : 'ready'
-        render()
+        state.status = waiting ? 'warming' : 'ready'
       }
+      repaint()
       return
     }
     if (snapshot.status !== 'loading') {
@@ -413,6 +434,9 @@ export function beginDevUI(options: DevUISupportOptions & { version?: string, cw
     expectRender,
     stopStartupTicker,
     reportProgress,
+    onProgressChange: (listener) => {
+      progressListener = listener
+    },
     reportListening,
     teardown,
     onTeardown: task => void teardownTasks.push(task),

packages/nuxt-cli/test/unit/dev-tui.spec.ts

@@ -74,12 +74,38 @@ describe('dev tui panel', () => {
     expect(lines.join('\n')).not.toContain('READY')
   })
 
-  it('should say which request it is busy with', () => {
-    const warming = renderPanel({ ...READY, status: 'warming', awaitingFirstRender: true, note: 'rendering GET /' }, 80, 30).map(strip)
-    expect(warming.join('\n')).toContain('WARMUP   rendering GET /')
+  it('should say which request it is busy with, and for how long', () => {
+    const first = renderPanel({ ...READY, awaitingFirstRender: true, rendering: { label: 'GET /', startedAt: 0 }, renderingMs: 6400 }, 80, 30).map(strip)
+    expect(first.join('\n')).toContain('WARMUP   rendering GET / · 6.4s')
 
-    const ready = renderPanel({ ...READY, note: 'rendering GET /about' }, 80, 30).map(strip)
-    expect(ready.join('\n')).toContain('READY   rendering GET /about')
+    const later = renderPanel({ ...READY, rendering: { label: 'GET /about', startedAt: 0 }, renderingMs: 1200 }, 80, 30).map(strip)
+    expect(later.join('\n')).toContain('READY   rendering GET /about · 1.2s')
+  })
+
+  it('should keep the last request off the line while one is in flight', () => {
+    const lines = renderPanel({
+      ...READY,
+      rendering: { label: 'GET /', startedAt: 0 },
+      renderingMs: 6700,
+      lastRequest: { method: 'GET', url: '/', status: 200, duration: 8442 },
+    }, 100, 30).map(strip)
+
+    expect(lines.join('\n')).toContain('READY   rendering GET / · 6.7s')
+    expect(lines.join('\n')).not.toContain('8442ms')
+  })
+
+  it('should not put a clock on a render that has only just arrived', () => {
+    const lines = renderPanel({ ...READY, rendering: { label: 'GET /', startedAt: 0 }, renderingMs: 40 }, 80, 30).map(strip)
+
+    expect(lines.join('\n')).toContain('READY   rendering GET /')
+    expect(lines.join('\n')).not.toContain('0.0s')
+  })
+
+  it('should let a load in flight keep the status line from a render', () => {
+    const lines = renderPanel({ ...READY, status: 'building', note: 'nuxt.config.ts changed', rendering: { label: 'GET /', startedAt: 0 }, renderingMs: 6400 }, 80, 30).map(strip)
+
+    expect(lines.join('\n')).toContain('BUILDING   nuxt.config.ts changed')
+    expect(lines.join('\n')).not.toContain('rendering GET /')
   })
 
   it('should not keep claiming how fast the last load was while rebuilding', () => {
@@ -2315,6 +2341,19 @@ describe('request failures on the panel', () => {
     })
   })
 
+  it('should keep reporting a render when the server reports itself ready again', async () => {
+    await withPanel(async (ui, settle) => {
+      ui.setStatus('ready')
+      ui.setRendering({ label: 'GET /', startedAt: Date.now() })
+      // The bundler reloads while it serves the first document, which is a
+      // `building` event either side of the render it is serving.
+      ui.setStatus('building')
+      ui.setStatus('ready')
+
+      expect(await settle()).toContain('rendering GET /')
+    })
+  })
+
   it('should report a failed app request', async () => {
     await withPanel(async (ui, settle) => {
       ui.setStatus('ready')