[wrangler] make sure that the ready-on message is printed after the appropriate runtime controller is ready (#9910)

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 appropriate runtime controller is ready
+
+fix the fact that when starting a local (or remote) dev session the log saying `Ready on http://localhost:xxxx` could be displayed before the runtime is actually ready to handle requests (this is quite noticeable when locally 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

@@ -500,11 +500,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,
@@ -524,11 +523,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

@@ -196,14 +196,15 @@ for (const source of imageSource) {
 			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/);
 
-				let response = await fetch(`${ready.url}/status`);
-				expect(response.status).toBe(200);
-				let status = await response.json();
-				expect(status).toBe(false);
+				await vi.waitFor(async () => {
+					const response = await fetch(`${ready.url}/status`);
+					expect(response.status).toBe(200);
+					const status = await response.json();
+					expect(status).toBe(false);
+				});
 
-				response = await fetch(`${ready.url}/start`);
+				let response = await fetch(`${ready.url}/start`);
 				let text = await response.text();
 				expect(response.status).toBe(200);
 				expect(text).toBe("Container create request sent...");
@@ -212,7 +213,7 @@ for (const source of imageSource) {
 				await new Promise((resolve) => setTimeout(resolve, 2_000));
 
 				response = await fetch(`${ready.url}/status`);
-				status = await response.json();
+				const status = await response.json();
 				expect(response.status).toBe(200);
 				expect(status).toBe(true);
 
@@ -254,6 +255,24 @@ for (const source of imageSource) {
 				);
 			});
 
+			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("won't start the container service if --enable-containers is set to false via CLI", async () => {
 				const worker = helper.runLongLived(
 					"wrangler dev --enable-containers=false"

packages/wrangler/e2e/helpers/wrangler.ts

@@ -35,7 +35,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/e2e/remote-binding/dev-remote-bindings.test.ts

@@ -177,18 +177,18 @@ describe.skipIf(!CLOUDFLARE_ACCOUNT_ID)(
 			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] Ready on http://<HOST>:<PORT>
 			[wrangler:info] GET / 200 OK (TIMINGS)`;
 
 			const output2 = dedent`
 			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.
-			[wrangler:info] Ready on http://<HOST>:<PORT>
 			⎔ Starting local server...
+			[wrangler:info] Ready on http://<HOST>:<PORT>
 			[wrangler:info] GET / 200 OK (TIMINGS)`;
 
 			const normalizedOutput = normalizeOutput(worker.currentOutput);

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,
 		};
@@ -419,6 +427,8 @@ export class ProxyController extends Controller<ProxyControllerEventMap> {
 		}
 	}
 	onReloadComplete(data: ReloadCompleteEvent) {
+		this.localServerReady.resolve();
+
 		this.latestConfig = data.config;
 		this.latestBundle = data.bundle;
 
@@ -606,6 +616,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