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 779a1d80a17..6db1b5d89a1 100644 --- a/src/workerd/io/trace.c++ +++ b/src/workerd/io/trace.c++ @@ -1486,36 +1486,6 @@ TailEvent TailEvent::clone() const { sequence, cloneEvent(event)); } -void CompleteSpan::copyTo(rpc::UserSpanData::Builder builder) const { - builder.setOperationName(operationName.asPtr()); - 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; - for (auto& tag: tags) { - auto tagParam = tagsParam[i++]; - tagParam.setKey(tag.key.asPtr()); - serializeTagValue(tagParam.initValue(), tag.value); - } -} - -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) { - auto tagsParam = reader.getTags(); - tags.reserve(tagsParam.size()); - for (auto tagParam: tagsParam) { - tags.insert(kj::ConstString(kj::heapString(tagParam.getKey())), - deserializeTagValue(tagParam.getValue())); - } -} - SpanOpenData::SpanOpenData(rpc::SpanOpenData::Reader reader) : spanId(reader.getSpanId()), parentSpanId(reader.getParentSpanId()), @@ -1529,12 +1499,6 @@ void SpanOpenData::copyTo(rpc::SpanOpenData::Builder builder) const { builder.setParentSpanId(parentSpanId); } -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()), startTime(kj::UNIX_EPOCH + reader.getStartTimeNs() * kj::NANOSECONDS), @@ -1571,6 +1535,8 @@ 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.clone(), time); span.emplace(kj::mv(operationName), time); this->observer = kj::mv(obs); } diff --git a/src/workerd/io/trace.h b/src/workerd/io/trace.h index 1080b7a584c..e5944b94b35 100644 --- a/src/workerd/io/trace.h +++ b/src/workerd/io/trace.h @@ -619,34 +619,6 @@ struct Attribute final { using CustomInfo = kj::Array; kj::String KJ_STRINGIFY(const CustomInfo& customInfo); -struct CompleteSpan { - // Represents a completed span within user tracing. - tracing::SpanId spanId; - tracing::SpanId parentSpanId; - - kj::ConstString operationName; - kj::Date startTime; - kj::Date endTime; - // Should be Span::TagMap, but we can't forward-declare that. - kj::HashMap tags; - - CompleteSpan(rpc::UserSpanData::Reader reader); - void copyTo(rpc::UserSpanData::Builder builder) 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)) {} -}; - struct SpanOpenData { // Represents the data needed for a SpanOpen event tracing::SpanId spanId; @@ -676,8 +648,6 @@ struct SpanEndData { // 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, @@ -1154,7 +1124,8 @@ 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 at span completion time. + // This should always be called exactly once per observer at span completion time. For user + // tracing, this is only used to transmit the span end data. virtual void report(const Span& span) = 0; // Report information about the span onset. virtual void reportStart(kj::ConstString operationName, kj::Date startTime) = 0; diff --git a/src/workerd/io/tracer.c++ b/src/workerd/io/tracer.c++ index 922e9b999e3..e5e6ff1a52b 100644 --- a/src/workerd/io/tracer.c++ +++ b/src/workerd/io/tracer.c++ @@ -123,14 +123,6 @@ void WorkerTracer::addLog(const tracing::InvocationSpanContext& context, } } -void WorkerTracer::addSpan(tracing::CompleteSpan&& span) { - // 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, @@ -407,58 +399,6 @@ kj::Date BaseTracer::getTime() { return timestamp; } -void BaseTracer::adjustSpanTime(tracing::CompleteSpan& 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", span.operationName, hasCompleteTime); - } else { - LOG_WARNING_PERIODICALLY( - "reported span without current request", span.operationName, hasCompleteTime); - } - } - }); - 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", span.operationName); - } else { - KJ_LOG(WARNING, "reported span after IoContext was deallocated", span.operationName); - } - } - } - } -} - 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 @@ -580,7 +520,7 @@ kj::Own UserSpanObserver::newChild() { } void UserSpanObserver::report(const Span& span) { - submitter->submitSpan(spanId, parentSpanId, span); + submitter->submitSpanEnd(spanId, span); } void UserSpanObserver::reportStart(kj::ConstString operationName, kj::Date startTime) { diff --git a/src/workerd/io/tracer.h b/src/workerd/io/tracer.h index 7a23036ba53..442aaa1bb35 100644 --- a/src/workerd/io/tracer.h +++ b/src/workerd/io/tracer.h @@ -31,8 +31,6 @@ class BaseTracer: public kj::Refcounted { kj::Date timestamp, LogLevel logLevel, kj::String message) = 0; - // 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, @@ -95,8 +93,7 @@ class BaseTracer: public kj::Refcounted { // acordingly. kj::Date getTime(); - // helper method for addSpan() implementations - void adjustSpanTime(tracing::CompleteSpan& span); + // helper method for addSpanEnd() implementations void adjustSpanTime(tracing::SpanEndData& span); // Function to create the root span for the new tracing format. @@ -133,7 +130,6 @@ class WorkerTracer final: public BaseTracer { kj::Date timestamp, LogLevel logLevel, kj::String message) override; - void addSpan(tracing::CompleteSpan&& span) override; void addSpanOpen(tracing::SpanId spanId, tracing::SpanId parentSpanId, kj::ConstString operationName, diff --git a/src/workerd/server/server.c++ b/src/workerd/server/server.c++ index e959c8c009f..c189db28b4a 100644 --- a/src/workerd/server/server.c++ +++ b/src/workerd/server/server.c++ @@ -1701,10 +1701,9 @@ 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 { - // 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); + // SpanOpen and SpanClose are reported separately, this function is not used in user tracing and + // should never be called. + KJ_FAIL_ASSERT("submitSpan() should never be invoked for user tracing"); } void submitSpanOpen(tracing::SpanId spanId,