Skip to content

Commit 9242ddb

Browse files
telemetry: move client stream spans from world-vercel to core (vercel#2901)
* fix(deps): dedupe @opentelemetry/api to a single workspace instance The lockfile resolved both 1.9.0 and 1.9.1, so the copy that registers the tracer provider (via @vercel/otel in the app) and the copy a package imports could differ. The API's global-registration version check rejects a consumer newer than the registered copy and silently hands back a noop tracer — which is why world-vercel's spans (workflow.stream.write/ chunk_rtt, read.connect, its http spans) never reached Datadog from deployed apps while core's spans flowed in the same process. Root-caused via the DEBUG=workflow:* run on vercel#2900: import succeeds, no warn, spans dropped. Pin a single version via a workspace override so every bundle shares one API instance. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> * debug: one-shot OTEL runtime diagnostic in core + world-vercel; DEBUG on turbopack workbench The dedupe alone did not restore world-vercel span emission (verified on this PR's own preview: stream traffic flowed, zero workflow.stream.write spans). Under DEBUG=workflow:*, both packages now log once how their module instance of @opentelemetry/api sees the world — global registration version, provider/delegate/tracer/probe constructor names, and whether a probe span is recording. Diffing the core line (spans work) against the world-vercel line (spans dropped) in one deployment's logs pinpoints the divergence. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> * debug: log span identity for named world-vercel spans; namespace otel probes per package Diag round 1 showed world-vercel's tracer records and instrumentedFetch handles the stream PUTs, yet the named spans are unfindable in the backend. Round 2: log traceId/spanId/isRecording for every named instrumentedFetch span under DEBUG so export can be checked for a specific span id, and split the probe span names (.core / .world_vercel) so per-package export is attributable. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> * telemetry: emit stream RPC latencies from core (chunk_rtt, connect_ms, close span) world-vercel's instrumentedFetch spans never export from deployed apps (root cause still open — see PR discussion), so the operationally needed client-side latency signals move one layer up to core, whose spans are proven to export: - workflow.stream.write.chunk_rtt on the workflow.stream.flush span: the World write RPC duration, network included (same attribute key as world-vercel's per-request span so queries are layer-agnostic). - workflow.stream.read.connect_ms on the workflow.stream.read span: the world.streams.get await (read dispatch -> stream handle). - new workflow.stream.close span: the close RPC round trip. Bonus: measured at the World interface, these cover world-local and world-postgres too, not just Vercel deployments. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> * telemetry: emit read-completion span (total duration, chunks, bytes) Completes the read-side picture: workflow.stream.read.complete is back-dated to the read dispatch so its duration is the total read, with chunk/byte counts for throughput. Cancelled reads emit nothing. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> * chore: drop DEBUG from turbopack workbench; tighten changeset Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> * telemetry: cover createReconnectingFramedStream in read telemetry Ordinary serialized streams read through createReconnectingFramedStream (which calls world.streams.get directly), so connect_ms / ttfc / read.complete never fired for that path — only WorkflowServerReadableStream was instrumented. Wire the same helpers into the framed reader: first- connect duration, first-frame TTFC, and completion totals — plus workflow.stream.read.reconnects, which only this path can know. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> --------- Co-authored-by: Claude Fable 5 <noreply@anthropic.com>
1 parent 200845d commit 9242ddb

10 files changed

Lines changed: 551 additions & 202 deletions

File tree

.changeset/dedupe-otel-api.md

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,6 @@
1+
---
2+
'@workflow/core': patch
3+
'@workflow/world-vercel': patch
4+
---
5+
6+
Move client-observed stream telemetry to core: `chunk_rtt` on the flush span, `connect_ms` on the read span, and new `workflow.stream.close` and `workflow.stream.read.complete` spans. Dedupe `@opentelemetry/api` to one workspace instance.

docs/content/docs/v5/observability/tracing.mdx

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -43,6 +43,8 @@ No workflow-specific configuration is required. As soon as a tracer provider and
4343
| `http <method>` | client | the SDK calls the workflow backend (event reads/writes) |
4444
| `workflow.stream.write` | client | a stream chunk (or the stream close) is flushed to the backend |
4545
| `workflow.stream.flush` | client | a buffered batch of stream writes settles; back-dated to the batch's first `write()`, so its duration is the app-perceived batch latency (buffer dwell + RPC) |
46+
| `workflow.stream.close` | client | the stream-close RPC; its duration is the close round trip |
47+
| `workflow.stream.read.complete` | client | a stream read drains; back-dated to the read dispatch, so its duration is the total read (`workflow.stream.read.chunks` / `.bytes` carry throughput counts) |
4648
| `workflow.stream.read.connect` | client | a live stream read opens; the span covers dispatch → response headers (network connect) |
4749
| `workflow.stream.read` | client | a live stream read receives its first chunk; the span's duration is the end-to-end time-to-first-chunk (see `workflow.stream.read.ttfc_ms`) |
4850

@@ -61,9 +63,10 @@ Stream spans are emitted by the SDK's world backend on the client that writes or
6163
| `workflow.queue.overhead_ms` | Time between the message being enqueued and the handler starting — queue dwell plus any cold start. |
6264
| `workflow.stream.name` | The stream name, on stream write/read spans. |
6365
| `workflow.stream.operation` | The stream operation: `write`, `write_multi`, `close`, `read`, or `flush`. |
64-
| `workflow.stream.write.chunk_rtt` | Time between emissions of a chunk to the wire, and receiving the `ack` message for that chunk. |
66+
| `workflow.stream.write.chunk_rtt` | Time between emissions of a chunk to the wire, and receiving the `ack` message for that chunk. Also stamped on `workflow.stream.flush` (the batch's write RPC duration, network included). |
6567
| `workflow.stream.flush.buffer_dwell_ms` | On `workflow.stream.flush`: time the batch's first chunk waited in the client-side write buffer (flush timer, run-ready barrier) before the request was dispatched. `workflow.stream.flush.chunks` / `.bytes` carry the batch shape. |
6668
| `workflow.stream.read.ttfc_ms` | Time between opening a read connection and observing and receiving the first chunk back. |
69+
| `workflow.stream.read.connect_ms` | On `workflow.stream.read`: the connect portion (read dispatch → stream handle/response headers), network included. |
6770

6871
## Trace shape: one trace per invocation
6972

Lines changed: 179 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,179 @@
1+
import { trace as otelTrace, SpanKind } from '@opentelemetry/api';
2+
import {
3+
BasicTracerProvider,
4+
InMemorySpanExporter,
5+
type ReadableSpan,
6+
SimpleSpanProcessor,
7+
} from '@opentelemetry/sdk-trace-base';
8+
import { SPEC_VERSION_CURRENT } from '@workflow/world';
9+
import {
10+
afterAll,
11+
afterEach,
12+
beforeAll,
13+
beforeEach,
14+
describe,
15+
expect,
16+
it,
17+
vi,
18+
} from 'vitest';
19+
import { setWorld } from './runtime/world.js';
20+
import {
21+
createReconnectingFramedStream,
22+
WorkflowServerReadableStream,
23+
} from './serialization.js';
24+
25+
/** 4-byte BE length prefix + payload — the framed-v1 wire layout. */
26+
function frame(payload: Uint8Array): Uint8Array {
27+
const out = new Uint8Array(4 + payload.byteLength);
28+
new DataView(out.buffer).setUint32(0, payload.byteLength, false);
29+
out.set(payload, 4);
30+
return out;
31+
}
32+
33+
const exporter = new InMemorySpanExporter();
34+
const provider = new BasicTracerProvider();
35+
36+
beforeAll(() => {
37+
provider.addSpanProcessor(new SimpleSpanProcessor(exporter));
38+
otelTrace.setGlobalTracerProvider(provider);
39+
});
40+
41+
afterAll(async () => {
42+
await provider.shutdown();
43+
otelTrace.disable();
44+
});
45+
46+
/** The read span is emitted fire-and-forget on the first chunk; poll for it. */
47+
async function waitForSpans(
48+
name: string,
49+
count: number
50+
): Promise<ReadableSpan[]> {
51+
for (let i = 0; i < 50; i++) {
52+
const spans = exporter.getFinishedSpans().filter((s) => s.name === name);
53+
if (spans.length >= count) return spans;
54+
await new Promise((r) => setTimeout(r, 10));
55+
}
56+
return exporter.getFinishedSpans().filter((s) => s.name === name);
57+
}
58+
59+
describe('WorkflowServerReadableStream read telemetry', () => {
60+
beforeEach(() => {
61+
exporter.reset();
62+
setWorld({
63+
specVersion: SPEC_VERSION_CURRENT,
64+
streams: {
65+
get: vi.fn().mockImplementation(
66+
async () =>
67+
new ReadableStream<Uint8Array>({
68+
start(controller) {
69+
controller.enqueue(new Uint8Array([1, 2, 3]));
70+
controller.close();
71+
},
72+
})
73+
),
74+
},
75+
} as any);
76+
});
77+
78+
afterEach(() => {
79+
setWorld(undefined);
80+
vi.clearAllMocks();
81+
});
82+
83+
it('emits a workflow.stream.read span with ttfc and connect durations', async () => {
84+
const stream = new WorkflowServerReadableStream('run-123', 'test-stream');
85+
const reader = stream.getReader();
86+
// Drain: empty header chunk, real chunk, done.
87+
for (let i = 0; i < 5; i++) {
88+
const { done } = await reader.read();
89+
if (done) break;
90+
}
91+
92+
const [span] = await waitForSpans('workflow.stream.read', 1);
93+
expect(span).toBeDefined();
94+
expect(span.kind).toBe(SpanKind.CLIENT);
95+
expect(span.attributes['workflow.run.id']).toBe('run-123');
96+
expect(span.attributes['workflow.stream.name']).toBe('test-stream');
97+
expect(span.attributes['workflow.stream.operation']).toBe('read');
98+
99+
const ttfc = span.attributes['workflow.stream.read.ttfc_ms'];
100+
expect(typeof ttfc).toBe('number');
101+
expect(ttfc as number).toBeGreaterThanOrEqual(0);
102+
103+
// Client-observed connect duration (the world.streams.get await).
104+
const connect = span.attributes['workflow.stream.read.connect_ms'];
105+
expect(typeof connect).toBe('number');
106+
expect(connect as number).toBeGreaterThanOrEqual(0);
107+
expect(connect as number).toBeLessThanOrEqual((ttfc as number) + 1);
108+
});
109+
110+
it('emits a workflow.stream.read.complete span with totals when the read drains', async () => {
111+
const stream = new WorkflowServerReadableStream('run-123', 'test-stream');
112+
const reader = stream.getReader();
113+
for (let i = 0; i < 5; i++) {
114+
const { done } = await reader.read();
115+
if (done) break;
116+
}
117+
118+
const [span] = await waitForSpans('workflow.stream.read.complete', 1);
119+
expect(span).toBeDefined();
120+
expect(span.kind).toBe(SpanKind.CLIENT);
121+
expect(span.attributes['workflow.stream.operation']).toBe('read_complete');
122+
expect(span.attributes['workflow.stream.read.chunks']).toBe(1);
123+
expect(span.attributes['workflow.stream.read.bytes']).toBe(3);
124+
expect(typeof span.attributes['workflow.stream.read.total_ms']).toBe(
125+
'number'
126+
);
127+
});
128+
});
129+
130+
describe('createReconnectingFramedStream read telemetry', () => {
131+
beforeEach(() => {
132+
exporter.reset();
133+
setWorld({
134+
specVersion: SPEC_VERSION_CURRENT,
135+
streams: {
136+
get: vi.fn().mockImplementation(
137+
async () =>
138+
new ReadableStream<Uint8Array>({
139+
start(controller) {
140+
controller.enqueue(frame(new Uint8Array([1, 2, 3])));
141+
controller.enqueue(frame(new Uint8Array([4, 5])));
142+
controller.close();
143+
},
144+
})
145+
),
146+
},
147+
} as any);
148+
});
149+
150+
afterEach(() => {
151+
setWorld(undefined);
152+
vi.clearAllMocks();
153+
});
154+
155+
it('emits read and read.complete spans with connect, ttfc, totals, and reconnects', async () => {
156+
const stream = createReconnectingFramedStream('run-123', 'test-stream');
157+
const reader = stream.getReader();
158+
for (let i = 0; i < 10; i++) {
159+
const { done } = await reader.read();
160+
if (done) break;
161+
}
162+
163+
const [readSpan] = await waitForSpans('workflow.stream.read', 1);
164+
expect(readSpan).toBeDefined();
165+
expect(typeof readSpan.attributes['workflow.stream.read.ttfc_ms']).toBe(
166+
'number'
167+
);
168+
expect(typeof readSpan.attributes['workflow.stream.read.connect_ms']).toBe(
169+
'number'
170+
);
171+
172+
const [doneSpan] = await waitForSpans('workflow.stream.read.complete', 1);
173+
expect(doneSpan).toBeDefined();
174+
expect(doneSpan.attributes['workflow.stream.read.chunks']).toBe(2);
175+
// 2 frames of (4-byte header + payload): (4+3) + (4+2)
176+
expect(doneSpan.attributes['workflow.stream.read.bytes']).toBe(13);
177+
expect(doneSpan.attributes['workflow.stream.read.reconnects']).toBe(0);
178+
});
179+
});

0 commit comments

Comments
 (0)