Support TailEvent messages in Tail sessions (#4071)

When tailing a tail worker, messages previously had a null event
property. Following cloudflare/workerd#1248,
these events have a valid event, specifying which scripts produced
events that caused your tail worker to run.

As part of rolling this out, we're filtering out tail events in the
internal tail infrastructure, so we control when these new messages are
forward to tail sessions, and can merge this freely.

One idiosyncracy to note, however, is that tail workers always report an
"OK" status, even if they run out of memory or throw. That is being
tracked and worked on separately.

.changeset/serious-beans-hug.md

@@ -0,0 +1,18 @@
+---
+"wrangler": minor
+---
+
+Support TailEvent messages in Tail sessions
+
+When tailing a tail worker, messages previously had a null event
+property. Following https://github.com/cloudflare/workerd/pull/1248,
+these events have a valid event, specifying which scripts produced
+events that caused your tail worker to run.
+
+As part of rolling this out, we're filtering out tail events in the
+internal tail infrastructure, so we control when these new messages are
+forward to tail sessions, and can merge this freely.
+
+One idiosyncracy to note, however, is that tail workers always report an
+"OK" status, even if they run out of memory or throw. That is being
+tracked and worked on separately.

packages/wrangler/src/__tests__/pages-deployment-tail.test.ts

@@ -13,6 +13,7 @@ import type {
 	ScheduledEvent,
 	AlarmEvent,
 	EmailEvent,
+	TailEvent,
 	TailInfo,
 } from "../tail/createTail";
 import type { RequestInit } from "undici";
@@ -663,6 +664,7 @@ function isRequest(
 		| RequestEvent
 		| AlarmEvent
 		| EmailEvent
+		| TailEvent
 		| TailInfo
 		| undefined
 		| null

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

@@ -14,6 +14,7 @@ import type {
 	ScheduledEvent,
 	AlarmEvent,
 	EmailEvent,
+	TailEvent,
 	TailInfo,
 } from "../tail/createTail";
 import type { RequestInit } from "undici";
@@ -426,6 +427,18 @@ describe("tail", () => {
 			expect(std.out).toMatch(deserializeToJson(serializedMessage));
 		});
 
+		it("logs tail messages in json format", async () => {
+			const api = mockWebsocketAPIs();
+			await runWrangler("tail test-worker --format json");
+
+			const event = generateMockTailEvent(["some-worker", "some-worker"]);
+			const message = generateMockEventMessage({ event });
+			const serializedMessage = serialize(message);
+
+			api.ws.send(serializedMessage);
+			expect(std.out).toMatch(deserializeToJson(serializedMessage));
+		});
+
 		it("logs request messages in pretty format", async () => {
 			const api = mockWebsocketAPIs();
 			await runWrangler("tail test-worker --format pretty");
@@ -518,6 +531,32 @@ describe("tail", () => {
 		`);
 		});
 
+		it("logs tail messages in pretty format", async () => {
+			const api = mockWebsocketAPIs();
+			await runWrangler("tail test-worker --format pretty");
+
+			const event = generateMockTailEvent(["some-worker", "other-worker", ""]);
+			const message = generateMockEventMessage({ event });
+			const serializedMessage = serialize(message);
+
+			api.ws.send(serializedMessage);
+			expect(
+				std.out
+					.replace(
+						new Date(mockEventTimestamp).toLocaleString(),
+						"[mock event timestamp]"
+					)
+					.replace(
+						new Date(mockTailExpiration).toISOString(),
+						"[mock expiration date]"
+					)
+			).toMatchInlineSnapshot(`
+			"Successfully created tail, expires at [mock expiration date]
+			Connected to test-worker, waiting for logs...
+			Tailing some-worker,other-worker - Ok @ [mock event timestamp]"
+		`);
+		});
+
 		it("logs tail overload message", async () => {
 			const api = mockWebsocketAPIs();
 			await runWrangler("tail test-worker --format pretty");
@@ -710,6 +749,7 @@ function isRequest(
 		| RequestEvent
 		| AlarmEvent
 		| EmailEvent
+		| TailEvent
 		| TailInfo
 		| undefined
 		| null
@@ -993,6 +1033,14 @@ function generateMockEmailEvent(opts?: Partial<EmailEvent>): EmailEvent {
 	};
 }
 
+function generateMockTailEvent(tailing: string[]): TailEvent {
+	return {
+		consumedEvents: tailing.map((tailedScript) => {
+			return { scriptName: tailedScript };
+		}),
+	};
+}
+
 function generateTailInfo(overload: boolean): TailInfo {
 	return overload
 		? {

packages/wrangler/src/tail/createTail.ts

@@ -252,6 +252,7 @@ export type TailEventMessage = {
 		| ScheduledEvent
 		| AlarmEvent
 		| EmailEvent
+		| TailEvent
 		| TailInfo
 		| undefined
 		| null;
@@ -406,6 +407,22 @@ export type EmailEvent = {
 	rawSize: number;
 };
 
+/**
+ * An event that was triggered for a tail receiving TailEventMessages
+ * Only seen when tailing a tail worker
+ */
+export type TailEvent = {
+	/**
+	 * A minimal representation of the TailEventMessages that were delivered to the tail handler
+	 */
+	consumedEvents: {
+		/**
+		 * The name of script being tailed
+		 */
+		scriptName?: string;
+	}[];
+};
+
 /**
  * Message from tail with information about the tail itself
  */

packages/wrangler/src/tail/printing.ts

@@ -5,6 +5,7 @@ import type {
 	EmailEvent,
 	RequestEvent,
 	ScheduledEvent,
+	TailEvent,
 	TailInfo,
 	TailEventMessage,
 } from "./createTail";
@@ -50,6 +51,20 @@ export function prettyPrintLogs(data: WebSocket.RawData): void {
 		).toLocaleString();
 
 		logger.log(`Alarm @ ${datetime} - ${outcome}`);
+	} else if (isTailEvent(eventMessage.event)) {
+		const outcome = prettifyOutcome(eventMessage.outcome);
+		const datetime = new Date(eventMessage.eventTimestamp).toLocaleString();
+		const tailedScripts = new Set(
+			eventMessage.event.consumedEvents
+				.map((consumedEvent) => consumedEvent.scriptName)
+				.filter((scriptName) => !!scriptName)
+		);
+
+		logger.log(
+			`Tailing ${Array.from(tailedScripts).join(
+				","
+			)} - ${outcome} @ ${datetime}`
+		);
 	} else if (isTailInfo(eventMessage.event)) {
 		if (eventMessage.event.type === "overload") {
 			logger.log(`${chalk.red.bold(eventMessage.event.message)}`);
@@ -111,6 +126,10 @@ function isAlarmEvent(event: TailEventMessage["event"]): event is AlarmEvent {
 	return Boolean(event && "scheduledTime" in event && !("cron" in event));
 }
 
+function isTailEvent(event: TailEventMessage["event"]): event is TailEvent {
+	return Boolean(event && "consumedEvents" in event);
+}
+
 function isTailInfo(event: TailEventMessage["event"]): event is TailInfo {
 	return Boolean(event && "message" in event && "type" in event);
 }