diff --git a/capture/output/nuxt-dev-restart.svg b/capture/output/nuxt-dev-restart.svg index 4413a3a51..149cf764c 100644 --- a/capture/output/nuxt-dev-restart.svg +++ b/capture/output/nuxt-dev-restart.svg @@ -16,36 +16,31 @@ svg{--bg:#ffffff;--fg:#24292f;--chrome:#f6f8fa;--dot:#d0d7de} nuxt dev (restart on config change) - -⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/⠋━━━━━━━━━━━━━━━━━━━━0% · 0.0s STARTING starting Nuxt...rrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━17% · 0.2s STARTING setting up modulesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━33% · 0.3s STARTING preparing apprrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━33% · 0.5s STARTING preparing apprrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━50% · 0.6s STARTING generating typesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━50% · 0.8s STARTING generating typesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━67% · 0.9s STARTING bundling apprrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 1.1s STARTING building serverrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 1.2s STARTING building serverrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 1.3s STARTING building serverrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 1.4s STARTING building serverrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 1.5s STARTING building serverrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 1.7s STARTING building serverrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 1.8s STARTING building serverrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2ready in 2.09sLocalhttp://localhost:3000/waiting for requests READY watching for changesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2ready in 2.09sLocalhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━0% · 0.0s BUILDING nuxt.config.ts changed. Reloading Nuxt...rrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2ready in 2.09sLocalhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━50% · 0.2s BUILDING generating typesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2ready in 2.09sLocalhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 0.3s BUILDING building serverrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2ready in 2.09sLocalhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 0.4s BUILDING compiling changesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2ready in 2.09sLocalhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 0.5s BUILDING compiling changesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2ready in 2.09sLocalhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 0.6s BUILDING compiling changesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2ready in 2.09sLocalhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 0.8s BUILDING compiling changesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2ready in 2.09sLocalhttp://localhost:3000/waiting for requests READY watching for changesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2ready in 2.09sLocalhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━33% · 0.1s BUILDING preparing apprrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2ready in 2.09sLocalhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 0.2s BUILDING building serverrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2ready in 2.09sLocalhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 0.2s BUILDING compiling changesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2ready in 2.09sLocalhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 0.4s BUILDING compiling changesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2ready in 2.09sLocalhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 0.5s BUILDING compiling changesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2ready in 2.09sLocalhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 0.6s BUILDING compiling changesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit -⣠⣦⣠⡀Nuxt4.5.2ready in 2.09sLocalhttp://localhost:3000/waiting for requests READY watching for changesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit + +⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/⠋━━━━━━━━━━━━━━━━━━━━0% · 0.0s STARTING starting Nuxt...rrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━17% · 0.1s STARTING setting up modulesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━33% · 0.3s STARTING preparing apprrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━33% · 0.4s STARTING preparing apprrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━50% · 0.5s STARTING generating typesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━67% · 0.7s STARTING bundling apprrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 0.9s STARTING building serverrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 1.0s STARTING building serverrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 1.1s STARTING building serverrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 1.2s STARTING building serverrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 1.4s STARTING building serverrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2ready in 1.67sLocalhttp://localhost:3000/waiting for requests READY watching for changesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━0% · 0.0s BUILDING nuxt.config.ts changed. Reloading Nuxt...rrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━50% · 0.1s BUILDING generating typesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 0.2s BUILDING compiling changesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 0.4s BUILDING compiling changesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 0.5s BUILDING compiling changesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 0.6s BUILDING compiling changesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2ready in 1.67sLocalhttp://localhost:3000/waiting for requests READY watching for changesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━67% · 0.1s BUILDING bundling apprrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 0.1s BUILDING compiling changesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 0.3s BUILDING compiling changesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 0.4s BUILDING compiling changesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2Localhttp://localhost:3000/━━━━━━━━━━━━━━━━━━━━83% · 0.5s BUILDING compiling changesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit +⣠⣦⣠⡀Nuxt4.5.2ready in 1.67sLocalhttp://localhost:3000/waiting for requests READY watching for changesrrestart · oopen · iinfo · llogs · nnetwork · proutes · ?help · qquit diff --git a/capture/output/nuxt-dev-restart.txt b/capture/output/nuxt-dev-restart.txt index e72665cc5..aa38b25ed 100644 --- a/capture/output/nuxt-dev-restart.txt +++ b/capture/output/nuxt-dev-restart.txt @@ -1,4 +1,4 @@ -styles: 6af3b1c828666453 +styles: cbc7a29b1cebf5be Local http://localhost:3000/ Local http://localhost:3000/ ⠋ waiting for requests diff --git a/packages/nuxt-cli/src/dev/index.ts b/packages/nuxt-cli/src/dev/index.ts index d9fea5e20..d95660cce 100644 --- a/packages/nuxt-cli/src/dev/index.ts +++ b/packages/nuxt-cli/src/dev/index.ts @@ -359,13 +359,30 @@ export async function initialize(devContext: NuxtDevContext, ctx: InitializeOpti ? undefined : createStartupReporter() const unsubscribeProgress = reporter && devServer.progress.onUpdate(reporter.update) + const stopReporting = () => { + unsubscribeProgress?.() + reporter?.stop() + } try { await devServer.init() } finally { - unsubscribeProgress?.() - reporter?.stop() + // Nuxt being ready ends startup for this process but not for whoever is + // waiting on the first render, so the reporter stays subscribed. Any state + // other than ready-but-not-serving has nothing left to wait for. + const snapshot = devServer.progress.snapshot + if (!reporter || snapshot?.status !== 'ready' || snapshot.serving) { + stopReporting() + } + else { + const unsubscribeServing = devServer.progress.onUpdate((snapshot) => { + if (snapshot.serving || snapshot.status === 'error') { + unsubscribeServing() + stopReporting() + } + }) + } } if (process.env.DEBUG) { diff --git a/packages/nuxt-cli/src/dev/loading-client.ts b/packages/nuxt-cli/src/dev/loading-client.ts index 15e22c17c..f207cdc15 100644 --- a/packages/nuxt-cli/src/dev/loading-client.ts +++ b/packages/nuxt-cli/src/dev/loading-client.ts @@ -29,16 +29,22 @@ export function progressClient(options: ProgressClientOptions): void { document.body.append(caption) let start = Date.now() - options.elapsed - let phase = '' + let label = '' function paint(): void { const seconds = `${((Date.now() - start) / 1000).toFixed(1)}s` - caption.textContent = phase ? `${phase} \u00B7 ${seconds}` : seconds + caption.textContent = label ? `${label} \u00B7 ${seconds}` : seconds } function apply(snapshot: DevProgressSnapshot): void { start = Date.now() - snapshot.elapsed - phase = `${snapshot.phase} \u00B7 step ${snapshot.index + 1}/${snapshot.total + 1}` + // The message, not the phase id: it carries whatever detail the server has, + // such as the module currently being set up, and this page is what the user + // is looking at for most of a cold start. + const message = /^[A-Z][a-z]/.test(snapshot.message) + ? snapshot.message[0]!.toLowerCase() + snapshot.message.slice(1) + : snapshot.message + label = `${message} \u00B7 step ${snapshot.index + 1}/${snapshot.total + 1}` const percent = Math.max(4, Math.round(snapshot.progress * 100)) document.documentElement.style.setProperty(options.progressProperty, `${percent}%`) if (snapshot.message && !document.title.startsWith(snapshot.message)) { @@ -59,6 +65,7 @@ export function progressClient(options: ProgressClientOptions): void { setInterval(paint, 100) const source = new EventSource(options.progressPath) + let polling = false source.addEventListener('nuxt:loading', (event) => { const snapshot = read(event) @@ -75,26 +82,42 @@ export function progressClient(options: ProgressClientOptions): void { }) source.addEventListener('nuxt:ready', (event) => { - source.close() - phase = 'starting the app' - document.title = 'Starting the app' - document.documentElement.style.setProperty(options.progressProperty, '100%') - paint() + // Repeats of this event while polling only matter if a rebuild finished, + // whose warm caches make it safe to reload at once. + if (polling) { + if (read(event)?.reload) { + source.close() + location.reload() + } + return + } + const snapshot = read(event) + // Use the server's wording so the terminal, the caption and the tab agree. + const message = snapshot && !snapshot.serving && snapshot.message ? snapshot.message : 'Starting the app' + label = message.charAt(0).toLowerCase() + message.slice(1) + document.title = message // A reload leaves the caches warm, so there is nothing left to wait for. - if (read(event)?.reload) { + if (snapshot?.reload) { + source.close() + document.documentElement.style.setProperty(options.progressProperty, '100%') + paint() location.reload() return } + // Hold the bar short of full while the caption still says starting. + const fraction = typeof snapshot?.progress === 'number' && snapshot.progress > 0 ? Math.min(snapshot.progress, 1) : 1 + document.documentElement.style.setProperty(options.progressProperty, `${Math.round(fraction * 100)}%`) + paint() + // `nuxt:ready` means the request handler exists, not that it can answer - // yet: the first document still has to be compiled. So this page stays, - // still reporting progress, and asks until the app answers, which keeps - // every page the dev server serves updating itself rather than needing a - // `Refresh` header whose hard reload would throw the progress away. - // - // One request at a time, backing off towards a ceiling. The dev server - // serialises the first render, so asking more often would only queue. + // yet: the first document still has to be compiled. So this page stays and + // asks until the app answers, one request at a time with backoff, since the + // dev server serialises the first render anyway. The event stream stays + // open meanwhile: the server takes the last stream closing as the sign + // that nobody is waiting on a first render any more. + polling = true const controller = new AbortController() let wait = options.pollInterval @@ -104,6 +127,7 @@ export function progressClient(options: ProgressClientOptions): void { const body = await response.text() if (!body.includes(options.captionId)) { controller.abort() + source.close() location.reload() return } diff --git a/packages/nuxt-cli/src/dev/progress.ts b/packages/nuxt-cli/src/dev/progress.ts index 4d394a77d..61ece8d5f 100644 --- a/packages/nuxt-cli/src/dev/progress.ts +++ b/packages/nuxt-cli/src/dev/progress.ts @@ -25,6 +25,16 @@ const DEV_PHASES: readonly DevPhase[] = [ { id: 'ready', message: 'Ready' }, ] +/** + * Fraction reserved for the first render. `nuxt:ready` means the server can + * accept a request, not answer one, and compiling the first document is the + * longest single wait on a large project. + */ +const READY_PROGRESS = 0.95 + +/** Shown between the server accepting requests and it answering one. */ +const WARMUP_MESSAGE = 'Compiling the first request' + const HOOK_PHASES: Record = { 'modules:before': 'modules', 'builder:generateApp': 'app', @@ -35,6 +45,68 @@ const HOOK_PHASES: Record = { 'nitro:build:before': 'server', } +/** + * Both carry a `name` that is always renderable. A Nuxt without them shows + * the phase label, as before. + */ +const MODULE_STARTED = 'module:before' +const MODULE_FINISHED = 'module:done' + +/** + * Nitro builds the server on its own hooks, which Nuxt's never see, so this is + * the only way the server phase says anything. The prefix keeps a name like + * `rollup:before` from reading as if Nuxt were the one busy. + */ +const NITRO_HOOK = 'nitro:init' +const NITRO_PREFIX = 'nitro:' + +/** + * How long a module has to stay busy before it is named. Most install in a few + * milliseconds, and a label flickering through dozens of names a second is + * worse than a still one, especially as a browser tab title. + */ +const MODULE_DWELL = 150 + +/** + * How long any other hook has to run before it is named, set where a hook has + * stopped being a step of the build and started being the reason for the wait. + * Nuxt calls thousands of them, nearly all sub-millisecond. + */ +const HOOK_DWELL = 1000 + +/** How often the narration looks at what is currently running. */ +const NARRATION_INTERVAL = 250 + +/** Friendlier wording for hooks whose raw name would not explain the wait. */ +const HOOK_LABELS: Record = { + 'devtools:before': 'Setting up Nuxt DevTools', +} + +/** + * Past this depth the stack is dropped rather than grown, so a hook that + * never settles cannot retain an entry for the rest of the load. + */ +const HOOK_STACK_LIMIT = 64 + +/** Module names share their line with the status badge, and paths get long. */ +const MODULE_NAME_LIMIT = 32 + +/** + * Local modules keep only their basename; package specifiers, scope included, + * are left alone. + */ +function shortenModuleName(name: string): string { + const short = name.startsWith('@') || !/[\\/]/.test(name) + ? name + : name.split(/[\\/]/).pop()!.replace(/\.[cm]?[jt]sx?$/, '') + return short.length > MODULE_NAME_LIMIT ? `${short.slice(0, MODULE_NAME_LIMIT - 1)}\u2026` : short +} + +function moduleName(module: unknown): string | undefined { + const name = (module as { name?: unknown } | undefined)?.name + return typeof name === 'string' && name ? name : undefined +} + export type DevProgressStatus = 'loading' | 'ready' | 'error' interface DevPhaseTiming { @@ -52,12 +124,24 @@ export interface DevProgressSnapshot { progress: number elapsed: number reload: boolean + /** + * Whether a request has actually been answered. `status` is `ready` from the + * moment the server is listening, so this is what tells a UI whether the app + * can be used yet. + */ + serving: boolean timings: DevPhaseTiming[] error?: { name: string, message: string } } interface HookableLike { - beforeEach?: (fn: (event: { name: string }) => void) => void + beforeEach?: (fn: (event: { name: string, args?: unknown[] }) => void) => void + afterEach?: (fn: (event: { name: string }) => void) => void +} + +interface ActiveHook { + name: string + at: number } /** @@ -77,6 +161,14 @@ export class DevProgress { #phaseStartedAt = Date.now() #timings: DevPhaseTiming[] = [] #reload = false + #baseMessage = DEV_PHASES[0]!.message + #module?: ActiveHook + #hooks: ActiveHook[] = [] + #narrating = false + #serving = false + #observing = false + #observed = new WeakSet() + #ticker?: NodeJS.Timeout get snapshot(): DevProgressSnapshot { const phase = DEV_PHASES[this.#index]! @@ -86,9 +178,12 @@ export class DevProgress { message: this.#message, index: this.#index, total: DEV_PHASES.length - 1, - progress: this.#status === 'ready' ? 1 : this.#index / (DEV_PHASES.length - 1), + progress: this.#status === 'ready' + ? (this.#serving ? 1 : READY_PROGRESS) + : this.#index / (DEV_PHASES.length - 1), elapsed: Date.now() - this.#startedAt, reload: this.#reload, + serving: this.#serving, timings: this.#timings, error: this.#error && { name: this.#error.name, message: this.#error.message }, } @@ -104,14 +199,22 @@ export class DevProgress { } start(message?: string, reload = false): void { + this.#hooks = [] + this.#clearModule() + this.#narrating = false + if (this.#observing) { + this.#startNarrating() + } this.#index = 0 this.#status = 'loading' this.#error = undefined this.#timings = [] this.#reload = reload + this.#serving = false this.#startedAt = Date.now() this.#phaseStartedAt = this.#startedAt - this.#message = message || DEV_PHASES[0]!.message + this.#baseMessage = message || DEV_PHASES[0]!.message + this.#message = this.#baseMessage this.#emit() } @@ -131,9 +234,27 @@ export class DevProgress { if (this.#status === 'ready') { return } + this.#stopNarrating() this.#advance('ready', undefined, false) this.#status = 'ready' this.#error = undefined + // Nobody is watching a loading page, so there is no first render to wait + // for: whoever asks next pays for it, and the panel reports that request + // like any other. + this.#serving = this.#clients.size === 0 + if (!this.#serving) { + this.#message = WARMUP_MESSAGE + } + this.#emit() + } + + /** The app has answered a request, so the wait is genuinely over. */ + setServing(): void { + if (this.#serving || this.#status !== 'ready') { + return + } + this.#serving = true + this.#message = DEV_PHASES.at(-1)!.message this.#emit() } @@ -152,18 +273,115 @@ export class DevProgress { }) this.#phaseStartedAt = Date.now() this.#index = index + this.#clearModule() } const next = message || DEV_PHASES[index]!.message - if (!advanced && next === this.#message) { + if (!advanced && next === this.#baseMessage) { return } + this.#baseMessage = next this.#message = next + this.#narrating = false if (emit) { this.#emit() } } + #clearModule(): void { + this.#module = undefined + } + + /** + * Replace the phase label with whatever the load is actually waiting on, or + * put the phase label back once it is waiting on nothing in particular. The + * phase index is untouched, so the fraction clients render stays monotonic. + */ + #narrate(): void { + if (this.#status !== 'loading') { + return + } + + const now = Date.now() + let text: string | undefined + + // A module name reads better than the hook it was installed from, so an + // install in flight wins over whatever hook is nested inside it. + if (this.#module && now - this.#module.at >= MODULE_DWELL) { + text = `Setting up ${shortenModuleName(this.#module.name)}` + } + else { + // Innermost first: the hook that has not returned yet is the one holding + // everything above it up. + for (let index = this.#hooks.length - 1; index >= 0; index--) { + const hook = this.#hooks[index]! + if (now - hook.at < HOOK_DWELL) { + continue + } + // A hook that owns a phase is already described by that phase's label, + // which reads better than its name. + if (!HOOK_PHASES[hook.name]) { + text = HOOK_LABELS[hook.name] ?? `Running ${hook.name}` + } + break + } + } + + if (!text && !this.#narrating) { + return + } + this.#narrating = !!text + const next = text ?? this.#baseMessage + if (next !== this.#message) { + this.#message = next + this.#emit() + } + } + + #startNarrating(): void { + if (this.#ticker) { + return + } + this.#ticker = setInterval(() => this.#narrate(), NARRATION_INTERVAL) + this.#ticker.unref?.() + } + + #stopNarrating(): void { + clearInterval(this.#ticker) + this.#ticker = undefined + this.#hooks = [] + this.#clearModule() + } + + /** + * Record a hook as running. Hooks nest, but they also run concurrently, so + * this is a stack only by convention: a hook that finishes out of order is + * removed from wherever it sits. An entry whose hook never completes would + * otherwise sit at the bottom of the stack for the rest of the load, so the + * oldest is dropped once the stack stops looking like one. + */ + #pushHook(name: string): void { + if (this.#hooks.length >= HOOK_STACK_LIMIT) { + this.#hooks.shift() + } + this.#hooks.push({ name, at: Date.now() }) + } + + #popHook(name: string): void { + const last = this.#hooks.length - 1 + if (last >= 0 && this.#hooks[last]!.name === name) { + this.#hooks.length = last + return + } + for (let index = last; index >= 0; index--) { + if (this.#hooks[index]!.name === name) { + this.#hooks.splice(index, 1) + return + } + } + } + setError(error: Error): void { + this.#stopNarrating() this.#error = error this.#status = 'error' this.#message = error.message || 'Nuxt failed to start.' @@ -172,17 +390,64 @@ export class DevProgress { /** * Derive phases from the hooks Nuxt calls, so the granularity follows the - * project's own build rather than a schedule guessed by the CLI. + * project's own build rather than a schedule guessed by the CLI, and name + * whatever is taking long enough that the phase alone stops explaining the + * wait. Both the modules a project installs and the hooks its own code + * registers are only visible from here. */ attachNuxt(hooks: HookableLike): void { + if (this.#observed.has(hooks)) { + return + } + const timed = !!(hooks.beforeEach && hooks.afterEach) // Phase tracking is a nicety: a Nuxt whose hooks cannot be observed still // gets a loading page, it just does not advance through the phases. - hooks.beforeEach?.(({ name }) => { + hooks.beforeEach?.(({ name, args }) => { + if (timed) { + this.#pushHook(name) + } const phase = HOOK_PHASES[name] if (phase) { this.setPhase(phase) } + else if (name === MODULE_STARTED) { + const module = moduleName(args?.[0]) + if (module) { + this.#module = { name: module, at: Date.now() } + } + } + // A module that finishes before it earned a mention must not be named + // afterwards: whatever the load is waiting on by then is not this module. + else if (name === MODULE_FINISHED && moduleName(args?.[0]) === this.#module?.name) { + this.#clearModule() + } + else if (name === NITRO_HOOK) { + this.#observe((args?.[0] as { hooks?: HookableLike } | undefined)?.hooks, NITRO_PREFIX) + } }) + + this.#observe(hooks, '') + } + + /** + * Time the hooks of one system. Entries carry the prefix they were pushed + * with, so a name shared by two systems cannot pop the other's entry, and the + * innermost-wins rule still holds across both: Nitro builds inside a Nuxt + * hook that is awaiting it. + */ + #observe(hooks: HookableLike | undefined, prefix: string): void { + // Without `afterEach` a hook can only be seen starting, never finishing, so + // timing one would mean naming a hook that has long since returned. + if (!hooks?.beforeEach || !hooks.afterEach || this.#observed.has(hooks)) { + return + } + this.#observed.add(hooks) + if (prefix) { + hooks.beforeEach(({ name }) => this.#pushHook(prefix + name)) + } + hooks.afterEach(({ name }) => this.#popHook(prefix + name)) + this.#observing = true + this.#startNarrating() } handleRequest(req: IncomingMessage, res: ServerResponse): boolean { @@ -209,6 +474,9 @@ export class DevProgress { if (this.#clients.size === 0) { clearInterval(this.#heartbeat) this.#heartbeat = undefined + // The page that was waiting for the first render has gone, so there is + // nothing left to narrate towards. + this.setServing() } }) @@ -225,6 +493,7 @@ export class DevProgress { } close(): void { + this.#stopNarrating() clearInterval(this.#heartbeat) this.#heartbeat = undefined for (const client of this.#clients) { diff --git a/packages/nuxt-cli/src/dev/startup-log.ts b/packages/nuxt-cli/src/dev/startup-log.ts index d9359aa03..2fd7571ab 100644 --- a/packages/nuxt-cli/src/dev/startup-log.ts +++ b/packages/nuxt-cli/src/dev/startup-log.ts @@ -35,7 +35,8 @@ export function formatSummary(snapshot: DevProgressSnapshot): string { .filter(timing => timing.duration >= 10) .map(timing => `${timing.phase} ${formatDuration(timing.duration)}`) .join(' · ') - const headline = `${snapshot.reload ? 'Reloaded' : 'Ready'} in ${formatDuration(snapshot.elapsed)}` + const headline = `${snapshot.reload ? 'Reloaded' : 'Ready'} in ${formatDuration(snapshot.elapsed)}${ + snapshot.serving ? '' : styleText('dim', ' \u00B7 compiling the first request')}` return breakdown ? `${headline}\n${styleText('dim', breakdown)}` : headline } @@ -49,6 +50,7 @@ export function createStartupReporter(options: StartupReporterOptions = {}): Sta const animated = options.animated ?? isAnimationSupported(stream) let snapshot: DevProgressSnapshot | undefined + let served = false let lastPhase: string | undefined let frame = 0 let dirty = false @@ -106,6 +108,11 @@ export function createStartupReporter(options: StartupReporterOptions = {}): Sta if (stopped) { return } + // The summary is printed; the only thing left to say is that the first + // request has been answered. + if (served && next.status !== 'ready') { + return + } snapshot = next receivedAt = Date.now() @@ -116,8 +123,16 @@ export function createStartupReporter(options: StartupReporterOptions = {}): Sta } if (next.status === 'ready') { + if (served) { + if (next.serving) { + stopped = true + logger.success(`Serving in ${formatDuration(next.elapsed)}`) + } + return + } restore() - stopped = true + served = true + stopped = next.serving logger.success(formatSummary(next)) return } diff --git a/packages/nuxt-cli/src/dev/tui/index.ts b/packages/nuxt-cli/src/dev/tui/index.ts index 6dbcad102..1fbfe6baf 100644 --- a/packages/nuxt-cli/src/dev/tui/index.ts +++ b/packages/nuxt-cli/src/dev/tui/index.ts @@ -36,6 +36,9 @@ export type { DevUIController } /** How often the traffic ticker may repaint, so bursts cannot strobe the panel. */ const TICKER_REPAINT_MS = 250 +/** Frames the mark skips per painted one while waiting for the first render. */ +const WARMUP_FRAME_RATIO = 4 + /** How long the mark keeps traffic colour after a request. */ const ACTIVITY_MS = 700 @@ -121,6 +124,7 @@ export function setupDevUI(context: ShortcutContext, options: DevUIOptions = {}) const openOverlay = () => views.find(view => view.isOpen) let animation: NodeJS.Timeout | undefined + let animationInterval = LOGO_FRAME_MS let activityTimer: NodeJS.Timeout | undefined let noticeTimer: NodeJS.Timeout | undefined @@ -152,8 +156,17 @@ export function setupDevUI(context: ShortcutContext, options: DevUIOptions = {}) /** Animate the mark only while the server is working and on screen. */ function syncAnimation(): void { const working = state.status !== 'ready' && state.status !== 'error' && !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 + if (working && animation && interval !== animationInterval) { + clearInterval(animation) + animation = undefined + } if (working && !animation) { - animation = setInterval(advanceFrame, LOGO_FRAME_MS) + animationInterval = interval + animation = setInterval(advanceFrame, interval) animation.unref?.() } else if (!working && animation) { @@ -207,10 +220,11 @@ export function setupDevUI(context: ShortcutContext, options: DevUIOptions = {}) }) context.onReady(() => { + const warming = state.awaitingFirstRender === true update({ - status: 'ready', - note: undefined, - progress: undefined, + status: warming ? 'warming' : 'ready', + note: warming ? state.note : undefined, + progress: warming ? state.progress : undefined, readyMs: state.readyMs ?? startupElapsedMs(options.startTime ?? sessionStart), urls: describeURLs(context), }) diff --git a/packages/nuxt-cli/src/dev/tui/panel.ts b/packages/nuxt-cli/src/dev/tui/panel.ts index c0fa19cff..64c7834a5 100644 --- a/packages/nuxt-cli/src/dev/tui/panel.ts +++ b/packages/nuxt-cli/src/dev/tui/panel.ts @@ -7,7 +7,7 @@ import { MUTED, paint } from '../../utils/terminal-theme' import { renderLogo } from './logo' import { stripAnsi, truncate, visibleWidth } from './width' -export type DevStatus = 'starting' | 'building' | 'ready' | 'restarting' | 'error' +export type DevStatus = 'starting' | 'building' | 'warming' | 'ready' | 'restarting' | 'error' export interface PanelURL { label: string @@ -67,6 +67,8 @@ export interface PanelState { urls?: PanelURL[] /** Milliseconds from process start to the first ready, once known. */ readyMs?: number + /** The server is listening but has not answered a request yet. */ + awaitingFirstRender?: boolean /** Milliseconds the current load has been running, while one is running. */ elapsedMs?: number /** How far through startup the current load is, 0..1, while one is running. */ @@ -111,6 +113,7 @@ const BADGES: Record = { building: { label: 'BUILDING', style: ['bgYellow', 'black', 'bold'], note: 'compiling changes' }, restarting: { label: 'RESTART', style: ['bgYellow', 'black', 'bold'], note: 'reloading the dev server' }, error: { label: 'ERROR', style: ['bgRed', 'white', 'bold'], note: 'an error was logged · press e to view it' }, + warming: { label: 'WARMUP', style: ['bgYellow', 'black', 'bold'], note: 'compiling the first request' }, ready: { label: 'READY', style: ['bgGreen', 'black', 'bold'], note: 'watching for changes' }, } @@ -177,7 +180,10 @@ function renderWordmark(state: PanelState, columns: number): string { const head = ` ${mark} ${paint('brand', styleText('bold', 'Nuxt'), state.background)}${version ? ` ${styleText(MUTED, version)}` : ''}${ state.update ? paint('warning', ` ${state.updateLink ?? `\u2192 ${state.update}`}`, state.background) : ''}` - const tail = state.readyMs === undefined + // How long the last load took says nothing about the one in flight, and a + // precise number is the wrong thing to be confident about mid-rebuild. + const settled = state.status === 'ready' || state.status === 'warming' + const tail = state.readyMs === undefined || !settled ? '' : styleText(MUTED, `ready in ${formatDuration(state.readyMs)} `) const gap = columns - visibleWidth(head) - visibleWidth(tail) diff --git a/packages/nuxt-cli/src/dev/tui/session.ts b/packages/nuxt-cli/src/dev/tui/session.ts index 757cc8663..85cfd8fe6 100644 --- a/packages/nuxt-cli/src/dev/tui/session.ts +++ b/packages/nuxt-cli/src/dev/tui/session.ts @@ -139,6 +139,18 @@ export function beginDevUI(options: DevUISupportOptions & { version?: string, cw } function reportProgress(snapshot: DevProgressSnapshot): 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. + state.awaitingFirstRender = !snapshot.serving + state.note = snapshot.serving ? undefined : snapshot.message + state.progress = snapshot.serving ? undefined : snapshot.progress + if (state.status === 'ready' || state.status === 'warming') { + state.status = snapshot.serving ? 'ready' : 'warming' + render() + } + return + } if (snapshot.status !== 'loading') { return } diff --git a/packages/nuxt-cli/src/dev/utils.ts b/packages/nuxt-cli/src/dev/utils.ts index 84eed96c5..a9d0ebc82 100644 --- a/packages/nuxt-cli/src/dev/utils.ts +++ b/packages/nuxt-cli/src/dev/utils.ts @@ -478,10 +478,15 @@ export class NuxtDevServer extends EventEmitter { return } this.#inflightResponses.add(res) + // A document that Nuxt itself answered is the first proof the app can be used. + const document = isDocumentRequest(req) res.once('close', () => { this.#inflightResponses.delete(res) + if (document && res.statusCode < 500) { + this.#progress.setServing() + } }) - if (!this.#warmup.warmed && isDocumentRequest(req)) { + if (!this.#warmup.warmed && document) { await this.#warmup.admit(res) if (res.destroyed || res.writableEnded) { return diff --git a/packages/nuxt-cli/test/unit/dev-progress.spec.ts b/packages/nuxt-cli/test/unit/dev-progress.spec.ts index 7e15d68ae..e48519e01 100644 --- a/packages/nuxt-cli/test/unit/dev-progress.spec.ts +++ b/packages/nuxt-cli/test/unit/dev-progress.spec.ts @@ -86,6 +86,343 @@ describe('devProgress', () => { expect(progress.snapshot.phase).toBe('server') }) + describe('narration', () => { + function attach() { + const progress = new DevProgress() + let before: (event: { name: string, args?: unknown[] }) => void = () => {} + let after: (event: { name: string }) => void = () => {} + progress.start() + progress.attachNuxt({ + beforeEach: fn => (before = fn), + afterEach: fn => (after = fn), + }) + const callHook = (name: string, ...args: unknown[]) => { + before({ name, args }) + after({ name }) + } + const enter = (name: string) => before({ name, args: [] }) + const leave = (name: string) => after({ name }) + callHook('modules:before') + const install = (name: string) => callHook('module:before', { name, meta: { name } }) + const finish = (name: string) => callHook('module:done', { name, meta: { name }, duration: 1 }) + return { progress, callHook, enter, leave, install, finish } + } + + it('should name a module that stays busy, without advancing the phase', () => { + vi.useFakeTimers() + const { progress, install } = attach() + + install('@nuxtjs/i18n') + vi.advanceTimersByTime(300) + + expect(progress.snapshot.message).toBe('Setting up @nuxtjs/i18n') + expect(progress.snapshot.phase).toBe('modules') + expect(progress.snapshot.index).toBe(1) + vi.useRealTimers() + }) + + it('should not name modules that install quickly', () => { + vi.useFakeTimers() + const { progress, install, finish } = attach() + + for (const name of ['a', 'b', 'c', 'd']) { + install(name) + vi.advanceTimersByTime(20) + finish(name) + } + + expect(progress.snapshot.message).toBe('Setting up modules') + vi.useRealTimers() + }) + + it('should put the phase label back once nothing is holding the load up', () => { + vi.useFakeTimers() + const { progress, install, finish } = attach() + + install('slow-module') + vi.advanceTimersByTime(300) + expect(progress.snapshot.message).toBe('Setting up slow-module') + + finish('slow-module') + vi.advanceTimersByTime(300) + expect(progress.snapshot.message).toBe('Setting up modules') + vi.useRealTimers() + }) + + it('should stop naming modules once the phase moves on', () => { + vi.useFakeTimers() + const { progress, callHook, install } = attach() + + install('slow-module') + callHook('builder:generateApp') + vi.advanceTimersByTime(300) + + expect(progress.snapshot.phase).toBe('app') + expect(progress.snapshot.message).toBe('Preparing app') + vi.useRealTimers() + }) + + it('should shorten local module paths and long names', () => { + vi.useFakeTimers() + const { progress, install } = attach() + + install('modules/analytics.ts') + vi.advanceTimersByTime(300) + expect(progress.snapshot.message).toBe('Setting up analytics') + + install(`@scope/${'x'.repeat(40)}`) + vi.advanceTimersByTime(300) + expect(progress.snapshot.message).toMatch(/^Setting up @scope\/x{24}\u2026$/) + vi.useRealTimers() + }) + + it('should not name a module that finished before it earned a mention', () => { + vi.useFakeTimers() + const { progress, install, finish } = attach() + + install('quick-module') + vi.advanceTimersByTime(20) + finish('quick-module') + vi.advanceTimersByTime(500) + + expect(progress.snapshot.message).toBe('Setting up modules') + vi.useRealTimers() + }) + + it('should name a hook that outlasts its phase label', () => { + vi.useFakeTimers() + const { progress, enter, leave } = attach() + + enter('markdown:blog-entries') + vi.advanceTimersByTime(1500) + expect(progress.snapshot.message).toBe('Running markdown:blog-entries') + expect(progress.snapshot.index).toBe(1) + + leave('markdown:blog-entries') + vi.advanceTimersByTime(300) + expect(progress.snapshot.message).toBe('Setting up modules') + vi.useRealTimers() + }) + + it('should not name the thousands of hooks that return at once', () => { + vi.useFakeTimers() + const { progress, callHook } = attach() + const listener = vi.fn() + progress.onUpdate(listener) + + for (let index = 0; index < 2000; index++) { + callHook(`some:hook:${index % 20}`) + } + vi.advanceTimersByTime(2000) + + expect(progress.snapshot.message).toBe('Setting up modules') + expect(listener).not.toHaveBeenCalled() + vi.useRealTimers() + }) + + it('should blame the innermost hook still running', () => { + vi.useFakeTimers() + const { progress, enter, leave } = attach() + + enter('outer:hook') + vi.advanceTimersByTime(1200) + enter('inner:hook') + vi.advanceTimersByTime(1200) + expect(progress.snapshot.message).toBe('Running inner:hook') + + leave('inner:hook') + vi.advanceTimersByTime(300) + expect(progress.snapshot.message).toBe('Running outer:hook') + vi.useRealTimers() + }) + + it('should survive hooks that finish out of order', () => { + vi.useFakeTimers() + const { progress, enter, leave } = attach() + + enter('first:hook') + enter('second:hook') + leave('first:hook') + vi.advanceTimersByTime(1200) + expect(progress.snapshot.message).toBe('Running second:hook') + + leave('second:hook') + leave('never:started') + vi.advanceTimersByTime(300) + expect(progress.snapshot.message).toBe('Setting up modules') + vi.useRealTimers() + }) + + it('should not grow without bound when hooks never finish', () => { + vi.useFakeTimers() + const { progress, enter } = attach() + + for (let index = 0; index < 500; index++) { + enter(`stuck:hook:${index}`) + } + vi.advanceTimersByTime(1200) + + expect(progress.snapshot.message).toBe('Running stuck:hook:499') + vi.useRealTimers() + }) + + it('should leave a hook that owns a phase described by that phase', () => { + vi.useFakeTimers() + const { progress, enter } = attach() + + enter('builder:generateApp') + vi.advanceTimersByTime(3000) + + expect(progress.snapshot.message).toBe('Preparing app') + vi.useRealTimers() + }) + + it('should give known slow steps a friendlier label than their hook name', () => { + vi.useFakeTimers() + const { progress, enter } = attach() + + enter('devtools:before') + vi.advanceTimersByTime(1200) + + expect(progress.snapshot.message).toBe('Setting up Nuxt DevTools') + vi.useRealTimers() + }) + + it('should name the nitro hook a server build is waiting on', () => { + vi.useFakeTimers() + const { progress, callHook, enter } = attach() + let nitroBefore: (event: { name: string }) => void = () => {} + let nitroAfter: (event: { name: string }) => void = () => {} + const nitro = { + hooks: { + beforeEach: (fn: (event: { name: string }) => void) => (nitroBefore = fn), + afterEach: (fn: (event: { name: string }) => void) => (nitroAfter = fn), + }, + } + + callHook('nitro:init', nitro) + enter('nitro:build:before') + nitroBefore({ name: 'rollup:before' }) + vi.advanceTimersByTime(1500) + expect(progress.snapshot.message).toBe('Running nitro:rollup:before') + expect(progress.snapshot.phase).toBe('server') + + nitroAfter({ name: 'rollup:before' }) + vi.advanceTimersByTime(300) + expect(progress.snapshot.message).toBe('Building server') + vi.useRealTimers() + }) + + it('should not let a hook of one system pop the entry of the other', () => { + vi.useFakeTimers() + const { progress, callHook, enter } = attach() + let nitroBefore: (event: { name: string }) => void = () => {} + const nitro = { + hooks: { + beforeEach: (fn: (event: { name: string }) => void) => (nitroBefore = fn), + afterEach: () => {}, + }, + } + + callHook('nitro:init', nitro) + enter('close') + nitroBefore({ name: 'close' }) + vi.advanceTimersByTime(1500) + + expect(progress.snapshot.message).toBe('Running nitro:close') + vi.useRealTimers() + }) + + it('should carry on when nitro is never initialised', () => { + vi.useFakeTimers() + const { progress, callHook } = attach() + + callHook('nitro:init', undefined) + callHook('nitro:init', { hooks: {} }) + vi.advanceTimersByTime(1500) + + expect(progress.snapshot.message).toBe('Setting up modules') + vi.useRealTimers() + }) + + it('should stay silent on a nuxt whose hooks cannot be timed', () => { + vi.useFakeTimers() + const progress = new DevProgress() + let before: (event: { name: string, args?: unknown[] }) => void = () => {} + progress.start() + progress.attachNuxt({ beforeEach: fn => (before = fn) }) + + before({ name: 'modules:before' }) + before({ name: 'markdown:blog-entries' }) + vi.advanceTimersByTime(5000) + + expect(progress.snapshot.message).toBe('Setting up modules') + vi.useRealTimers() + }) + }) + + describe('the wait after the server is ready', () => { + it('should hold short of complete until a request has been answered', () => { + const progress = new DevProgress() + progress.start() + const { res } = createResponse() + progress.handleRequest(request(PROGRESS_PATH), res) + + progress.setReady() + expect(progress.snapshot.serving).toBe(false) + expect(progress.snapshot.progress).toBe(0.95) + expect(progress.snapshot.message).toBe('Compiling the first request') + + progress.setServing() + expect(progress.snapshot.serving).toBe(true) + expect(progress.snapshot.progress).toBe(1) + expect(progress.snapshot.message).toBe('Ready') + }) + + it('should not wait for a render nobody is waiting for', () => { + const progress = new DevProgress() + progress.start() + progress.setReady() + + expect(progress.snapshot.serving).toBe(true) + expect(progress.snapshot.progress).toBe(1) + }) + + it('should stop waiting once the page that was waiting has gone', () => { + const progress = new DevProgress() + progress.start() + const { res, close } = createResponse() + progress.handleRequest(request(PROGRESS_PATH), res) + progress.setReady() + + close() + expect(progress.snapshot.serving).toBe(true) + }) + + it('should ignore a render reported before the server is ready', () => { + const progress = new DevProgress() + progress.start() + progress.setServing() + + expect(progress.snapshot.serving).toBe(false) + expect(progress.snapshot.status).toBe('loading') + }) + + it('should wait again for the first render of a reload', () => { + const progress = new DevProgress() + progress.start() + const { res } = createResponse() + progress.handleRequest(request(PROGRESS_PATH), res) + progress.setReady() + progress.setServing() + + progress.start('nuxt.config.ts changed. Reloading Nuxt...', true) + progress.setReady() + + expect(progress.snapshot.serving).toBe(false) + }) + }) + it('should stream snapshots to subscribers', () => { const progress = new DevProgress() progress.start() diff --git a/packages/nuxt-cli/test/unit/dev-startup-log.spec.ts b/packages/nuxt-cli/test/unit/dev-startup-log.spec.ts index 447c05c27..e3def7d67 100644 --- a/packages/nuxt-cli/test/unit/dev-startup-log.spec.ts +++ b/packages/nuxt-cli/test/unit/dev-startup-log.spec.ts @@ -25,6 +25,7 @@ function snapshot(overrides: Partial = {}): DevProgressSnap progress: 0, elapsed: 0, reload: false, + serving: false, timings: [], ...overrides, } @@ -71,6 +72,7 @@ describe('startup reporter', () => { message: 'Ready', index: 6, progress: 1, + serving: true, elapsed: 2400, timings: [ { phase: 'config', message: 'Loading Nuxt config', duration: 320 }, @@ -126,6 +128,22 @@ describe('startup reporter', () => { expect(blankLineBefore()).toBe('\n') }) + it('should not claim a startup is over while the first request is compiling', async () => { + const renderer = await render(() => { + const startup = reporter(true) + startup.update(snapshot()) + startup.update(snapshot({ status: 'ready', phase: 'ready', message: 'Compiling the first request', index: 6, elapsed: 2400 })) + startup.update(snapshot({ status: 'ready', phase: 'ready', message: 'Ready', index: 6, serving: true, elapsed: 8100 })) + }) + + expect(screen(renderer)).toMatchInlineSnapshot(` + "│ + ◆ Ready in 2.4s · compiling the first request + │ + ◆ Serving in 8.1s" + `) + }) + it('should say nothing more after a build error, which is reported separately', async () => { const renderer = await render(() => { const startup = reporter(true) @@ -137,7 +155,7 @@ describe('startup reporter', () => { }) it('should describe a reload rather than a first start', () => { - expect(formatSummary(snapshot({ status: 'ready', reload: true, elapsed: 900 }))).toBe('Reloaded in 900ms') + expect(formatSummary(snapshot({ status: 'ready', reload: true, serving: true, elapsed: 900 }))).toBe('Reloaded in 900ms') }) // `nuxt dev` runs under `consola.wrapAll()`, which moves the real `write` to diff --git a/packages/nuxt-cli/test/unit/dev-tui.spec.ts b/packages/nuxt-cli/test/unit/dev-tui.spec.ts index 39df64d41..b780f522e 100644 --- a/packages/nuxt-cli/test/unit/dev-tui.spec.ts +++ b/packages/nuxt-cli/test/unit/dev-tui.spec.ts @@ -65,6 +65,20 @@ describe('dev tui panel', () => { `) }) + it('should say the first request is still compiling before claiming to be ready', () => { + const lines = renderPanel({ ...READY, status: 'warming', progress: 0.95, awaitingFirstRender: true }, 80, 30).map(strip) + + expect(lines.join('\n')).toContain('WARMUP compiling the first request') + expect(lines.join('\n')).not.toContain('READY') + }) + + it('should not keep claiming how fast the last load was while rebuilding', () => { + for (const status of ['building', 'restarting', 'error'] as const) { + expect(strip(renderPanel({ ...READY, status }, 100, 30)[0]!)).not.toContain('ready in') + } + expect(strip(renderPanel({ ...READY, status: 'warming' }, 100, 30)[0]!)).toContain('ready in 1.24s') + }) + it('counts warnings and errors without printing them', () => { const line = renderPanel({ ...READY, warnings: 2, errors: 1, requests: 12, medianMs: 8 }, 100, 30) .map(strip) diff --git a/packages/nuxt-cli/test/unit/loading-client.spec.ts b/packages/nuxt-cli/test/unit/loading-client.spec.ts index 497e08443..e8e697832 100644 --- a/packages/nuxt-cli/test/unit/loading-client.spec.ts +++ b/packages/nuxt-cli/test/unit/loading-client.spec.ts @@ -24,6 +24,7 @@ function snapshot(overrides: Partial = {}): DevProgressSnap progress: 0.5, elapsed: 1200, reload: false, + serving: false, timings: [], ...overrides, } @@ -108,11 +109,19 @@ describe('the injected progress client', () => { const client = run() client.emit('nuxt:loading', snapshot()) - expect(client.elements[0]!.textContent).toMatch(/^bundle · step 5\/7 · \d+\.\ds$/) + expect(client.elements[0]!.textContent).toMatch(/^bundling app · step 5\/7 · \d+\.\ds$/) expect(client.properties.get('--nuxt-progress')).toBe('50%') expect(document.title).toBe('Bundling app') }) + it('should surface the module being set up, in the caption and the tab title', () => { + const client = run() + client.emit('nuxt:loading', snapshot({ index: 1, phase: 'modules', message: 'Setting up @nuxtjs/i18n', progress: 1 / 6 })) + + expect(client.elements[0]!.textContent).toMatch(/^setting up @nuxtjs\/i18n · step 2\/7 · \d+\.\ds$/) + expect(document.title).toBe('Setting up @nuxtjs/i18n') + }) + it('should hand a build error over to the error page', () => { const client = run() client.emit('nuxt:error', snapshot({ status: 'error' })) @@ -123,18 +132,19 @@ describe('the injected progress client', () => { it('should reload at once after a reload, where nothing is left to warm up', () => { const client = run() - client.emit('nuxt:ready', snapshot({ status: 'ready', reload: true, progress: 1 })) + client.emit('nuxt:ready', snapshot({ status: 'ready', reload: true, progress: 0.95 })) + expect(client.properties.get('--nuxt-progress')).toBe('100%') expect(client.close).toHaveBeenCalled() expect(client.reload).toHaveBeenCalled() }) it('should wait for the app rather than reloading into a cold start', async () => { const client = run({ pollInterval: 1 }) - client.emit('nuxt:ready', snapshot({ status: 'ready', progress: 1 })) + client.emit('nuxt:ready', snapshot({ status: 'ready', progress: 0.95, message: 'Compiling the first request' })) expect(client.reload).not.toHaveBeenCalled() - expect(client.elements[0]!.textContent).toMatch(/^starting the app · /) + expect(client.elements[0]!.textContent).toMatch(/^compiling the first request · /) await vi.waitFor(() => expect(client.reload).toHaveBeenCalled()) expect(client.request).toHaveBeenCalledWith('http://localhost:3000/', expect.objectContaining({ headers: { accept: 'text/html' } })) @@ -143,10 +153,24 @@ describe('the injected progress client', () => { it('should say it is starting the app in the tab title as well as the caption', () => { const client = run() client.emit('nuxt:loading', snapshot()) - client.emit('nuxt:ready', snapshot({ status: 'ready', progress: 1 })) + client.emit('nuxt:ready', snapshot({ status: 'ready', progress: 0.95, message: 'Compiling the first request' })) + + expect(document.title).toBe('Compiling the first request') + expect(client.elements[0]!.textContent).toMatch(/^compiling the first request · /) + }) + + it('should hold the bar short of full while the server is still not serving', () => { + const client = run() + client.emit('nuxt:ready', snapshot({ status: 'ready', progress: 0.95 })) + + expect(client.properties.get('--nuxt-progress')).toBe('95%') + }) + + it('should fill the bar when the snapshot says nothing useful about progress', () => { + const client = run() + client.emit('nuxt:ready', undefined) - expect(document.title).toBe('Starting the app') - expect(client.elements[0]!.textContent).toMatch(/^starting the app · /) + expect(client.properties.get('--nuxt-progress')).toBe('100%') }) it('should never have more than one request for the app in flight', async () => { @@ -186,6 +210,39 @@ describe('the injected progress client', () => { vi.useRealTimers() }) + it('should keep the event stream open while it polls for the app', async () => { + vi.useFakeTimers() + const client = run({}, () => Promise.resolve({ text: () => Promise.resolve('
') } as Response)) + + client.emit('nuxt:ready', snapshot({ status: 'ready', progress: 0.95 })) + await vi.advanceTimersByTimeAsync(5000) + + expect(client.close).not.toHaveBeenCalled() + expect(client.reload).not.toHaveBeenCalled() + vi.useRealTimers() + }) + + it('should close the stream when the app finally answers', async () => { + const client = run({ pollInterval: 1 }) + client.emit('nuxt:ready', snapshot({ status: 'ready', progress: 0.95 })) + + await vi.waitFor(() => expect(client.reload).toHaveBeenCalled()) + expect(client.close).toHaveBeenCalled() + }) + + it('should reload at once when a rebuild finishes mid-warmup', async () => { + vi.useFakeTimers() + const client = run({}, () => Promise.resolve({ text: () => Promise.resolve('
') } as Response)) + + client.emit('nuxt:ready', snapshot({ status: 'ready', progress: 0.95 })) + await vi.advanceTimersByTimeAsync(50) + client.emit('nuxt:ready', snapshot({ status: 'ready', reload: true })) + + expect(client.close).toHaveBeenCalled() + expect(client.reload).toHaveBeenCalledTimes(1) + vi.useRealTimers() + }) + it('should stop polling and reload once, aborting whatever is in flight', async () => { vi.useFakeTimers() const signals: (AbortSignal | undefined)[] = [] diff --git a/packages/nuxt-cli/test/unit/loading-page.spec.ts b/packages/nuxt-cli/test/unit/loading-page.spec.ts index cbb9f7f71..665c7a558 100644 --- a/packages/nuxt-cli/test/unit/loading-page.spec.ts +++ b/packages/nuxt-cli/test/unit/loading-page.spec.ts @@ -12,6 +12,7 @@ function snapshot(overrides: Partial = {}): DevProgressSnap progress: 0.1, elapsed: 0, reload: false, + serving: false, timings: [], ...overrides, }