[wrangler] make sure that the ready-on message is printed after the local runtime is ready

Author: dario-piotrowicz

.changeset/fluffy-seals-arrive.md

@@ -0,0 +1,7 @@
+---
+"wrangler": patch
+---
+
+make sure that the ready-on message is printed after the local runtime is ready
+
+fix the fact that when starting a local dev session the log saying `Ready on http://localhost:xxxx` could be displayed before the local runtime is actually ready to handle requests (this is quite noticeable when running dev sessions with containers, where the ready message currently gets displayed before the container images building/pulling process)

fixtures/interactive-dev-tests/tests/index.test.ts

@@ -493,11 +493,10 @@ baseDescribe.skipIf(process.platform !== "linux" && process.env.CI === "true")(
 		});
 
 		it("should allow quitting while the image is building", async () => {
-			const wrangler = await startWranglerDev([
-				"dev",
-				"-c",
-				path.join(tmpDir, "wrangler.jsonc"),
-			]);
+			const wrangler = await startWranglerDev(
+				["dev", "-c", path.join(tmpDir, "wrangler.jsonc")],
+				true
+			);
 
 			const waitForOptions = {
 				timeout: 10_000,
@@ -517,11 +516,10 @@ baseDescribe.skipIf(process.platform !== "linux" && process.env.CI === "true")(
 		});
 
 		it("should rebuilding while the image is building", async () => {
-			const wrangler = await startWranglerDev([
-				"dev",
-				"-c",
-				path.join(tmpDir, "wrangler.jsonc"),
-			]);
+			const wrangler = await startWranglerDev(
+				["dev", "-c", path.join(tmpDir, "wrangler.jsonc")],
+				true
+			);
 
 			const waitForOptions = {
 				timeout: 15_000,

fixtures/pages-workerjs-app/tests/index.test.ts

@@ -3,7 +3,7 @@ import { rename } from "node:fs/promises";
 import path, { resolve } from "node:path";
 import { setTimeout } from "node:timers/promises";
 import { fetch } from "undici";
-import { describe, it } from "vitest";
+import { describe, it, vi } from "vitest";
 import { runWranglerPagesDev } from "../../shared/src/run-wrangler-long-lived";
 
 describe("Pages _worker.js", () => {
@@ -72,6 +72,15 @@ describe("Pages _worker.js", () => {
 				"--port=0",
 				"--inspector-port=0",
 			]);
+		vi.waitFor(
+			() => {
+				expect(getOutput()).toContain("Ready on");
+			},
+			{
+				timeout: 5_000,
+			}
+		);
+		await setTimeout(200);
 		try {
 			clearOutput();
 			await tryRename(
@@ -109,6 +118,15 @@ describe("Pages _worker.js", () => {
 				"--port=0",
 				"--inspector-port=0",
 			]);
+		vi.waitFor(
+			() => {
+				expect(getOutput()).toContain("Ready on");
+			},
+			{
+				timeout: 5_000,
+			}
+		);
+		await setTimeout(200);
 		try {
 			clearOutput();
 			await tryRename(

packages/wrangler/e2e/containers.dev.test.ts

@@ -189,12 +189,31 @@ describe
 			}
 			// from miniflare output:
 			await worker.readUntil(/Container image\(s\) ready/);
+			await worker.stop();
+		});
+
+		it("will display the ready-on message after the container(s) have been built/pulled", async () => {
+			const worker = helper.runLongLived("wrangler dev");
+			const readyRegexp = /Ready on (http:\/\/[a-z0-9.]+:[0-9]+)/;
+			await worker.readUntil(readyRegexp);
+
+			await worker.stop();
+
+			const fullOutput = await worker.output;
+			const indexOfContainersReadyMessage = fullOutput.indexOf(
+				"Container image(s) ready"
+			);
+
+			const indexOfReadyOnMessage = fullOutput.indexOf("Ready on");
+			expect(indexOfReadyOnMessage).toBeGreaterThan(
+				indexOfContainersReadyMessage
+			);
 		});
 
 		it(`will be able to interact with the container`, async () => {
 			const worker = helper.runLongLived("wrangler dev");
-			const ready = await worker.waitForReady();
 			await worker.readUntil(/Container image\(s\) ready/);
+			const ready = await worker.waitForReady();
 
 			let response = await fetch(`${ready.url}/status`);
 			expect(response.status).toBe(200);

packages/wrangler/e2e/dev-remote-bindings.test.ts

@@ -189,14 +189,14 @@ describe.skipIf(!CLOUDFLARE_ACCOUNT_ID)(
 
 			// This should only include logs from the user Wrangler session (i.e. a single list of attached bindings, and only one ready message)
 			expect(normalizeOutput(worker.currentOutput)).toMatchInlineSnapshot(`
-			"Your Worker has access to the following bindings:
-			Binding        Resource      Mode
-			env.AI         AI            remote
-			[wrangler:info] Ready on http://<HOST>:<PORT>
-			▲ [WARNING] AI bindings always access remote resources, and so may incur usage charges even in local dev. To suppress this warning, set \`experimental_remote: true\` for the binding definition in your configuration file.
-			⎔ Starting local server...
-			[wrangler:info] GET / 200 OK (TIMINGS)"
-		`);
+				"Your Worker has access to the following bindings:
+				Binding        Resource      Mode
+				env.AI         AI            remote
+				▲ [WARNING] AI bindings always access remote resources, and so may incur usage charges even in local dev. To suppress this warning, set \`experimental_remote: true\` for the binding definition in your configuration file.
+				⎔ Starting local server...
+				[wrangler:info] Ready on http://<HOST>:<PORT>
+				[wrangler:info] GET / 200 OK (TIMINGS)"
+			`);
 		});
 
 		describe("shows helpful error logs", () => {

packages/wrangler/e2e/helpers/wrangler.ts

@@ -37,7 +37,7 @@ export class WranglerLongLivedCommand extends LongLivedCommand {
 		super(getWranglerCommand(wranglerCommand), getOptions(options));
 	}
 
-	async waitForReady(readTimeout = 5_000): Promise<{ url: string }> {
+	async waitForReady(readTimeout = 15_000): Promise<{ url: string }> {
 		const match = await this.readUntil(
 			/Ready on (?<url>https?:\/\/.*)/,
 			readTimeout

packages/wrangler/src/api/startDevWorker/DevEnv.ts

@@ -77,6 +77,8 @@ export class DevEnv extends EventEmitter {
 			});
 		});
 
+		this.resolveProxyLocalServerReady().catch(() => {});
+
 		runtimes.forEach((runtime) => {
 			runtime.on("reloadStart", (event) => {
 				proxy.onReloadStart(event);
@@ -93,6 +95,29 @@ export class DevEnv extends EventEmitter {
 		});
 	}
 
+	/**
+	 * Awaits for all the local runtime controllers to be ready, and when they are
+	 * it resolves a promise on the proxy controller to let it know that the
+	 * local server is now ready to handle requests
+	 */
+	private async resolveProxyLocalServerReady(): Promise<void> {
+		await Promise.all(
+			this.runtimes
+				.filter(
+					(runtime) =>
+						runtime instanceof RemoteRuntimeController ||
+						runtime instanceof LocalRuntimeController
+				)
+				.map((runtime) => {
+					return new Promise<void>((resolve) => {
+						runtime.once("reloadComplete", () => resolve());
+					});
+				})
+		);
+
+		this.proxy.localServerReady.resolve();
+	}
+
 	// *********************
 	//   Event Dispatchers
 	// *********************

packages/wrangler/src/api/startDevWorker/ProxyController.ts

@@ -41,7 +41,7 @@ import type {
 } from "./events";
 import type { StartDevWorkerOptions } from "./types";
 import type { DeferredPromise } from "./utils";
-import type { MiniflareOptions } from "miniflare";
+import type { LogOptions, MiniflareOptions } from "miniflare";
 
 type ProxyControllerEventMap = ControllerEventMap & {
 	ready: [ReadyEvent];
@@ -50,6 +50,8 @@ type ProxyControllerEventMap = ControllerEventMap & {
 export class ProxyController extends Controller<ProxyControllerEventMap> {
 	public ready = createDeferred<ReadyEvent>();
 
+	public localServerReady = createDeferred<void>();
+
 	public proxyWorker?: Miniflare;
 	proxyWorkerOptions?: MiniflareOptions;
 	private inspectorProxyWorkerWebSocket?: DeferredPromise<WebSocket>;
@@ -126,11 +128,17 @@ export class ProxyController extends Controller<ProxyControllerEventMap> {
 			verbose: logger.loggerLevel === "debug",
 
 			// log requests into the ProxyWorker (for local + remote mode)
-			log: new ProxyControllerLogger(castLogLevel(logger.loggerLevel), {
-				prefix:
-					// if debugging, log requests with specic ProxyWorker prefix
-					logger.loggerLevel === "debug" ? "wrangler-ProxyWorker" : "wrangler",
-			}),
+			log: new ProxyControllerLogger(
+				castLogLevel(logger.loggerLevel),
+				{
+					prefix:
+						// if debugging, log requests with specic ProxyWorker prefix
+						logger.loggerLevel === "debug"
+							? "wrangler-ProxyWorker"
+							: "wrangler",
+				},
+				this.localServerReady.promise
+			),
 			handleRuntimeStdio,
 			liveReload: false,
 		};
@@ -606,6 +614,18 @@ export class ProxyController extends Controller<ProxyControllerEventMap> {
 }
 
 class ProxyControllerLogger extends WranglerLog {
+	constructor(
+		level: LogLevel,
+		opts: LogOptions,
+		private localServerReady: Promise<void>
+	) {
+		super(level, opts);
+	}
+
+	logReady(message: string): void {
+		this.localServerReady.then(() => super.logReady(message)).catch(() => {});
+	}
+
 	log(message: string) {
 		// filter out request logs being handled by the ProxyWorker
 		// the requests log remaining are handled by the UserWorker

packages/wrangler/src/dev.ts

@@ -5,8 +5,13 @@ import path from "node:path";
 import util from "node:util";
 import { isWebContainer } from "@webcontainer/env";
 import { DevEnv } from "./api";
+import { BundlerController } from "./api/startDevWorker/BundlerController";
+import { ConfigController } from "./api/startDevWorker/ConfigController";
+import { LocalRuntimeController } from "./api/startDevWorker/LocalRuntimeController";
 import { MultiworkerRuntimeController } from "./api/startDevWorker/MultiworkerRuntimeController";
 import { NoOpProxyController } from "./api/startDevWorker/NoOpProxyController";
+import { ProxyController } from "./api/startDevWorker/ProxyController";
+import { RemoteRuntimeController } from "./api/startDevWorker/RemoteRuntimeController";
 import {
 	convertCfWorkerInitBindingsToBindings,
 	extractBindingsOfType,
@@ -38,6 +43,7 @@ import type {
 	StartDevWorkerInput,
 	Trigger,
 } from "./api";
+import type { RuntimeController } from "./api/startDevWorker/BaseController";
 import type { Config, Environment } from "./config";
 import type {
 	EnvironmentNonInheritable,
@@ -670,7 +676,17 @@ export async function startDev(args: StartDevOptions) {
 				unregisterHotKeys = registerDevHotKeys(primaryDevEnv, args);
 			}
 		} else {
-			devEnv = new DevEnv();
+			devEnv = new DevEnv({
+				config: new ConfigController(),
+				bundler: new BundlerController(),
+				runtimes: [
+					...(args.remote
+						? [new RemoteRuntimeController()]
+						: [new LocalRuntimeController()]),
+					// new RemoteRuntimeController(),
+				] as RuntimeController[],
+				proxy: new ProxyController(),
+			});
 
 			// The ProxyWorker will have a stable host and port, so only listen for the first update
 			void devEnv.proxy.ready.promise.then(({ url }) => {