Clarify custom build logging (#7423)

* Skip double custom build

* Fix logging

* update snapshots

* Create thirty-bears-appear.md

Author: penalosa

.changeset/thirty-bears-appear.md

@@ -0,0 +1,5 @@
+---
+"wrangler": patch
+---
+
+Make sure custom build logging output is more clearly signposted, and make sure it doesn't interfere with the interactive dev session output.

packages/wrangler/e2e/dev.test.ts

@@ -1118,9 +1118,9 @@ describe("custom builds", () => {
 		const worker = helper.runLongLived("wrangler dev");
 
 		// first build on startup
-		await worker.readUntil(/Running custom build/, 5_000);
+		await worker.readUntil(/\[custom build\] Running/, 5_000);
 		// second build for first watcher notification (can be optimised away, leaving as-is for now)
-		await worker.readUntil(/Running custom build/, 5_000);
+		await worker.readUntil(/\[custom build\] Running/, 5_000);
 
 		// Need to get the url in this order because waitForReady calls readUntil
 		// which keeps track of where it's read up to so far,
@@ -1132,7 +1132,7 @@ describe("custom builds", () => {
 		// assert no more custom builds happen
 		// regression: https://github.com/cloudflare/workers-sdk/issues/6876
 		await expect(
-			worker.readUntil(/Running custom build:/, 5_000)
+			worker.readUntil(/\[custom build\] Running/, 5_000)
 		).rejects.toThrowError();
 
 		// now check assets are still fetchable, even after updates

packages/wrangler/src/__tests__/deploy.test.ts

@@ -6381,7 +6381,7 @@ addEventListener('fetch', event => {});`
 
 			await runWrangler("deploy index.js");
 			expect(std.out).toMatchInlineSnapshot(`
-				"Running custom build: node -e \\"4+4; require('fs').writeFileSync('index.js', 'export default { fetch(){ return new Response(123) } }')\\"
+				"[custom build] Running: node -e \\"4+4; require('fs').writeFileSync('index.js', 'export default { fetch(){ return new Response(123) } }')\\"
 				Total Upload: xx KiB / gzip: xx KiB
 				Worker Startup Time: 100 ms
 				No bindings found.
@@ -6409,7 +6409,7 @@ addEventListener('fetch', event => {});`
 
 				await runWrangler("deploy index.js");
 				expect(std.out).toMatchInlineSnapshot(`
-					"Running custom build: echo \\"export default { fetch(){ return new Response(123) } }\\" > index.js
+					"[custom build] Running: echo \\"export default { fetch(){ return new Response(123) } }\\" > index.js
 					Total Upload: xx KiB / gzip: xx KiB
 					Worker Startup Time: 100 ms
 					No bindings found.
@@ -6437,9 +6437,9 @@ addEventListener('fetch', event => {});`
 				The \`main\` property in your wrangler.toml file should point to the file generated by the custom build.]
 			`);
 			expect(std.out).toMatchInlineSnapshot(`
-			"Running custom build: node -e \\"4+4;\\"
-			"
-		`);
+				"[custom build] Running: node -e \\"4+4;\\"
+				"
+			`);
 			expect(std.err).toMatchInlineSnapshot(`
 				"X [ERROR] The expected output file at \\"index.js\\" was not found after running custom build: node -e \\"4+4;\\".
 
@@ -6476,9 +6476,9 @@ addEventListener('fetch', event => {});`
 				\`\`\`]
 			`);
 			expect(std.out).toMatchInlineSnapshot(`
-			"Running custom build: node -e \\"4+4;\\"
-			"
-		`);
+				"[custom build] Running: node -e \\"4+4;\\"
+				"
+			`);
 			expect(std.err).toMatchInlineSnapshot(`
 				"X [ERROR] The expected output file at \\".\\" was not found after running custom build: node -e \\"4+4;\\".
 

packages/wrangler/src/__tests__/dev.test.ts

@@ -887,7 +887,7 @@ describe.sequential("wrangler dev", () => {
 			});
 			expect(std.out).toMatchInlineSnapshot(
 				`
-				"Running custom build: node -e \\"4+4; require('fs').writeFileSync('index.js', 'export default { fetch(){ return new Response(123) } }')\\"
+				"[custom build] Running: node -e \\"4+4; require('fs').writeFileSync('index.js', 'export default { fetch(){ return new Response(123) } }')\\"
 				No bindings found.
 				"
 			`
@@ -912,7 +912,7 @@ describe.sequential("wrangler dev", () => {
 
 				expect(std.out).toMatchInlineSnapshot(
 					`
-					"Running custom build: echo \\"export default { fetch(){ return new Response(123) } }\\" > index.js
+					"[custom build] Running: echo \\"export default { fetch(){ return new Response(123) } }\\" > index.js
 					No bindings found.
 					"
 				`
@@ -934,9 +934,9 @@ describe.sequential("wrangler dev", () => {
 				The \`main\` property in your wrangler.toml file should point to the file generated by the custom build.]
 			`);
 			expect(std.out).toMatchInlineSnapshot(`
-			"Running custom build: node -e \\"4+4;\\"
-			"
-		`);
+				"[custom build] Running: node -e \\"4+4;\\"
+				"
+			`);
 			expect(std.err).toMatchInlineSnapshot(`
 				"X [ERROR] The expected output file at \\"index.js\\" was not found after running custom build: node -e \\"4+4;\\".
 

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

@@ -197,7 +197,7 @@ export class BundlerController extends Controller<BundlerControllerEventMap> {
 
 		this.#customBuildWatcher = watch(pathsToWatch, {
 			persistent: true,
-			// TODO: add comments re this ans ready
+			// The initial custom build is always done in getEntry()
 			ignoreInitial: true,
 		});
 		this.#customBuildWatcher.on("ready", () => {

packages/wrangler/src/deployment-bundle/run-custom-build.ts

@@ -1,5 +1,7 @@
 import { existsSync, statSync } from "node:fs";
 import path from "node:path";
+import { Writable } from "node:stream";
+import chalk from "chalk";
 import { execaCommand } from "execa";
 import { configFileName } from "../config";
 import { UserError } from "../errors";
@@ -19,17 +21,37 @@ export async function runCustomBuild(
 	configPath: string | undefined
 ) {
 	if (build.command) {
-		logger.log("Running custom build:", build.command);
+		logger.log(chalk.blue("[custom build]"), "Running:", build.command);
 		try {
-			await execaCommand(build.command, {
+			const res = execaCommand(build.command, {
 				shell: true,
-				// we keep these two as "inherit" so that
-				// logs are still visible.
-				stdout: "inherit",
-				stderr: "inherit",
 				...(build.cwd && { cwd: build.cwd }),
 			});
+			res.stdout?.pipe(
+				new Writable({
+					write(chunk: Buffer, _, callback) {
+						const lines = chunk.toString().split("\n");
+						for (const line of lines) {
+							logger.log(chalk.blue("[custom build]"), line);
+						}
+						callback();
+					},
+				})
+			);
+			res.stderr?.pipe(
+				new Writable({
+					write(chunk: Buffer, _, callback) {
+						const lines = chunk.toString().split("\n");
+						for (const line of lines) {
+							logger.log(chalk.red("[custom build]"), line);
+						}
+						callback();
+					},
+				})
+			);
+			await res;
 		} catch (e) {
+			logger.error(e);
 			throw new UserError(
 				`Running custom build \`${build.command}\` failed. There are likely more logs from your build command above.`,
 				{