From f880a009ad7c7ec26a85c51f577164522a307217 Mon Sep 17 00:00:00 2001 From: matthewdavidrodgers <39633382+matthewdavidrodgers@users.noreply.github.com> Date: Fri, 6 Oct 2023 09:10:44 -0700 Subject: [PATCH] Support TailEvent messages in Tail sessions (#4071) 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. --- .changeset/serious-beans-hug.md | 18 +++++++ .../__tests__/pages-deployment-tail.test.ts | 2 + packages/wrangler/src/__tests__/tail.test.ts | 48 +++++++++++++++++++ packages/wrangler/src/tail/createTail.ts | 17 +++++++ packages/wrangler/src/tail/printing.ts | 19 ++++++++ 5 files changed, 104 insertions(+) create mode 100644 .changeset/serious-beans-hug.md diff --git a/.changeset/serious-beans-hug.md b/.changeset/serious-beans-hug.md new file mode 100644 index 000000000000..25c772cf1873 --- /dev/null +++ b/.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. diff --git a/packages/wrangler/src/__tests__/pages-deployment-tail.test.ts b/packages/wrangler/src/__tests__/pages-deployment-tail.test.ts index e4aa6750cf47..d7f190c4aa87 100644 --- a/packages/wrangler/src/__tests__/pages-deployment-tail.test.ts +++ b/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 diff --git a/packages/wrangler/src/__tests__/tail.test.ts b/packages/wrangler/src/__tests__/tail.test.ts index c637fdfdb8df..99b66936bac8 100644 --- a/packages/wrangler/src/__tests__/tail.test.ts +++ b/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 { }; } +function generateMockTailEvent(tailing: string[]): TailEvent { + return { + consumedEvents: tailing.map((tailedScript) => { + return { scriptName: tailedScript }; + }), + }; +} + function generateTailInfo(overload: boolean): TailInfo { return overload ? { diff --git a/packages/wrangler/src/tail/createTail.ts b/packages/wrangler/src/tail/createTail.ts index 89d470726155..9d5143370585 100644 --- a/packages/wrangler/src/tail/createTail.ts +++ b/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 */ diff --git a/packages/wrangler/src/tail/printing.ts b/packages/wrangler/src/tail/printing.ts index 05d8fd6d3152..f2be8cae2a0c 100644 --- a/packages/wrangler/src/tail/printing.ts +++ b/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); }