From e0f9a6e0f542bd63d5a007e7f39f337e7cf5458b Mon Sep 17 00:00:00 2001 From: Felix Hanau Date: Tue, 21 Oct 2025 16:25:39 -0400 Subject: [PATCH 1/3] EW-9372 EW-9455 [o11y] Prepare reporting SpanOpen event earlier This PR serves to perform two long-standing cleanup tasks in the STW implementation: 1) Sending the SpanOpen event as soon as a span is opened instead of when it closes 2) Getting rid of the CompleteSpan struct, which represents a full span but is something that won't be needed once SpanOpen is handled separately. To implement this in a backwards-compatible way, we need to land it in two parts so that the old code path and the new code path are both supported until we have phased out the old version which doesn't have the APIs for handling SpanOpen separately. --- .../test/d1/d1-api-instrumentation-test.js | 62 ++++++------- .../images/images-api-instrumentation-test.js | 90 ++++++++++++++++--- src/workerd/api/tests/actor-kv-test-tail.js | 12 +-- .../api/tests/r2-instrumentation-test.js | 26 +++--- src/workerd/api/tests/tail-worker-test.js | 2 +- src/workerd/io/trace.c++ | 25 ++++-- src/workerd/io/trace.capnp | 11 +++ src/workerd/io/trace.h | 29 ++++-- src/workerd/io/tracer.c++ | 51 +++++++---- src/workerd/io/tracer.h | 16 +++- src/workerd/server/server.c++ | 14 ++- 11 files changed, 243 insertions(+), 95 deletions(-) diff --git a/src/cloudflare/internal/test/d1/d1-api-instrumentation-test.js b/src/cloudflare/internal/test/d1/d1-api-instrumentation-test.js index 2f3881437d8..8f8fa5b3a0d 100644 --- a/src/cloudflare/internal/test/d1/d1-api-instrumentation-test.js +++ b/src/cloudflare/internal/test/d1/d1-api-instrumentation-test.js @@ -31,18 +31,6 @@ export const test = { }; const expectedSpans = [ - { - name: 'fetch', - 'network.protocol.name': 'http', - 'network.protocol.version': 'HTTP/1.1', - 'http.request.method': 'POST', - 'url.full': 'http://d1/execute?resultsFormat=NONE', - 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 231n, - 'http.response.status_code': 200n, - 'http.response.body.size': 0n, - closed: true, - }, { name: 'd1_run', 'db.system.name': 'cloudflare-d1', @@ -70,9 +58,9 @@ const expectedSpans = [ 'network.protocol.name': 'http', 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', - 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', + 'url.full': 'http://d1/execute?resultsFormat=NONE', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 42n, + 'http.request.body.size': 231n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -96,7 +84,7 @@ const expectedSpans = [ 'network.protocol.name': 'http', 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', - 'url.full': 'http://d1/execute?resultsFormat=NONE', + 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', 'http.request.header.content-type': 'application/json', 'http.request.body.size': 42n, 'http.response.status_code': 200n, @@ -124,7 +112,7 @@ const expectedSpans = [ 'http.request.method': 'POST', 'url.full': 'http://d1/execute?resultsFormat=NONE', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 40n, + 'http.request.body.size': 42n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -148,9 +136,9 @@ const expectedSpans = [ 'network.protocol.name': 'http', 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', - 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', + 'url.full': 'http://d1/execute?resultsFormat=NONE', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 223n, + 'http.request.body.size': 40n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -180,9 +168,9 @@ const expectedSpans = [ 'network.protocol.name': 'http', 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', - 'url.full': 'http://d1/execute?resultsFormat=NONE', + 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 40n, + 'http.request.body.size': 223n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -208,7 +196,7 @@ const expectedSpans = [ 'http.request.method': 'POST', 'url.full': 'http://d1/execute?resultsFormat=NONE', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 223n, + 'http.request.body.size': 40n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -238,9 +226,9 @@ const expectedSpans = [ 'network.protocol.name': 'http', 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', - 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', + 'url.full': 'http://d1/execute?resultsFormat=NONE', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 31n, + 'http.request.body.size': 223n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -344,7 +332,7 @@ const expectedSpans = [ 'http.request.method': 'POST', 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 42n, + 'http.request.body.size': 31n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -448,7 +436,7 @@ const expectedSpans = [ 'http.request.method': 'POST', 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 61n, + 'http.request.body.size': 42n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -656,7 +644,7 @@ const expectedSpans = [ 'http.request.method': 'POST', 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 125n, + 'http.request.body.size': 61n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -685,7 +673,7 @@ const expectedSpans = [ 'http.request.method': 'POST', 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 79n, + 'http.request.body.size': 125n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -815,7 +803,7 @@ const expectedSpans = [ 'http.request.method': 'POST', 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 298n, + 'http.request.body.size': 79n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -846,7 +834,7 @@ const expectedSpans = [ 'http.request.method': 'POST', 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 45n, + 'http.request.body.size': 298n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -950,7 +938,7 @@ const expectedSpans = [ 'http.request.method': 'POST', 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 76n, + 'http.request.body.size': 45n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -976,7 +964,7 @@ const expectedSpans = [ 'http.request.method': 'POST', 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 117n, + 'http.request.body.size': 76n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -996,4 +984,16 @@ const expectedSpans = [ 'cloudflare.d1.response.changes': 0, closed: true, }, + { + name: 'fetch', + 'network.protocol.name': 'http', + 'network.protocol.version': 'HTTP/1.1', + 'http.request.method': 'POST', + 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', + 'http.request.header.content-type': 'application/json', + 'http.request.body.size': 117n, + 'http.response.status_code': 200n, + 'http.response.body.size': 0n, + closed: true, + }, ]; diff --git a/src/cloudflare/internal/test/images/images-api-instrumentation-test.js b/src/cloudflare/internal/test/images/images-api-instrumentation-test.js index 5757a1dd10b..8f73045222e 100644 --- a/src/cloudflare/internal/test/images/images-api-instrumentation-test.js +++ b/src/cloudflare/internal/test/images/images-api-instrumentation-test.js @@ -84,6 +84,8 @@ const expectedSpans = [ 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', 'url.full': 'https://js.images.cloudflare.com/transform', + 'cloudflare.binding.type': 'Images', + 'cloudflare.images.options.format': 'image/avif', 'http.request.header.content-type': 'multipart/form-data; boundary=', 'http.response.status_code': 200n, @@ -96,6 +98,8 @@ const expectedSpans = [ 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', 'url.full': 'https://js.images.cloudflare.com/transform', + 'cloudflare.binding.type': 'Images', + 'cloudflare.images.options.format': 'image/avif', 'http.request.header.content-type': 'multipart/form-data; boundary=', 'http.response.status_code': 200n, @@ -108,6 +112,9 @@ const expectedSpans = [ 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', 'url.full': 'https://js.images.cloudflare.com/transform', + 'cloudflare.binding.type': 'Images', + 'cloudflare.images.options.format': 'image/avif', + 'cloudflare.images.options.transforms': '[{"imageIndex":0,"rotate":90}]', 'http.request.header.content-type': 'multipart/form-data; boundary=', 'http.response.status_code': 200n, @@ -120,6 +127,9 @@ const expectedSpans = [ 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', 'url.full': 'https://js.images.cloudflare.com/transform', + 'cloudflare.binding.type': 'Images', + 'cloudflare.images.options.format': 'image/avif', + 'cloudflare.images.options.transforms': '[{"imageIndex":0,"rotate":90}]', 'http.request.header.content-type': 'multipart/form-data; boundary=', 'http.response.status_code': 200n, @@ -132,6 +142,8 @@ const expectedSpans = [ 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', 'url.full': 'https://js.images.cloudflare.com/transform', + 'cloudflare.binding.type': 'Images', + 'cloudflare.images.options.format': 'image/avif', 'http.request.header.content-type': 'multipart/form-data; boundary=', 'http.response.status_code': 200n, @@ -144,6 +156,8 @@ const expectedSpans = [ 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', 'url.full': 'https://js.images.cloudflare.com/transform', + 'cloudflare.binding.type': 'Images', + 'cloudflare.images.options.format': 'image/avif', 'http.request.header.content-type': 'multipart/form-data; boundary=', 'http.response.status_code': 200n, @@ -151,42 +165,78 @@ const expectedSpans = [ closed: true, }, { - name: 'images_info', + name: 'fetch', + 'network.protocol.name': 'http', + 'network.protocol.version': 'HTTP/1.1', + 'http.request.method': 'POST', + 'url.full': 'https://js.images.cloudflare.com/info', 'cloudflare.binding.type': 'Images', 'cloudflare.images.options.encoding': 'base64', - 'cloudflare.images.result.format': 'image/png', 'cloudflare.images.result.file_size': 123, - 'cloudflare.images.result.width': 123, + 'cloudflare.images.result.format': 'image/png', 'cloudflare.images.result.height': 123, + 'cloudflare.images.result.width': 123, + 'http.request.header.content-type': + 'multipart/form-data; boundary=', + 'http.response.status_code': 200n, + 'http.response.body.size': 63n, closed: true, }, { - name: 'images_info', + name: 'fetch', + 'network.protocol.name': 'http', + 'network.protocol.version': 'HTTP/1.1', + 'http.request.method': 'POST', + 'url.full': 'https://js.images.cloudflare.com/info', 'cloudflare.binding.type': 'Images', 'cloudflare.images.options.encoding': 'base64', - 'cloudflare.images.result.format': 'image/png', 'cloudflare.images.result.file_size': 123, - 'cloudflare.images.result.width': 123, + 'cloudflare.images.result.format': 'image/png', 'cloudflare.images.result.height': 123, + 'cloudflare.images.result.width': 123, + 'http.request.header.content-type': + 'multipart/form-data; boundary=', + 'http.response.status_code': 200n, + 'http.response.body.size': 63n, closed: true, }, { - name: 'images_info', + name: 'fetch', + 'network.protocol.name': 'http', + 'network.protocol.version': 'HTTP/1.1', + 'http.request.method': 'POST', + 'url.full': 'https://js.images.cloudflare.com/info', 'cloudflare.binding.type': 'Images', - 'cloudflare.images.options.encoding': 'base64', 'cloudflare.images.error.code': '123', + 'cloudflare.images.options.encoding': 'base64', 'error.type': 'ERROR 123: Bad request', + 'http.request.header.content-type': + 'multipart/form-data; boundary=', + 'http.response.status_code': 409n, + 'http.response.body.size': 22n, closed: true, }, { - name: 'images_info', + name: 'fetch', 'cloudflare.binding.type': 'Images', 'cloudflare.images.options.encoding': 'base64', 'cloudflare.images.result.format': 'image/svg+xml', + 'http.request.header.content-type': + 'multipart/form-data; boundary=', + 'http.request.method': 'POST', + 'http.response.body.size': 26n, + 'http.response.status_code': 200n, + 'network.protocol.name': 'http', + 'network.protocol.version': 'HTTP/1.1', + 'url.full': 'https://js.images.cloudflare.com/info', closed: true, }, { name: 'fetch', + 'cloudflare.binding.type': 'Images', + 'cloudflare.images.options.format': 'image/avif', + 'cloudflare.images.options.transforms': + '[{"imageIndex":0,"rotate":90},{"imageIndex":1,"rotate":180},{"drawImageIndex":1,"targetImageIndex":0},{"drawImageIndex":3,"targetImageIndex":2},{"imageIndex":2,"rotate":270},{"drawImageIndex":2,"targetImageIndex":0},{"drawImageIndex":4,"targetImageIndex":0}]', 'network.protocol.name': 'http', 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', @@ -199,6 +249,10 @@ const expectedSpans = [ }, { name: 'fetch', + 'cloudflare.binding.type': 'Images', + 'cloudflare.images.options.anim': true, + 'cloudflare.images.options.format': 'image/avif', + 'cloudflare.images.options.transforms': '[{"imageIndex":0,"rotate":90}]', 'network.protocol.name': 'http', 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', @@ -210,16 +264,25 @@ const expectedSpans = [ closed: true, }, { - name: 'images_output', + name: 'fetch', + 'network.protocol.name': 'http', + 'network.protocol.version': 'HTTP/1.1', + 'http.request.method': 'POST', + 'url.full': 'https://js.images.cloudflare.com/transform', 'cloudflare.binding.type': 'Images', - 'cloudflare.images.options.transforms': '[{"imageIndex":0,"rotate":90}]', - 'cloudflare.images.options.format': 'image/avif', 'cloudflare.images.error.code': '123', + 'cloudflare.images.options.format': 'image/avif', + 'cloudflare.images.options.transforms': '[{"imageIndex":0,"rotate":90}]', 'error.type': 'ERROR 123: Bad request', + 'http.request.header.content-type': + 'multipart/form-data; boundary=', + 'http.response.status_code': 409n, + 'http.response.body.size': 22n, closed: true, }, { - name: 'fetch', + name: 'images_output', + 'cloudflare.binding.type': 'Images', 'network.protocol.name': 'http', 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', @@ -232,6 +295,7 @@ const expectedSpans = [ }, { name: 'fetch', + 'cloudflare.binding.type': 'Images', 'network.protocol.name': 'http', 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', diff --git a/src/workerd/api/tests/actor-kv-test-tail.js b/src/workerd/api/tests/actor-kv-test-tail.js index d441559aafa..8a86b3f6fc3 100644 --- a/src/workerd/api/tests/actor-kv-test-tail.js +++ b/src/workerd/api/tests/actor-kv-test-tail.js @@ -11,6 +11,12 @@ export default testTailHandler; export const test = { async test(ctrl, env, ctx) { const expected = [ + { + name: 'durable_object_subrequest', + closed: true, + objectId: + 'aa299662980ce671dbcb09a5d7ab26ab30e45465bcd12f263f2bdd7d5edd804a', + }, { name: 'durable_object_storage_put', closed: true }, { name: 'durable_object_storage_put', closed: true }, { name: 'durable_object_storage_get', closed: true }, @@ -23,12 +29,6 @@ export const test = { { name: 'durable_object_storage_deleteAlarm', closed: true }, { name: 'durable_object_storage_transaction', closed: true }, { name: 'durable_object_storage_sync', closed: true }, - { - name: 'durable_object_subrequest', - closed: true, - objectId: - 'aa299662980ce671dbcb09a5d7ab26ab30e45465bcd12f263f2bdd7d5edd804a', - }, ]; await Promise.allSettled(invocationPromises); diff --git a/src/workerd/api/tests/r2-instrumentation-test.js b/src/workerd/api/tests/r2-instrumentation-test.js index 59caafba8b2..2030aff8789 100644 --- a/src/workerd/api/tests/r2-instrumentation-test.js +++ b/src/workerd/api/tests/r2-instrumentation-test.js @@ -192,12 +192,19 @@ export const test = { closed: true, }, { - name: 'r2_put', + name: 'r2_get', 'cloudflare.binding.type': 'r2', 'cloudflare.binding.name': 'BUCKET', - 'cloudflare.r2.operation': 'PutObject', + 'cloudflare.r2.operation': 'GetObject', 'cloudflare.r2.bucket': 'r2-test', - 'cloudflare.r2.request.key': 'throwOnInvalidEtag', + 'cloudflare.r2.request.key': 'rangeSuff', + 'cloudflare.r2.request.range.suffix': 2n, + 'cloudflare.r2.response.success': true, + 'cloudflare.r2.response.etag': 'objectEtag', + 'cloudflare.r2.response.size': 123, + 'cloudflare.r2.response.uploaded': '2024-08-27T14:00:57.918Z', + 'cloudflare.r2.response.storage_class': 'Standard', + 'cloudflare.r2.response.custom_metadata': true, closed: true, }, { @@ -210,19 +217,12 @@ export const test = { closed: true, }, { - name: 'r2_get', + name: 'r2_put', 'cloudflare.binding.type': 'r2', 'cloudflare.binding.name': 'BUCKET', - 'cloudflare.r2.operation': 'GetObject', + 'cloudflare.r2.operation': 'PutObject', 'cloudflare.r2.bucket': 'r2-test', - 'cloudflare.r2.request.key': 'rangeSuff', - 'cloudflare.r2.request.range.suffix': 2n, - 'cloudflare.r2.response.success': true, - 'cloudflare.r2.response.etag': 'objectEtag', - 'cloudflare.r2.response.size': 123, - 'cloudflare.r2.response.uploaded': '2024-08-27T14:00:57.918Z', - 'cloudflare.r2.response.storage_class': 'Standard', - 'cloudflare.r2.response.custom_metadata': true, + 'cloudflare.r2.request.key': 'throwOnInvalidEtag', closed: true, }, { diff --git a/src/workerd/api/tests/tail-worker-test.js b/src/workerd/api/tests/tail-worker-test.js index aa3429e48cb..d451fdafea6 100644 --- a/src/workerd/api/tests/tail-worker-test.js +++ b/src/workerd/api/tests/tail-worker-test.js @@ -125,7 +125,7 @@ export const test = { // tail-worker-test-jsrpc: Regression test for EW-9282 (missing onset event with // JsRpcSessionCustomEvent). This is derived from tests/js-rpc-test.js. - '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"custom"}}{"type":"spanOpen","name":"durable_object_subrequest","spanId":"0000000000000002"}{"type":"attributes","info":[{"name":"objectId","value":"af6dd8b6678e07bac992dae1bbbb3f385af19ebae7e5ea8c66d6341b246d3328"}]}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"jsRpcSession","spanId":"0000000000000003"}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"jsRpcSession","spanId":"0000000000000001"}{"type":"spanClose","outcome":"ok"}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', + '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"custom"}}{"type":"spanOpen","name":"jsRpcSession","spanId":"0000000000000001"}{"type":"spanOpen","name":"durable_object_subrequest","spanId":"0000000000000002"}{"type":"spanOpen","name":"jsRpcSession","spanId":"0000000000000003"}{"type":"attributes","info":[{"name":"objectId","value":"af6dd8b6678e07bac992dae1bbbb3f385af19ebae7e5ea8c66d6341b246d3328"}]}{"type":"spanClose","outcome":"ok"}{"type":"spanClose","outcome":"ok"}{"type":"spanClose","outcome":"ok"}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","entrypoint":"MyService","scriptTags":[],"info":{"type":"jsrpc"}}{"type":"attributes","info":[{"name":"jsrpc.method","value":"nonFunctionProperty"}]}{"type":"log","level":"log","message":["bar"]}{"type":"log","level":"log","message":["foo"]}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', '{"type":"onset","executionModel":"durableObject","spanId":"0000000000000000","entrypoint":"MyActor","scriptTags":[],"info":{"type":"jsrpc"}}{"type":"log","level":"log","message":["baz"]}{"type":"attributes","info":[{"name":"jsrpc.method","value":"functionProperty"}]}{"type":"return"}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', // Test for transient objects - getCounter returns an object with methods diff --git a/src/workerd/io/trace.c++ b/src/workerd/io/trace.c++ index a12e3bbd8a9..0952d598bd7 100644 --- a/src/workerd/io/trace.c++ +++ b/src/workerd/io/trace.c++ @@ -1491,7 +1491,6 @@ void CompleteSpan::copyTo(rpc::UserSpanData::Builder builder) const { builder.setStartTimeNs((startTime - kj::UNIX_EPOCH) / kj::NANOSECONDS); builder.setEndTimeNs((endTime - kj::UNIX_EPOCH) / kj::NANOSECONDS); builder.setSpanId(spanId); - builder.setParentSpanId(parentSpanId); auto tagsParam = builder.initTags(tags.size()); auto i = 0; @@ -1504,7 +1503,6 @@ void CompleteSpan::copyTo(rpc::UserSpanData::Builder builder) const { CompleteSpan::CompleteSpan(rpc::UserSpanData::Reader reader) : spanId(reader.getSpanId()), - parentSpanId(reader.getParentSpanId()), operationName(kj::str(reader.getOperationName())), startTime(kj::UNIX_EPOCH + reader.getStartTimeNs() * kj::NANOSECONDS), endTime(kj::UNIX_EPOCH + reader.getEndTimeNs() * kj::NANOSECONDS) { @@ -1516,14 +1514,28 @@ CompleteSpan::CompleteSpan(rpc::UserSpanData::Reader reader) } } -CompleteSpan CompleteSpan::clone() const { - CompleteSpan copy(spanId, parentSpanId, operationName.clone(), startTime, endTime); +/*CompleteSpan CompleteSpan::clone() const { + CompleteSpan copy(spanId, operationName.clone(), startTime, endTime); copy.tags.reserve(tags.size()); for (auto& tag: tags) { copy.tags.insert(tag.key.clone(), spanTagClone(tag.value)); } return copy; +}*/ + +void SpanOpenData::copyTo(rpc::SpanOpenData::Builder builder) const { + builder.setOperationName(operationName.asPtr()); + builder.setStartTimeNs((startTime - kj::UNIX_EPOCH) / kj::NANOSECONDS); + builder.setSpanId(spanId); + builder.setParentSpanId(parentSpanId); } + +SpanOpenData::SpanOpenData(rpc::SpanOpenData::Reader reader) + : spanId(reader.getSpanId()), + parentSpanId(reader.getParentSpanId()), + operationName(kj::str(reader.getOperationName())), + startTime(kj::UNIX_EPOCH + reader.getStartTimeNs() * kj::NANOSECONDS) {} + } // namespace tracing // ====================================================================================== @@ -1534,7 +1546,10 @@ SpanBuilder::SpanBuilder(kj::Maybe> observer, KJ_IF_SOME(obs, observer) { // TODO(o11y): Once we report the user tracing spanOpen event as soon as a span is created, we // should be able to fold this virtual call and just get the timestamp directly. - span.emplace(kj::mv(operationName), startTime.orDefault(obs->getTime())); + kj::Date time = startTime.orDefault([&]() { return obs->getTime(); }); + // Report spanOpen event for user tracing spans + obs->reportStart(operationName, time); + span.emplace(kj::mv(operationName), time); this->observer = kj::mv(obs); } } diff --git a/src/workerd/io/trace.capnp b/src/workerd/io/trace.capnp index d27e2cfe9fc..19d15dccc9a 100644 --- a/src/workerd/io/trace.capnp +++ b/src/workerd/io/trace.capnp @@ -42,3 +42,14 @@ struct UserSpanData { parentSpanId @5 :UInt64; } +struct SpanOpenData { + # Representation of a SpanOpen event + operationName @0 :Text; + + startTimeNs @1 :Int64; + # Nanoseconds since Unix epoch + + spanId @2 :UInt64; + parentSpanId @3 :UInt64; +} + diff --git a/src/workerd/io/trace.h b/src/workerd/io/trace.h index dfd34b06b77..98aeaf46bb6 100644 --- a/src/workerd/io/trace.h +++ b/src/workerd/io/trace.h @@ -622,8 +622,10 @@ kj::String KJ_STRINGIFY(const CustomInfo& customInfo); struct CompleteSpan { // Represents a completed span within user tracing. tracing::SpanId spanId; - tracing::SpanId parentSpanId; + // TODO(cleanup): operationName and startTime are not used in the spanClose event, but still used + // for diagnostics and a fallback timestamp in the implementation. Get rid of them once that is no + // longer needed. kj::ConstString operationName; kj::Date startTime; kj::Date endTime; @@ -632,21 +634,37 @@ struct CompleteSpan { CompleteSpan(rpc::UserSpanData::Reader reader); void copyTo(rpc::UserSpanData::Builder builder) const; - CompleteSpan clone() const; explicit CompleteSpan(tracing::SpanId spanId, - tracing::SpanId parentSpanId, kj::ConstString operationName, kj::Date startTime, kj::Date endTime, kj::HashMap tags = kj::HashMap()) : spanId(spanId), - parentSpanId(parentSpanId), operationName(kj::mv(operationName)), startTime(startTime), endTime(endTime), tags(kj::mv(tags)) {} - kj::String toString() const; +}; + +struct SpanOpenData { + // Represents the data needed for a SpanOpen event + tracing::SpanId spanId; + tracing::SpanId parentSpanId; + + kj::ConstString operationName; + kj::Date startTime; + + SpanOpenData(rpc::SpanOpenData::Reader reader); + void copyTo(rpc::SpanOpenData::Builder builder) const; + explicit SpanOpenData(tracing::SpanId spanId, + tracing::SpanId parentSpanId, + kj::ConstString operationName, + kj::Date startTime) + : spanId(spanId), + parentSpanId(parentSpanId), + operationName(kj::mv(operationName)), + startTime(startTime) {} }; // A Return mark is used to mark the point at which a span operation returned @@ -1114,6 +1132,7 @@ class SpanObserver: public kj::Refcounted { // // This should always be called exactly once per observer. virtual void report(const Span& span) = 0; + virtual void reportStart(kj::ConstString& operationName, kj::Date startTime) = 0; // The current time to be provided for the span. For user tracing, we will override this to // provide I/O time. This *requires* that spans are only created when an IOContext is available diff --git a/src/workerd/io/tracer.c++ b/src/workerd/io/tracer.c++ index 5f401db2c69..c4a2503a91f 100644 --- a/src/workerd/io/tracer.c++ +++ b/src/workerd/io/tracer.c++ @@ -136,7 +136,6 @@ void WorkerTracer::addSpan(tracing::CompleteSpan&& span) { adjustSpanTime(span); size_t spanTagsSize = 0; - size_t spanNameSize = span.operationName.size(); for (const Span::TagMap::Entry& tag: span.tags) { spanTagsSize += tag.key.size(); KJ_SWITCH_ONEOF(tag.value) { @@ -153,34 +152,48 @@ void WorkerTracer::addSpan(tracing::CompleteSpan&& span) { } } - // Span events are transmitted together for now. + // Compose span events – attributes and spanClose are transmitted together for now. auto& topLevelContext = KJ_ASSERT_NONNULL(topLevelInvocationSpanContext); - // Compose span events. For SpanOpen, an all-zero spanId is interpreted as having no spans above - // this one, thus we use the Onset spanId instead (taken from topLevelContext). We go to great - // lengths to rule out getting an all-zero spanId by chance (see SpanId::fromEntropy()), so this - // should be safe. - tracing::SpanId parentSpanId = span.parentSpanId; - if (parentSpanId == tracing::SpanId::nullId) { - parentSpanId = topLevelContext.getSpanId(); - } - // TODO(o11y): Actually report the spanOpen event at span creation time - auto spanOpenContext = tracing::InvocationSpanContext( - topLevelContext.getTraceId(), topLevelContext.getInvocationId(), parentSpanId); auto spanComponentContext = tracing::InvocationSpanContext( topLevelContext.getTraceId(), topLevelContext.getInvocationId(), span.spanId); - tailStreamWriter->report(spanOpenContext, - tracing::SpanOpen(span.spanId, span.operationName.clone()), span.startTime, spanNameSize); + // TODO: No longer needed + //tailStreamWriter->report(spanOpenContext, + // tracing::SpanOpen(span.spanId, span.operationName.clone()), span.startTime, spanNameSize); // If a span manages to exceed the size limit, truncate it by not providing span attributes. if (span.tags.size() && spanTagsSize <= MAX_TRACE_BYTES) { tracing::CustomInfo attr = KJ_MAP(tag, span.tags) { - return tracing::Attribute(tag.key.clone(), kj::mv(tag.value)); + return tracing::Attribute(kj::mv(tag.key), kj::mv(tag.value)); }; tailStreamWriter->report(spanComponentContext, kj::mv(attr), span.startTime, spanTagsSize); } tailStreamWriter->report(spanComponentContext, tracing::SpanClose(), span.endTime, 0); } +void WorkerTracer::addSpanOpen(tracing::SpanId spanId, + tracing::SpanId parentSpanId, + kj::ConstString& operationName, + kj::Date startTime) { + // This is where we'll actually encode the span. + if (pipelineLogLevel == PipelineLogLevel::NONE) { + return; + } + + auto& tailStreamWriter = KJ_UNWRAP_OR_RETURN(maybeTailStreamWriter); + auto& topLevelContext = KJ_ASSERT_NONNULL(topLevelInvocationSpanContext); + // Compose SpanOpen. An all-zero spanId is interpreted as having no spans above this one, thus we + // use the Onset spanId instead (taken from topLevelContext). We go to great lengths to rule out + // getting an all-zero spanId by chance (see SpanId::fromEntropy()), so this should be safe. + if (parentSpanId == tracing::SpanId::nullId) { + parentSpanId = topLevelContext.getSpanId(); + } + size_t spanNameSize = operationName.size(); + auto spanOpenContext = tracing::InvocationSpanContext( + topLevelContext.getTraceId(), topLevelContext.getInvocationId(), parentSpanId); + tailStreamWriter->report( + spanOpenContext, tracing::SpanOpen(spanId, operationName.clone()), startTime, spanNameSize); +} + void WorkerTracer::addException(const tracing::InvocationSpanContext& context, kj::Date timestamp, kj::String name, @@ -514,7 +527,11 @@ kj::Own UserSpanObserver::newChild() { } void UserSpanObserver::report(const Span& span) { - submitter->submitSpan(spanId, parentSpanId, span); + submitter->submitSpan(spanId, span); +} + +void UserSpanObserver::reportStart(kj::ConstString& operationName, kj::Date startTime) { + submitter->submitSpanStart(spanId, parentSpanId, operationName, startTime); } // Provide I/O time to the tracing system for user spans. diff --git a/src/workerd/io/tracer.h b/src/workerd/io/tracer.h index cc1efefc14b..cdc34cff90d 100644 --- a/src/workerd/io/tracer.h +++ b/src/workerd/io/tracer.h @@ -33,6 +33,10 @@ class BaseTracer: public kj::Refcounted { kj::String message) = 0; // Add a span. virtual void addSpan(tracing::CompleteSpan&& span) = 0; + virtual void addSpanOpen(tracing::SpanId spanId, + tracing::SpanId parentSpanId, + kj::ConstString& operationName, + kj::Date startTime) = 0; virtual void addException(const tracing::InvocationSpanContext& context, kj::Date timestamp, @@ -126,6 +130,10 @@ class WorkerTracer final: public BaseTracer { LogLevel logLevel, kj::String message) override; void addSpan(tracing::CompleteSpan&& span) override; + void addSpanOpen(tracing::SpanId spanId, + tracing::SpanId parentSpanId, + kj::ConstString& operationName, + kj::Date startTime) override; void addException(const tracing::InvocationSpanContext& context, kj::Date timestamp, kj::String name, @@ -181,7 +189,12 @@ class WorkerTracer final: public BaseTracer { class SpanSubmitter: public kj::Refcounted { public: - virtual void submitSpan(tracing::SpanId context, tracing::SpanId spanId, const Span& span) = 0; + virtual void submitSpan(tracing::SpanId spanId, const Span& span) = 0; + virtual void submitSpanStart(tracing::SpanId spanId, + tracing::SpanId parentSpanId, + kj::ConstString& operationName, + kj::Date startTime) = 0; + virtual tracing::SpanId makeSpanId() = 0; }; @@ -202,6 +215,7 @@ class UserSpanObserver final: public SpanObserver { kj::Own newChild() override; void report(const Span& span) override; + void reportStart(kj::ConstString& operationName, kj::Date startTime) override; kj::Date getTime() override; private: diff --git a/src/workerd/server/server.c++ b/src/workerd/server/server.c++ index 93fd589c9de..5e076e7482a 100644 --- a/src/workerd/server/server.c++ +++ b/src/workerd/server/server.c++ @@ -1700,11 +1700,10 @@ class RequestObserverWithTracer final: public RequestObserver, public WorkerInte class SequentialSpanSubmitter final: public SpanSubmitter { public: SequentialSpanSubmitter(kj::Own workerTracer): workerTracer(kj::mv(workerTracer)) {} - void submitSpan(tracing::SpanId spanId, tracing::SpanId parentSpanId, const Span& span) override { + void submitSpan(tracing::SpanId spanId, const Span& span) override { // We largely recreate the span here which feels inefficient, but is hard to avoid given the // mismatch between the Span type and the full span information required for OTel. - tracing::CompleteSpan span2( - spanId, parentSpanId, span.operationName.clone(), span.startTime, span.endTime); + tracing::CompleteSpan span2(spanId, span.operationName.clone(), span.startTime, span.endTime); span2.tags.reserve(span.tags.size()); for (auto& tag: span.tags) { span2.tags.insert(tag.key.clone(), spanTagClone(tag.value)); @@ -1715,6 +1714,15 @@ class SequentialSpanSubmitter final: public SpanSubmitter { workerTracer->addSpan(kj::mv(span2)); } + void submitSpanStart(tracing::SpanId spanId, + tracing::SpanId parentSpanId, + kj::ConstString& operationName, + kj::Date startTime) override { + if (isPredictableModeForTest()) { + startTime = kj::UNIX_EPOCH; + } + workerTracer->addSpanOpen(spanId, parentSpanId, operationName, startTime); + } tracing::SpanId makeSpanId() override { return tracing::SpanId(nextSpanId++); From 693b134cb044ed7673e0dec8b825541c229e2289 Mon Sep 17 00:00:00 2001 From: Felix Hanau Date: Mon, 9 Feb 2026 16:46:38 -0500 Subject: [PATCH 2/3] downstream-compatible version --- .../test/d1/d1-api-instrumentation-test.js | 62 ++++++------- .../images/images-api-instrumentation-test.js | 90 +++---------------- src/workerd/api/tests/actor-kv-test-tail.js | 12 +-- .../api/tests/r2-instrumentation-test.js | 26 +++--- src/workerd/api/tests/tail-worker-test.js | 2 +- src/workerd/io/trace.c++ | 10 +-- src/workerd/io/trace.capnp | 14 +++ src/workerd/io/trace.h | 9 +- src/workerd/io/tracer.c++ | 73 +++++++++++++-- src/workerd/io/tracer.h | 6 +- src/workerd/server/server.c++ | 34 ++++--- 11 files changed, 183 insertions(+), 155 deletions(-) diff --git a/src/cloudflare/internal/test/d1/d1-api-instrumentation-test.js b/src/cloudflare/internal/test/d1/d1-api-instrumentation-test.js index 8f8fa5b3a0d..2f3881437d8 100644 --- a/src/cloudflare/internal/test/d1/d1-api-instrumentation-test.js +++ b/src/cloudflare/internal/test/d1/d1-api-instrumentation-test.js @@ -31,6 +31,18 @@ export const test = { }; const expectedSpans = [ + { + name: 'fetch', + 'network.protocol.name': 'http', + 'network.protocol.version': 'HTTP/1.1', + 'http.request.method': 'POST', + 'url.full': 'http://d1/execute?resultsFormat=NONE', + 'http.request.header.content-type': 'application/json', + 'http.request.body.size': 231n, + 'http.response.status_code': 200n, + 'http.response.body.size': 0n, + closed: true, + }, { name: 'd1_run', 'db.system.name': 'cloudflare-d1', @@ -58,9 +70,9 @@ const expectedSpans = [ 'network.protocol.name': 'http', 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', - 'url.full': 'http://d1/execute?resultsFormat=NONE', + 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 231n, + 'http.request.body.size': 42n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -84,7 +96,7 @@ const expectedSpans = [ 'network.protocol.name': 'http', 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', - 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', + 'url.full': 'http://d1/execute?resultsFormat=NONE', 'http.request.header.content-type': 'application/json', 'http.request.body.size': 42n, 'http.response.status_code': 200n, @@ -112,7 +124,7 @@ const expectedSpans = [ 'http.request.method': 'POST', 'url.full': 'http://d1/execute?resultsFormat=NONE', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 42n, + 'http.request.body.size': 40n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -136,9 +148,9 @@ const expectedSpans = [ 'network.protocol.name': 'http', 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', - 'url.full': 'http://d1/execute?resultsFormat=NONE', + 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 40n, + 'http.request.body.size': 223n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -168,9 +180,9 @@ const expectedSpans = [ 'network.protocol.name': 'http', 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', - 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', + 'url.full': 'http://d1/execute?resultsFormat=NONE', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 223n, + 'http.request.body.size': 40n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -196,7 +208,7 @@ const expectedSpans = [ 'http.request.method': 'POST', 'url.full': 'http://d1/execute?resultsFormat=NONE', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 40n, + 'http.request.body.size': 223n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -226,9 +238,9 @@ const expectedSpans = [ 'network.protocol.name': 'http', 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', - 'url.full': 'http://d1/execute?resultsFormat=NONE', + 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 223n, + 'http.request.body.size': 31n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -332,7 +344,7 @@ const expectedSpans = [ 'http.request.method': 'POST', 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 31n, + 'http.request.body.size': 42n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -436,7 +448,7 @@ const expectedSpans = [ 'http.request.method': 'POST', 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 42n, + 'http.request.body.size': 61n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -644,7 +656,7 @@ const expectedSpans = [ 'http.request.method': 'POST', 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 61n, + 'http.request.body.size': 125n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -673,7 +685,7 @@ const expectedSpans = [ 'http.request.method': 'POST', 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 125n, + 'http.request.body.size': 79n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -803,7 +815,7 @@ const expectedSpans = [ 'http.request.method': 'POST', 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 79n, + 'http.request.body.size': 298n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -834,7 +846,7 @@ const expectedSpans = [ 'http.request.method': 'POST', 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 298n, + 'http.request.body.size': 45n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -938,7 +950,7 @@ const expectedSpans = [ 'http.request.method': 'POST', 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 45n, + 'http.request.body.size': 76n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -964,7 +976,7 @@ const expectedSpans = [ 'http.request.method': 'POST', 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 76n, + 'http.request.body.size': 117n, 'http.response.status_code': 200n, 'http.response.body.size': 0n, closed: true, @@ -984,16 +996,4 @@ const expectedSpans = [ 'cloudflare.d1.response.changes': 0, closed: true, }, - { - name: 'fetch', - 'network.protocol.name': 'http', - 'network.protocol.version': 'HTTP/1.1', - 'http.request.method': 'POST', - 'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS', - 'http.request.header.content-type': 'application/json', - 'http.request.body.size': 117n, - 'http.response.status_code': 200n, - 'http.response.body.size': 0n, - closed: true, - }, ]; diff --git a/src/cloudflare/internal/test/images/images-api-instrumentation-test.js b/src/cloudflare/internal/test/images/images-api-instrumentation-test.js index 8f73045222e..5757a1dd10b 100644 --- a/src/cloudflare/internal/test/images/images-api-instrumentation-test.js +++ b/src/cloudflare/internal/test/images/images-api-instrumentation-test.js @@ -84,8 +84,6 @@ const expectedSpans = [ 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', 'url.full': 'https://js.images.cloudflare.com/transform', - 'cloudflare.binding.type': 'Images', - 'cloudflare.images.options.format': 'image/avif', 'http.request.header.content-type': 'multipart/form-data; boundary=', 'http.response.status_code': 200n, @@ -98,8 +96,6 @@ const expectedSpans = [ 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', 'url.full': 'https://js.images.cloudflare.com/transform', - 'cloudflare.binding.type': 'Images', - 'cloudflare.images.options.format': 'image/avif', 'http.request.header.content-type': 'multipart/form-data; boundary=', 'http.response.status_code': 200n, @@ -112,9 +108,6 @@ const expectedSpans = [ 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', 'url.full': 'https://js.images.cloudflare.com/transform', - 'cloudflare.binding.type': 'Images', - 'cloudflare.images.options.format': 'image/avif', - 'cloudflare.images.options.transforms': '[{"imageIndex":0,"rotate":90}]', 'http.request.header.content-type': 'multipart/form-data; boundary=', 'http.response.status_code': 200n, @@ -127,9 +120,6 @@ const expectedSpans = [ 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', 'url.full': 'https://js.images.cloudflare.com/transform', - 'cloudflare.binding.type': 'Images', - 'cloudflare.images.options.format': 'image/avif', - 'cloudflare.images.options.transforms': '[{"imageIndex":0,"rotate":90}]', 'http.request.header.content-type': 'multipart/form-data; boundary=', 'http.response.status_code': 200n, @@ -142,8 +132,6 @@ const expectedSpans = [ 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', 'url.full': 'https://js.images.cloudflare.com/transform', - 'cloudflare.binding.type': 'Images', - 'cloudflare.images.options.format': 'image/avif', 'http.request.header.content-type': 'multipart/form-data; boundary=', 'http.response.status_code': 200n, @@ -156,8 +144,6 @@ const expectedSpans = [ 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', 'url.full': 'https://js.images.cloudflare.com/transform', - 'cloudflare.binding.type': 'Images', - 'cloudflare.images.options.format': 'image/avif', 'http.request.header.content-type': 'multipart/form-data; boundary=', 'http.response.status_code': 200n, @@ -165,78 +151,42 @@ const expectedSpans = [ closed: true, }, { - name: 'fetch', - 'network.protocol.name': 'http', - 'network.protocol.version': 'HTTP/1.1', - 'http.request.method': 'POST', - 'url.full': 'https://js.images.cloudflare.com/info', + name: 'images_info', 'cloudflare.binding.type': 'Images', 'cloudflare.images.options.encoding': 'base64', - 'cloudflare.images.result.file_size': 123, 'cloudflare.images.result.format': 'image/png', - 'cloudflare.images.result.height': 123, + 'cloudflare.images.result.file_size': 123, 'cloudflare.images.result.width': 123, - 'http.request.header.content-type': - 'multipart/form-data; boundary=', - 'http.response.status_code': 200n, - 'http.response.body.size': 63n, + 'cloudflare.images.result.height': 123, closed: true, }, { - name: 'fetch', - 'network.protocol.name': 'http', - 'network.protocol.version': 'HTTP/1.1', - 'http.request.method': 'POST', - 'url.full': 'https://js.images.cloudflare.com/info', + name: 'images_info', 'cloudflare.binding.type': 'Images', 'cloudflare.images.options.encoding': 'base64', - 'cloudflare.images.result.file_size': 123, 'cloudflare.images.result.format': 'image/png', - 'cloudflare.images.result.height': 123, + 'cloudflare.images.result.file_size': 123, 'cloudflare.images.result.width': 123, - 'http.request.header.content-type': - 'multipart/form-data; boundary=', - 'http.response.status_code': 200n, - 'http.response.body.size': 63n, + 'cloudflare.images.result.height': 123, closed: true, }, { - name: 'fetch', - 'network.protocol.name': 'http', - 'network.protocol.version': 'HTTP/1.1', - 'http.request.method': 'POST', - 'url.full': 'https://js.images.cloudflare.com/info', + name: 'images_info', 'cloudflare.binding.type': 'Images', - 'cloudflare.images.error.code': '123', 'cloudflare.images.options.encoding': 'base64', + 'cloudflare.images.error.code': '123', 'error.type': 'ERROR 123: Bad request', - 'http.request.header.content-type': - 'multipart/form-data; boundary=', - 'http.response.status_code': 409n, - 'http.response.body.size': 22n, closed: true, }, { - name: 'fetch', + name: 'images_info', 'cloudflare.binding.type': 'Images', 'cloudflare.images.options.encoding': 'base64', 'cloudflare.images.result.format': 'image/svg+xml', - 'http.request.header.content-type': - 'multipart/form-data; boundary=', - 'http.request.method': 'POST', - 'http.response.body.size': 26n, - 'http.response.status_code': 200n, - 'network.protocol.name': 'http', - 'network.protocol.version': 'HTTP/1.1', - 'url.full': 'https://js.images.cloudflare.com/info', closed: true, }, { name: 'fetch', - 'cloudflare.binding.type': 'Images', - 'cloudflare.images.options.format': 'image/avif', - 'cloudflare.images.options.transforms': - '[{"imageIndex":0,"rotate":90},{"imageIndex":1,"rotate":180},{"drawImageIndex":1,"targetImageIndex":0},{"drawImageIndex":3,"targetImageIndex":2},{"imageIndex":2,"rotate":270},{"drawImageIndex":2,"targetImageIndex":0},{"drawImageIndex":4,"targetImageIndex":0}]', 'network.protocol.name': 'http', 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', @@ -249,10 +199,6 @@ const expectedSpans = [ }, { name: 'fetch', - 'cloudflare.binding.type': 'Images', - 'cloudflare.images.options.anim': true, - 'cloudflare.images.options.format': 'image/avif', - 'cloudflare.images.options.transforms': '[{"imageIndex":0,"rotate":90}]', 'network.protocol.name': 'http', 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', @@ -264,25 +210,16 @@ const expectedSpans = [ closed: true, }, { - name: 'fetch', - 'network.protocol.name': 'http', - 'network.protocol.version': 'HTTP/1.1', - 'http.request.method': 'POST', - 'url.full': 'https://js.images.cloudflare.com/transform', + name: 'images_output', 'cloudflare.binding.type': 'Images', - 'cloudflare.images.error.code': '123', - 'cloudflare.images.options.format': 'image/avif', 'cloudflare.images.options.transforms': '[{"imageIndex":0,"rotate":90}]', + 'cloudflare.images.options.format': 'image/avif', + 'cloudflare.images.error.code': '123', 'error.type': 'ERROR 123: Bad request', - 'http.request.header.content-type': - 'multipart/form-data; boundary=', - 'http.response.status_code': 409n, - 'http.response.body.size': 22n, closed: true, }, { - name: 'images_output', - 'cloudflare.binding.type': 'Images', + name: 'fetch', 'network.protocol.name': 'http', 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', @@ -295,7 +232,6 @@ const expectedSpans = [ }, { name: 'fetch', - 'cloudflare.binding.type': 'Images', 'network.protocol.name': 'http', 'network.protocol.version': 'HTTP/1.1', 'http.request.method': 'POST', diff --git a/src/workerd/api/tests/actor-kv-test-tail.js b/src/workerd/api/tests/actor-kv-test-tail.js index 8a86b3f6fc3..d441559aafa 100644 --- a/src/workerd/api/tests/actor-kv-test-tail.js +++ b/src/workerd/api/tests/actor-kv-test-tail.js @@ -11,12 +11,6 @@ export default testTailHandler; export const test = { async test(ctrl, env, ctx) { const expected = [ - { - name: 'durable_object_subrequest', - closed: true, - objectId: - 'aa299662980ce671dbcb09a5d7ab26ab30e45465bcd12f263f2bdd7d5edd804a', - }, { name: 'durable_object_storage_put', closed: true }, { name: 'durable_object_storage_put', closed: true }, { name: 'durable_object_storage_get', closed: true }, @@ -29,6 +23,12 @@ export const test = { { name: 'durable_object_storage_deleteAlarm', closed: true }, { name: 'durable_object_storage_transaction', closed: true }, { name: 'durable_object_storage_sync', closed: true }, + { + name: 'durable_object_subrequest', + closed: true, + objectId: + 'aa299662980ce671dbcb09a5d7ab26ab30e45465bcd12f263f2bdd7d5edd804a', + }, ]; await Promise.allSettled(invocationPromises); diff --git a/src/workerd/api/tests/r2-instrumentation-test.js b/src/workerd/api/tests/r2-instrumentation-test.js index 2030aff8789..59caafba8b2 100644 --- a/src/workerd/api/tests/r2-instrumentation-test.js +++ b/src/workerd/api/tests/r2-instrumentation-test.js @@ -192,19 +192,12 @@ export const test = { closed: true, }, { - name: 'r2_get', + name: 'r2_put', 'cloudflare.binding.type': 'r2', 'cloudflare.binding.name': 'BUCKET', - 'cloudflare.r2.operation': 'GetObject', + 'cloudflare.r2.operation': 'PutObject', 'cloudflare.r2.bucket': 'r2-test', - 'cloudflare.r2.request.key': 'rangeSuff', - 'cloudflare.r2.request.range.suffix': 2n, - 'cloudflare.r2.response.success': true, - 'cloudflare.r2.response.etag': 'objectEtag', - 'cloudflare.r2.response.size': 123, - 'cloudflare.r2.response.uploaded': '2024-08-27T14:00:57.918Z', - 'cloudflare.r2.response.storage_class': 'Standard', - 'cloudflare.r2.response.custom_metadata': true, + 'cloudflare.r2.request.key': 'throwOnInvalidEtag', closed: true, }, { @@ -217,12 +210,19 @@ export const test = { closed: true, }, { - name: 'r2_put', + name: 'r2_get', 'cloudflare.binding.type': 'r2', 'cloudflare.binding.name': 'BUCKET', - 'cloudflare.r2.operation': 'PutObject', + 'cloudflare.r2.operation': 'GetObject', 'cloudflare.r2.bucket': 'r2-test', - 'cloudflare.r2.request.key': 'throwOnInvalidEtag', + 'cloudflare.r2.request.key': 'rangeSuff', + 'cloudflare.r2.request.range.suffix': 2n, + 'cloudflare.r2.response.success': true, + 'cloudflare.r2.response.etag': 'objectEtag', + 'cloudflare.r2.response.size': 123, + 'cloudflare.r2.response.uploaded': '2024-08-27T14:00:57.918Z', + 'cloudflare.r2.response.storage_class': 'Standard', + 'cloudflare.r2.response.custom_metadata': true, closed: true, }, { diff --git a/src/workerd/api/tests/tail-worker-test.js b/src/workerd/api/tests/tail-worker-test.js index d451fdafea6..aa3429e48cb 100644 --- a/src/workerd/api/tests/tail-worker-test.js +++ b/src/workerd/api/tests/tail-worker-test.js @@ -125,7 +125,7 @@ export const test = { // tail-worker-test-jsrpc: Regression test for EW-9282 (missing onset event with // JsRpcSessionCustomEvent). This is derived from tests/js-rpc-test.js. - '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"custom"}}{"type":"spanOpen","name":"jsRpcSession","spanId":"0000000000000001"}{"type":"spanOpen","name":"durable_object_subrequest","spanId":"0000000000000002"}{"type":"spanOpen","name":"jsRpcSession","spanId":"0000000000000003"}{"type":"attributes","info":[{"name":"objectId","value":"af6dd8b6678e07bac992dae1bbbb3f385af19ebae7e5ea8c66d6341b246d3328"}]}{"type":"spanClose","outcome":"ok"}{"type":"spanClose","outcome":"ok"}{"type":"spanClose","outcome":"ok"}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', + '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"custom"}}{"type":"spanOpen","name":"durable_object_subrequest","spanId":"0000000000000002"}{"type":"attributes","info":[{"name":"objectId","value":"af6dd8b6678e07bac992dae1bbbb3f385af19ebae7e5ea8c66d6341b246d3328"}]}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"jsRpcSession","spanId":"0000000000000003"}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"jsRpcSession","spanId":"0000000000000001"}{"type":"spanClose","outcome":"ok"}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","entrypoint":"MyService","scriptTags":[],"info":{"type":"jsrpc"}}{"type":"attributes","info":[{"name":"jsrpc.method","value":"nonFunctionProperty"}]}{"type":"log","level":"log","message":["bar"]}{"type":"log","level":"log","message":["foo"]}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', '{"type":"onset","executionModel":"durableObject","spanId":"0000000000000000","entrypoint":"MyActor","scriptTags":[],"info":{"type":"jsrpc"}}{"type":"log","level":"log","message":["baz"]}{"type":"attributes","info":[{"name":"jsrpc.method","value":"functionProperty"}]}{"type":"return"}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', // Test for transient objects - getCounter returns an object with methods diff --git a/src/workerd/io/trace.c++ b/src/workerd/io/trace.c++ index 0952d598bd7..241bcbfe053 100644 --- a/src/workerd/io/trace.c++ +++ b/src/workerd/io/trace.c++ @@ -1491,6 +1491,7 @@ void CompleteSpan::copyTo(rpc::UserSpanData::Builder builder) const { builder.setStartTimeNs((startTime - kj::UNIX_EPOCH) / kj::NANOSECONDS); builder.setEndTimeNs((endTime - kj::UNIX_EPOCH) / kj::NANOSECONDS); builder.setSpanId(spanId); + builder.setParentSpanId(parentSpanId); auto tagsParam = builder.initTags(tags.size()); auto i = 0; @@ -1503,6 +1504,7 @@ void CompleteSpan::copyTo(rpc::UserSpanData::Builder builder) const { CompleteSpan::CompleteSpan(rpc::UserSpanData::Reader reader) : spanId(reader.getSpanId()), + parentSpanId(reader.getParentSpanId()), operationName(kj::str(reader.getOperationName())), startTime(kj::UNIX_EPOCH + reader.getStartTimeNs() * kj::NANOSECONDS), endTime(kj::UNIX_EPOCH + reader.getEndTimeNs() * kj::NANOSECONDS) { @@ -1514,14 +1516,14 @@ CompleteSpan::CompleteSpan(rpc::UserSpanData::Reader reader) } } -/*CompleteSpan CompleteSpan::clone() const { - CompleteSpan copy(spanId, operationName.clone(), startTime, endTime); +CompleteSpan CompleteSpan::clone() const { + CompleteSpan copy(spanId, parentSpanId, operationName.clone(), startTime, endTime); copy.tags.reserve(tags.size()); for (auto& tag: tags) { copy.tags.insert(tag.key.clone(), spanTagClone(tag.value)); } return copy; -}*/ +} void SpanOpenData::copyTo(rpc::SpanOpenData::Builder builder) const { builder.setOperationName(operationName.asPtr()); @@ -1547,8 +1549,6 @@ SpanBuilder::SpanBuilder(kj::Maybe> observer, // TODO(o11y): Once we report the user tracing spanOpen event as soon as a span is created, we // should be able to fold this virtual call and just get the timestamp directly. kj::Date time = startTime.orDefault([&]() { return obs->getTime(); }); - // Report spanOpen event for user tracing spans - obs->reportStart(operationName, time); span.emplace(kj::mv(operationName), time); this->observer = kj::mv(obs); } diff --git a/src/workerd/io/trace.capnp b/src/workerd/io/trace.capnp index 19d15dccc9a..b60483a0cb3 100644 --- a/src/workerd/io/trace.capnp +++ b/src/workerd/io/trace.capnp @@ -53,3 +53,17 @@ struct SpanOpenData { parentSpanId @3 :UInt64; } +struct SpanEndData { + # Representation of an event that indicates completion of a user span. This information is + # provided to the tail worker in the Attributes and SpanClose events. + + # TODO: These can probably go? + operationName @0 :Text; + startTimeNs @1 :Int64; + # Nanoseconds since Unix epoch + endTimeNs @2 :Int64; + # Nanoseconds since Unix epoch + + tags @3 :List(Tag); + spanId @4 :UInt64; +} \ No newline at end of file diff --git a/src/workerd/io/trace.h b/src/workerd/io/trace.h index 98aeaf46bb6..22e7014bbf4 100644 --- a/src/workerd/io/trace.h +++ b/src/workerd/io/trace.h @@ -622,10 +622,8 @@ kj::String KJ_STRINGIFY(const CustomInfo& customInfo); struct CompleteSpan { // Represents a completed span within user tracing. tracing::SpanId spanId; + tracing::SpanId parentSpanId; - // TODO(cleanup): operationName and startTime are not used in the spanClose event, but still used - // for diagnostics and a fallback timestamp in the implementation. Get rid of them once that is no - // longer needed. kj::ConstString operationName; kj::Date startTime; kj::Date endTime; @@ -634,13 +632,17 @@ struct CompleteSpan { CompleteSpan(rpc::UserSpanData::Reader reader); void copyTo(rpc::UserSpanData::Builder builder) const; + // TODO: Is clone() still needed? + CompleteSpan clone() const; explicit CompleteSpan(tracing::SpanId spanId, + tracing::SpanId parentSpanId, kj::ConstString operationName, kj::Date startTime, kj::Date endTime, kj::HashMap tags = kj::HashMap()) : spanId(spanId), + parentSpanId(parentSpanId), operationName(kj::mv(operationName)), startTime(startTime), endTime(endTime), @@ -1133,6 +1135,7 @@ class SpanObserver: public kj::Refcounted { // This should always be called exactly once per observer. virtual void report(const Span& span) = 0; virtual void reportStart(kj::ConstString& operationName, kj::Date startTime) = 0; + virtual void reportEnd(const Span& span) = 0; // The current time to be provided for the span. For user tracing, we will override this to // provide I/O time. This *requires* that spans are only created when an IOContext is available diff --git a/src/workerd/io/tracer.c++ b/src/workerd/io/tracer.c++ index c4a2503a91f..42e312737c3 100644 --- a/src/workerd/io/tracer.c++ +++ b/src/workerd/io/tracer.c++ @@ -124,6 +124,9 @@ void WorkerTracer::addLog(const tracing::InvocationSpanContext& context, } void WorkerTracer::addSpan(tracing::CompleteSpan&& span) { + addSpanOpen(span.spanId, span.parentSpanId, span.operationName, span.startTime); + addSpanEnd(kj::mv(span)); +#if 0 // This is where we'll actually encode the span. if (pipelineLogLevel == PipelineLogLevel::NONE) { return; @@ -136,6 +139,7 @@ void WorkerTracer::addSpan(tracing::CompleteSpan&& span) { adjustSpanTime(span); size_t spanTagsSize = 0; + size_t spanNameSize = span.operationName.size(); for (const Span::TagMap::Entry& tag: span.tags) { spanTagsSize += tag.key.size(); KJ_SWITCH_ONEOF(tag.value) { @@ -154,12 +158,21 @@ void WorkerTracer::addSpan(tracing::CompleteSpan&& span) { // Compose span events – attributes and spanClose are transmitted together for now. auto& topLevelContext = KJ_ASSERT_NONNULL(topLevelInvocationSpanContext); - auto spanComponentContext = tracing::InvocationSpanContext( - topLevelContext.getTraceId(), topLevelContext.getInvocationId(), span.spanId); + // Compose span events. For SpanOpen, an all-zero spanId is interpreted as having no spans above + // this one, thus we use the Onset spanId instead (taken from topLevelContext). We go to great + // lengths to rule out getting an all-zero spanId by chance (see SpanId::fromEntropy()), so this + // should be safe. + tracing::SpanId parentSpanId = span.parentSpanId; + if (parentSpanId == tracing::SpanId::nullId) { + parentSpanId = topLevelContext.getSpanId(); + } - // TODO: No longer needed - //tailStreamWriter->report(spanOpenContext, - // tracing::SpanOpen(span.spanId, span.operationName.clone()), span.startTime, spanNameSize); + auto spanOpenContext = tracing::InvocationSpanContext( + topLevelContext.getTraceId(), topLevelContext.getInvocationId(), parentSpanId); + auto spanComponentContext = tracing::InvocationSpanContext( + topLevelContext.getTraceId(), topLevelContext.getInvocationId(), span.spanId); + tailStreamWriter->report(spanOpenContext, + tracing::SpanOpen(span.spanId, span.operationName.clone()), span.startTime, spanNameSize); // If a span manages to exceed the size limit, truncate it by not providing span attributes. if (span.tags.size() && spanTagsSize <= MAX_TRACE_BYTES) { tracing::CustomInfo attr = KJ_MAP(tag, span.tags) { @@ -168,6 +181,7 @@ void WorkerTracer::addSpan(tracing::CompleteSpan&& span) { tailStreamWriter->report(spanComponentContext, kj::mv(attr), span.startTime, spanTagsSize); } tailStreamWriter->report(spanComponentContext, tracing::SpanClose(), span.endTime, 0); +#endif } void WorkerTracer::addSpanOpen(tracing::SpanId spanId, @@ -194,6 +208,49 @@ void WorkerTracer::addSpanOpen(tracing::SpanId spanId, spanOpenContext, tracing::SpanOpen(spanId, operationName.clone()), startTime, spanNameSize); } +void WorkerTracer::addSpanEnd(tracing::CompleteSpan&& span) { + // This is where we'll actually encode the span. + if (pipelineLogLevel == PipelineLogLevel::NONE) { + return; + } + + // Note: spans are not available in the buffered tail worker, so we don't need an exceededSpanLimit + // variable for it and it can't cause truncation. + auto& tailStreamWriter = KJ_UNWRAP_OR_RETURN(maybeTailStreamWriter); + + adjustSpanTime(span); + + size_t spanTagsSize = 0; + for (const Span::TagMap::Entry& tag: span.tags) { + spanTagsSize += tag.key.size(); + KJ_SWITCH_ONEOF(tag.value) { + KJ_CASE_ONEOF(str, kj::ConstString) { + spanTagsSize += str.size(); + } + KJ_CASE_ONEOF(val, bool) { + spanTagsSize++; + } + // int64_t and double + KJ_CASE_ONEOF_DEFAULT { + spanTagsSize += sizeof(int64_t); + } + } + } + + // Compose span events – attributes and spanClose are transmitted together for now. + auto& topLevelContext = KJ_ASSERT_NONNULL(topLevelInvocationSpanContext); + auto spanComponentContext = tracing::InvocationSpanContext( + topLevelContext.getTraceId(), topLevelContext.getInvocationId(), span.spanId); + + if (span.tags.size() && spanTagsSize <= MAX_TRACE_BYTES) { + tracing::CustomInfo attr = KJ_MAP(tag, span.tags) { + return tracing::Attribute(kj::mv(tag.key), kj::mv(tag.value)); + }; + tailStreamWriter->report(spanComponentContext, kj::mv(attr), span.startTime, spanTagsSize); + } + tailStreamWriter->report(spanComponentContext, tracing::SpanClose(), span.endTime, 0); +} + void WorkerTracer::addException(const tracing::InvocationSpanContext& context, kj::Date timestamp, kj::String name, @@ -527,13 +584,17 @@ kj::Own UserSpanObserver::newChild() { } void UserSpanObserver::report(const Span& span) { - submitter->submitSpan(spanId, span); + submitter->submitSpan(spanId, parentSpanId, span); } void UserSpanObserver::reportStart(kj::ConstString& operationName, kj::Date startTime) { submitter->submitSpanStart(spanId, parentSpanId, operationName, startTime); } +void UserSpanObserver::reportEnd(const Span& span) { + submitter->submitSpanEnd(spanId, span); +} + // Provide I/O time to the tracing system for user spans. kj::Date UserSpanObserver::getTime() { return IoContext::current().now(); diff --git a/src/workerd/io/tracer.h b/src/workerd/io/tracer.h index cdc34cff90d..877fad8db11 100644 --- a/src/workerd/io/tracer.h +++ b/src/workerd/io/tracer.h @@ -37,6 +37,7 @@ class BaseTracer: public kj::Refcounted { tracing::SpanId parentSpanId, kj::ConstString& operationName, kj::Date startTime) = 0; + virtual void addSpanEnd(tracing::CompleteSpan&& span) = 0; virtual void addException(const tracing::InvocationSpanContext& context, kj::Date timestamp, @@ -134,6 +135,7 @@ class WorkerTracer final: public BaseTracer { tracing::SpanId parentSpanId, kj::ConstString& operationName, kj::Date startTime) override; + void addSpanEnd(tracing::CompleteSpan&& span) override; void addException(const tracing::InvocationSpanContext& context, kj::Date timestamp, kj::String name, @@ -189,11 +191,12 @@ class WorkerTracer final: public BaseTracer { class SpanSubmitter: public kj::Refcounted { public: - virtual void submitSpan(tracing::SpanId spanId, const Span& span) = 0; + virtual void submitSpan(tracing::SpanId context, tracing::SpanId spanId, const Span& span) = 0; virtual void submitSpanStart(tracing::SpanId spanId, tracing::SpanId parentSpanId, kj::ConstString& operationName, kj::Date startTime) = 0; + virtual void submitSpanEnd(tracing::SpanId spanId, const Span& span) = 0; virtual tracing::SpanId makeSpanId() = 0; }; @@ -216,6 +219,7 @@ class UserSpanObserver final: public SpanObserver { kj::Own newChild() override; void report(const Span& span) override; void reportStart(kj::ConstString& operationName, kj::Date startTime) override; + void reportEnd(const Span& span) override; kj::Date getTime() override; private: diff --git a/src/workerd/server/server.c++ b/src/workerd/server/server.c++ index 5e076e7482a..5d89b9dec2b 100644 --- a/src/workerd/server/server.c++ +++ b/src/workerd/server/server.c++ @@ -1700,10 +1700,29 @@ class RequestObserverWithTracer final: public RequestObserver, public WorkerInte class SequentialSpanSubmitter final: public SpanSubmitter { public: SequentialSpanSubmitter(kj::Own workerTracer): workerTracer(kj::mv(workerTracer)) {} - void submitSpan(tracing::SpanId spanId, const Span& span) override { + void submitSpan(tracing::SpanId spanId, tracing::SpanId parentSpanId, const Span& span) override { + // We will soon report SpanOpen and SpanClose separately. In workerd, we can already use this to + // implement submitSpan using submitSpanStart and submitSpanEnd. + kj::ConstString blah = span.operationName.clone(); + submitSpanStart(spanId, parentSpanId, blah, span.startTime); + submitSpanEnd(spanId, span); + } + + void submitSpanStart(tracing::SpanId spanId, + tracing::SpanId parentSpanId, + kj::ConstString& operationName, + kj::Date startTime) override { + if (isPredictableModeForTest()) { + startTime = kj::UNIX_EPOCH; + } + workerTracer->addSpanOpen(spanId, parentSpanId, operationName, startTime); + } + + void submitSpanEnd(tracing::SpanId spanId, const Span& span) override { // We largely recreate the span here which feels inefficient, but is hard to avoid given the // mismatch between the Span type and the full span information required for OTel. - tracing::CompleteSpan span2(spanId, span.operationName.clone(), span.startTime, span.endTime); + tracing::CompleteSpan span2( + spanId, tracing::SpanId::nullId, span.operationName.clone(), span.startTime, span.endTime); span2.tags.reserve(span.tags.size()); for (auto& tag: span.tags) { span2.tags.insert(tag.key.clone(), spanTagClone(tag.value)); @@ -1712,16 +1731,7 @@ class SequentialSpanSubmitter final: public SpanSubmitter { span2.startTime = span2.endTime = kj::UNIX_EPOCH; } - workerTracer->addSpan(kj::mv(span2)); - } - void submitSpanStart(tracing::SpanId spanId, - tracing::SpanId parentSpanId, - kj::ConstString& operationName, - kj::Date startTime) override { - if (isPredictableModeForTest()) { - startTime = kj::UNIX_EPOCH; - } - workerTracer->addSpanOpen(spanId, parentSpanId, operationName, startTime); + workerTracer->addSpanEnd(kj::mv(span2)); } tracing::SpanId makeSpanId() override { From cc5193822f2cca41c66ef4d4399dce7564b15932 Mon Sep 17 00:00:00 2001 From: Felix Hanau Date: Tue, 10 Feb 2026 09:31:41 -0500 Subject: [PATCH 3/3] Prepare getting rid of CompleteSpan --- src/workerd/io/trace.c++ | 46 ++++++++---- src/workerd/io/trace.capnp | 18 ++--- src/workerd/io/trace.h | 32 +++++++-- src/workerd/io/tracer.c++ | 132 ++++++++++++++++------------------ src/workerd/io/tracer.h | 20 +++--- src/workerd/server/server.c++ | 18 ++--- 6 files changed, 150 insertions(+), 116 deletions(-) diff --git a/src/workerd/io/trace.c++ b/src/workerd/io/trace.c++ index 241bcbfe053..779a1d80a17 100644 --- a/src/workerd/io/trace.c++ +++ b/src/workerd/io/trace.c++ @@ -1516,14 +1516,11 @@ CompleteSpan::CompleteSpan(rpc::UserSpanData::Reader reader) } } -CompleteSpan CompleteSpan::clone() const { - CompleteSpan copy(spanId, parentSpanId, operationName.clone(), startTime, endTime); - copy.tags.reserve(tags.size()); - for (auto& tag: tags) { - copy.tags.insert(tag.key.clone(), spanTagClone(tag.value)); - } - return copy; -} +SpanOpenData::SpanOpenData(rpc::SpanOpenData::Reader reader) + : spanId(reader.getSpanId()), + parentSpanId(reader.getParentSpanId()), + operationName(kj::str(reader.getOperationName())), + startTime(kj::UNIX_EPOCH + reader.getStartTimeNs() * kj::NANOSECONDS) {} void SpanOpenData::copyTo(rpc::SpanOpenData::Builder builder) const { builder.setOperationName(operationName.asPtr()); @@ -1532,12 +1529,37 @@ void SpanOpenData::copyTo(rpc::SpanOpenData::Builder builder) const { builder.setParentSpanId(parentSpanId); } -SpanOpenData::SpanOpenData(rpc::SpanOpenData::Reader reader) +SpanEndData::SpanEndData(CompleteSpan&& span) + : spanId(span.spanId), + startTime(span.startTime), + endTime(span.endTime), + tags(kj::mv(span.tags)) {} + +SpanEndData::SpanEndData(rpc::SpanEndData::Reader reader) : spanId(reader.getSpanId()), - parentSpanId(reader.getParentSpanId()), - operationName(kj::str(reader.getOperationName())), - startTime(kj::UNIX_EPOCH + reader.getStartTimeNs() * kj::NANOSECONDS) {} + startTime(kj::UNIX_EPOCH + reader.getStartTimeNs() * kj::NANOSECONDS), + endTime(kj::UNIX_EPOCH + reader.getEndTimeNs() * kj::NANOSECONDS) { + auto tagsParam = reader.getTags(); + tags.reserve(tagsParam.size()); + for (auto tagParam: tagsParam) { + tags.insert(kj::ConstString(kj::heapString(tagParam.getKey())), + deserializeTagValue(tagParam.getValue())); + } +} + +void SpanEndData::copyTo(rpc::SpanEndData::Builder builder) const { + builder.setStartTimeNs((startTime - kj::UNIX_EPOCH) / kj::NANOSECONDS); + builder.setEndTimeNs((endTime - kj::UNIX_EPOCH) / kj::NANOSECONDS); + builder.setSpanId(spanId); + auto tagsParam = builder.initTags(tags.size()); + auto i = 0; + for (auto& tag: tags) { + auto tagParam = tagsParam[i++]; + tagParam.setKey(tag.key.asPtr()); + serializeTagValue(tagParam.initValue(), tag.value); + } +} } // namespace tracing // ====================================================================================== diff --git a/src/workerd/io/trace.capnp b/src/workerd/io/trace.capnp index b60483a0cb3..3ab995523c1 100644 --- a/src/workerd/io/trace.capnp +++ b/src/workerd/io/trace.capnp @@ -43,7 +43,7 @@ struct UserSpanData { } struct SpanOpenData { - # Representation of a SpanOpen event + # Representation of a SpanOpen event, created when a user span is opened. operationName @0 :Text; startTimeNs @1 :Int64; @@ -55,15 +55,15 @@ struct SpanOpenData { struct SpanEndData { # Representation of an event that indicates completion of a user span. This information is - # provided to the tail worker in the Attributes and SpanClose events. + # provided to the streaming tail worker in the Attributes and SpanClose events. - # TODO: These can probably go? - operationName @0 :Text; - startTimeNs @1 :Int64; + # TODO(cleanup): startTimeNs is merely used as a fallback timestamp, consider obsoleting it. + startTimeNs @0 :Int64; # Nanoseconds since Unix epoch - endTimeNs @2 :Int64; + endTimeNs @1 :Int64; # Nanoseconds since Unix epoch - tags @3 :List(Tag); - spanId @4 :UInt64; -} \ No newline at end of file + # List of span attributes + tags @2 :List(Tag); + spanId @3 :UInt64; +} diff --git a/src/workerd/io/trace.h b/src/workerd/io/trace.h index 22e7014bbf4..1080b7a584c 100644 --- a/src/workerd/io/trace.h +++ b/src/workerd/io/trace.h @@ -632,8 +632,6 @@ struct CompleteSpan { CompleteSpan(rpc::UserSpanData::Reader reader); void copyTo(rpc::UserSpanData::Builder builder) const; - // TODO: Is clone() still needed? - CompleteSpan clone() const; explicit CompleteSpan(tracing::SpanId spanId, tracing::SpanId parentSpanId, kj::ConstString operationName, @@ -669,6 +667,30 @@ struct SpanOpenData { startTime(startTime) {} }; +struct SpanEndData { + // Represents the data needed when closing a span, including the Attributes and SpanClose events. + tracing::SpanId spanId; + + kj::Date startTime; + kj::Date endTime; + // Should be Span::TagMap, but we can't forward-declare that. + kj::HashMap tags; + + // Convert CompleteSpan to SpanEndData + explicit SpanEndData(CompleteSpan&& span); + SpanEndData(rpc::SpanEndData::Reader reader); + void copyTo(rpc::SpanEndData::Builder builder) const; + explicit SpanEndData(tracing::SpanId spanId, + kj::Date startTime, + kj::Date endTime, + kj::HashMap tags = + kj::HashMap()) + : spanId(spanId), + startTime(startTime), + endTime(endTime), + tags(kj::mv(tags)) {} +}; + // A Return mark is used to mark the point at which a span operation returned // a value. For instance, when a fetch subrequest response is received, or when // the fetch handler returns a Response. Importantly, it does not signal that the @@ -1132,10 +1154,10 @@ class SpanObserver: public kj::Refcounted { // Report the span data. Called at the end of the span. // - // This should always be called exactly once per observer. + // This should always be called exactly once per observer at span completion time. virtual void report(const Span& span) = 0; - virtual void reportStart(kj::ConstString& operationName, kj::Date startTime) = 0; - virtual void reportEnd(const Span& span) = 0; + // Report information about the span onset. + virtual void reportStart(kj::ConstString operationName, kj::Date startTime) = 0; // The current time to be provided for the span. For user tracing, we will override this to // provide I/O time. This *requires* that spans are only created when an IOContext is available diff --git a/src/workerd/io/tracer.c++ b/src/workerd/io/tracer.c++ index 42e312737c3..922e9b999e3 100644 --- a/src/workerd/io/tracer.c++ +++ b/src/workerd/io/tracer.c++ @@ -124,71 +124,17 @@ void WorkerTracer::addLog(const tracing::InvocationSpanContext& context, } void WorkerTracer::addSpan(tracing::CompleteSpan&& span) { - addSpanOpen(span.spanId, span.parentSpanId, span.operationName, span.startTime); - addSpanEnd(kj::mv(span)); -#if 0 - // This is where we'll actually encode the span. - if (pipelineLogLevel == PipelineLogLevel::NONE) { - return; - } - - // Note: spans are not available in the buffered tail worker, so we don't need an exceededSpanLimit - // variable for it and it can't cause truncation. - auto& tailStreamWriter = KJ_UNWRAP_OR_RETURN(maybeTailStreamWriter); - - adjustSpanTime(span); - - size_t spanTagsSize = 0; - size_t spanNameSize = span.operationName.size(); - for (const Span::TagMap::Entry& tag: span.tags) { - spanTagsSize += tag.key.size(); - KJ_SWITCH_ONEOF(tag.value) { - KJ_CASE_ONEOF(str, kj::ConstString) { - spanTagsSize += str.size(); - } - KJ_CASE_ONEOF(val, bool) { - spanTagsSize++; - } - // int64_t and double - KJ_CASE_ONEOF_DEFAULT { - spanTagsSize += sizeof(int64_t); - } - } - } - - // Compose span events – attributes and spanClose are transmitted together for now. - auto& topLevelContext = KJ_ASSERT_NONNULL(topLevelInvocationSpanContext); - // Compose span events. For SpanOpen, an all-zero spanId is interpreted as having no spans above - // this one, thus we use the Onset spanId instead (taken from topLevelContext). We go to great - // lengths to rule out getting an all-zero spanId by chance (see SpanId::fromEntropy()), so this - // should be safe. - tracing::SpanId parentSpanId = span.parentSpanId; - if (parentSpanId == tracing::SpanId::nullId) { - parentSpanId = topLevelContext.getSpanId(); - } - - auto spanOpenContext = tracing::InvocationSpanContext( - topLevelContext.getTraceId(), topLevelContext.getInvocationId(), parentSpanId); - auto spanComponentContext = tracing::InvocationSpanContext( - topLevelContext.getTraceId(), topLevelContext.getInvocationId(), span.spanId); - tailStreamWriter->report(spanOpenContext, - tracing::SpanOpen(span.spanId, span.operationName.clone()), span.startTime, spanNameSize); - // If a span manages to exceed the size limit, truncate it by not providing span attributes. - if (span.tags.size() && spanTagsSize <= MAX_TRACE_BYTES) { - tracing::CustomInfo attr = KJ_MAP(tag, span.tags) { - return tracing::Attribute(kj::mv(tag.key), kj::mv(tag.value)); - }; - tailStreamWriter->report(spanComponentContext, kj::mv(attr), span.startTime, spanTagsSize); - } - tailStreamWriter->report(spanComponentContext, tracing::SpanClose(), span.endTime, 0); -#endif + // The span information is not transmitted via RPC at this point, we can decompose the span into + // spanOpen/spanEnd. + addSpanOpen(span.spanId, span.parentSpanId, kj::mv(span.operationName), span.startTime); + tracing::SpanEndData spanEnd(kj::mv(span)); + addSpanEnd(kj::mv(spanEnd)); } void WorkerTracer::addSpanOpen(tracing::SpanId spanId, tracing::SpanId parentSpanId, - kj::ConstString& operationName, + kj::ConstString operationName, kj::Date startTime) { - // This is where we'll actually encode the span. if (pipelineLogLevel == PipelineLogLevel::NONE) { return; } @@ -205,11 +151,10 @@ void WorkerTracer::addSpanOpen(tracing::SpanId spanId, auto spanOpenContext = tracing::InvocationSpanContext( topLevelContext.getTraceId(), topLevelContext.getInvocationId(), parentSpanId); tailStreamWriter->report( - spanOpenContext, tracing::SpanOpen(spanId, operationName.clone()), startTime, spanNameSize); + spanOpenContext, tracing::SpanOpen(spanId, kj::mv(operationName)), startTime, spanNameSize); } -void WorkerTracer::addSpanEnd(tracing::CompleteSpan&& span) { - // This is where we'll actually encode the span. +void WorkerTracer::addSpanEnd(tracing::SpanEndData&& span) { if (pipelineLogLevel == PipelineLogLevel::NONE) { return; } @@ -237,7 +182,8 @@ void WorkerTracer::addSpanEnd(tracing::CompleteSpan&& span) { } } - // Compose span events – attributes and spanClose are transmitted together for now. + // Compose Attributes and SpanClose, which are available at span completion time and transmitted + // together. auto& topLevelContext = KJ_ASSERT_NONNULL(topLevelInvocationSpanContext); auto spanComponentContext = tracing::InvocationSpanContext( topLevelContext.getTraceId(), topLevelContext.getInvocationId(), span.spanId); @@ -513,6 +459,56 @@ void BaseTracer::adjustSpanTime(tracing::CompleteSpan& span) { } } +void BaseTracer::adjustSpanTime(tracing::SpanEndData& span) { + // To report I/O time, we need the IOContext to still be alive. + // weakIoContext is only none if we are tracing via RPC (in this case span times have already been + // adjusted) or if we failed to transmit an Onset event (in that case we'll get an error based on + // missing topLevelInvocationSpanContext right after). + if (weakIoContext != kj::none) { + auto& weakIoCtx = KJ_ASSERT_NONNULL(weakIoContext); + weakIoCtx->runIfAlive([this, &span](IoContext& context) { + if (context.hasCurrentIncomingRequest()) { + span.endTime = context.now(); + } else { + // We have an IOContext, but there's no current IncomingRequest. Always log a warning here, + // this should not be happening. Still report completeTime as a useful timestamp if + // available. + bool hasCompleteTime = false; + if (completeTime != kj::UNIX_EPOCH) { + span.endTime = completeTime; + hasCompleteTime = true; + } else { + span.endTime = span.startTime; + } + if (isPredictableModeForTest()) { + KJ_FAIL_ASSERT("reported span without current request", hasCompleteTime); + } else { + LOG_WARNING_PERIODICALLY("reported span without current request"); + } + } + }); + if (!weakIoCtx->isValid()) { + // This can happen if we start a customEvent from this event and cancel it after this IoContext + // gets destroyed. In that case we no longer have an IoContext available and can't get the + // current time, but the outcome timestamp will have already been set. Since the outcome + // timestamp is "late enough", simply use that. + // TODO(o11y): fix this – spans should not be outliving the IoContext. + if (completeTime != kj::UNIX_EPOCH) { + span.endTime = completeTime; + } else { + // Otherwise, we can't actually get an end timestamp that makes sense. Report a zero-duration + // span and log a warning (or fail assert in test mode). + span.endTime = span.startTime; + if (isPredictableModeForTest()) { + KJ_FAIL_ASSERT("reported span after IoContext was deallocated"); + } else { + KJ_LOG(WARNING, "reported span after IoContext was deallocated"); + } + } + } + } +} + void WorkerTracer::setReturn( kj::Maybe timestamp, kj::Maybe fetchResponseInfo) { // Match the behavior of setEventInfo(). Any resolution of the TODO comments in setEventInfo() @@ -587,12 +583,8 @@ void UserSpanObserver::report(const Span& span) { submitter->submitSpan(spanId, parentSpanId, span); } -void UserSpanObserver::reportStart(kj::ConstString& operationName, kj::Date startTime) { - submitter->submitSpanStart(spanId, parentSpanId, operationName, startTime); -} - -void UserSpanObserver::reportEnd(const Span& span) { - submitter->submitSpanEnd(spanId, span); +void UserSpanObserver::reportStart(kj::ConstString operationName, kj::Date startTime) { + submitter->submitSpanOpen(spanId, parentSpanId, kj::mv(operationName), startTime); } // Provide I/O time to the tracing system for user spans. diff --git a/src/workerd/io/tracer.h b/src/workerd/io/tracer.h index 877fad8db11..7a23036ba53 100644 --- a/src/workerd/io/tracer.h +++ b/src/workerd/io/tracer.h @@ -31,13 +31,15 @@ class BaseTracer: public kj::Refcounted { kj::Date timestamp, LogLevel logLevel, kj::String message) = 0; - // Add a span. + // Add a complete span. virtual void addSpan(tracing::CompleteSpan&& span) = 0; + // Add information about a span when it is opened, corresponds to SpanOpen event. virtual void addSpanOpen(tracing::SpanId spanId, tracing::SpanId parentSpanId, - kj::ConstString& operationName, + kj::ConstString operationName, kj::Date startTime) = 0; - virtual void addSpanEnd(tracing::CompleteSpan&& span) = 0; + // Add span events when the span is complete (Attributes and SpanClose). + virtual void addSpanEnd(tracing::SpanEndData&& span) = 0; virtual void addException(const tracing::InvocationSpanContext& context, kj::Date timestamp, @@ -95,6 +97,7 @@ class BaseTracer: public kj::Refcounted { // helper method for addSpan() implementations void adjustSpanTime(tracing::CompleteSpan& span); + void adjustSpanTime(tracing::SpanEndData& span); // Function to create the root span for the new tracing format. kj::Maybe makeUserRequestSpanFunc; @@ -133,9 +136,9 @@ class WorkerTracer final: public BaseTracer { void addSpan(tracing::CompleteSpan&& span) override; void addSpanOpen(tracing::SpanId spanId, tracing::SpanId parentSpanId, - kj::ConstString& operationName, + kj::ConstString operationName, kj::Date startTime) override; - void addSpanEnd(tracing::CompleteSpan&& span) override; + void addSpanEnd(tracing::SpanEndData&& span) override; void addException(const tracing::InvocationSpanContext& context, kj::Date timestamp, kj::String name, @@ -192,9 +195,9 @@ class WorkerTracer final: public BaseTracer { class SpanSubmitter: public kj::Refcounted { public: virtual void submitSpan(tracing::SpanId context, tracing::SpanId spanId, const Span& span) = 0; - virtual void submitSpanStart(tracing::SpanId spanId, + virtual void submitSpanOpen(tracing::SpanId spanId, tracing::SpanId parentSpanId, - kj::ConstString& operationName, + kj::ConstString operationName, kj::Date startTime) = 0; virtual void submitSpanEnd(tracing::SpanId spanId, const Span& span) = 0; @@ -218,8 +221,7 @@ class UserSpanObserver final: public SpanObserver { kj::Own newChild() override; void report(const Span& span) override; - void reportStart(kj::ConstString& operationName, kj::Date startTime) override; - void reportEnd(const Span& span) override; + void reportStart(kj::ConstString operationName, kj::Date startTime) override; kj::Date getTime() override; private: diff --git a/src/workerd/server/server.c++ b/src/workerd/server/server.c++ index 5d89b9dec2b..e959c8c009f 100644 --- a/src/workerd/server/server.c++ +++ b/src/workerd/server/server.c++ @@ -1701,28 +1701,24 @@ class SequentialSpanSubmitter final: public SpanSubmitter { public: SequentialSpanSubmitter(kj::Own workerTracer): workerTracer(kj::mv(workerTracer)) {} void submitSpan(tracing::SpanId spanId, tracing::SpanId parentSpanId, const Span& span) override { - // We will soon report SpanOpen and SpanClose separately. In workerd, we can already use this to - // implement submitSpan using submitSpanStart and submitSpanEnd. - kj::ConstString blah = span.operationName.clone(); - submitSpanStart(spanId, parentSpanId, blah, span.startTime); + // This code path is workerd-only, we can safely decompose this span into its components and + // call submitSpanOpen/submitSpanEnd instead of reimplementing them here. + submitSpanOpen(spanId, parentSpanId, span.operationName.clone(), span.startTime); submitSpanEnd(spanId, span); } - void submitSpanStart(tracing::SpanId spanId, + void submitSpanOpen(tracing::SpanId spanId, tracing::SpanId parentSpanId, - kj::ConstString& operationName, + kj::ConstString operationName, kj::Date startTime) override { if (isPredictableModeForTest()) { startTime = kj::UNIX_EPOCH; } - workerTracer->addSpanOpen(spanId, parentSpanId, operationName, startTime); + workerTracer->addSpanOpen(spanId, parentSpanId, kj::mv(operationName), startTime); } void submitSpanEnd(tracing::SpanId spanId, const Span& span) override { - // We largely recreate the span here which feels inefficient, but is hard to avoid given the - // mismatch between the Span type and the full span information required for OTel. - tracing::CompleteSpan span2( - spanId, tracing::SpanId::nullId, span.operationName.clone(), span.startTime, span.endTime); + tracing::SpanEndData span2(spanId, span.startTime, span.endTime); span2.tags.reserve(span.tags.size()); for (auto& tag: span.tags) { span2.tags.insert(tag.key.clone(), spanTagClone(tag.value));