From 34fb6eb5155f65a5821510ede76afa1cd69cfb6d Mon Sep 17 00:00:00 2001 From: Luca Steeb Date: Sat, 17 Jan 2026 17:39:41 +0000 Subject: [PATCH 01/10] Add request/response body size tracking to workerd trace events Add requestSize and bodySize fields to FetchEventInfo and FetchResponseInfo so tail workers can access body size information. Request size is captured from the Content-Length header, and response size from expectedBodySize in ResponseSentTracker. Both are exposed as optional properties in JavaScript trace events. Co-Authored-By: Claude Haiku 4.5 --- src/workerd/api/trace.c++ | 29 ++++++++++++++++++++++----- src/workerd/api/trace.h | 9 ++++++++- src/workerd/io/trace.c++ | 26 ++++++++++++++++-------- src/workerd/io/trace.h | 11 +++++++--- src/workerd/io/worker-entrypoint.c++ | 23 +++++++++++++++++++-- src/workerd/io/worker-interface.capnp | 4 ++++ 6 files changed, 83 insertions(+), 19 deletions(-) diff --git a/src/workerd/api/trace.c++ b/src/workerd/api/trace.c++ index 972e2cf9cdc..f5412935ee9 100644 --- a/src/workerd/api/trace.c++ +++ b/src/workerd/api/trace.c++ @@ -127,8 +127,8 @@ kj::Own getFetchRequestDetail( }; }; - return kj::refcounted( - getCf(), getHeaders(), kj::str(eventInfo.method), kj::str(eventInfo.url)); + return kj::refcounted(getCf(), getHeaders(), + kj::str(eventInfo.method), kj::str(eventInfo.url), eventInfo.requestSize); } kj::Maybe getTraceEvent(jsg::Lock& js, const Trace& trace) { @@ -304,11 +304,13 @@ TraceItem::FetchEventInfo::FetchEventInfo(jsg::Lock& js, TraceItem::FetchEventInfo::Request::Detail::Detail(jsg::Optional> cf, kj::Array headers, kj::String method, - kj::String url) + kj::String url, + uint64_t requestSize) : cf(kj::mv(cf)), headers(kj::mv(headers)), method(kj::mv(method)), - url(kj::mv(url)) {} + url(kj::mv(url)), + requestSize(requestSize) {} jsg::Ref TraceItem::FetchEventInfo::getRequest() { return request.addRef(); @@ -361,6 +363,14 @@ kj::String TraceItem::FetchEventInfo::Request::getUrl() { return (redacted ? redactUrl(detail->url) : kj::str(detail->url)); } +jsg::Optional TraceItem::FetchEventInfo::Request::getBodySize() { + // Return null if requestSize is 0 (unknown/no body), otherwise return the size + if (detail->requestSize == 0) { + return kj::none; + } + return static_cast(detail->requestSize); +} + jsg::Ref TraceItem::FetchEventInfo::Request::getUnredacted( jsg::Lock& js) { return js.alloc(*detail, false /* details are not redacted */); @@ -368,12 +378,21 @@ jsg::Ref TraceItem::FetchEventInfo::Request: TraceItem::FetchEventInfo::Response::Response( const Trace& trace, const tracing::FetchResponseInfo& responseInfo) - : status(responseInfo.statusCode) {} + : status(responseInfo.statusCode), + bodySize(responseInfo.bodySize) {} uint16_t TraceItem::FetchEventInfo::Response::getStatus() { return status; } +jsg::Optional TraceItem::FetchEventInfo::Response::getBodySize() { + // Return null if bodySize is 0 (unknown/no body), otherwise return the size + if (bodySize == 0) { + return kj::none; + } + return static_cast(bodySize); +} + TraceItem::JsRpcEventInfo::JsRpcEventInfo( const Trace& trace, const tracing::JsRpcEventInfo& eventInfo) : rpcMethod(kj::str(eventInfo.methodName)) {} diff --git a/src/workerd/api/trace.h b/src/workerd/api/trace.h index 9cf9e6b50f0..4908ce86906 100644 --- a/src/workerd/api/trace.h +++ b/src/workerd/api/trace.h @@ -199,11 +199,13 @@ class TraceItem::FetchEventInfo::Request final: public jsg::Object { kj::Array headers; kj::String method; kj::String url; + uint64_t requestSize; Detail(jsg::Optional> cf, kj::Array headers, kj::String method, - kj::String url); + kj::String url, + uint64_t requestSize); JSG_MEMORY_INFO(Detail) { tracker.trackField("cf", cf); @@ -224,6 +226,7 @@ class TraceItem::FetchEventInfo::Request final: public jsg::Object { jsg::Dict getHeaders(jsg::Lock& js); kj::StringPtr getMethod(); kj::String getUrl(); + jsg::Optional getBodySize(); jsg::Ref getUnredacted(jsg::Lock& js); @@ -232,6 +235,7 @@ class TraceItem::FetchEventInfo::Request final: public jsg::Object { JSG_LAZY_READONLY_INSTANCE_PROPERTY(headers, getHeaders); JSG_LAZY_READONLY_INSTANCE_PROPERTY(method, getMethod); JSG_LAZY_READONLY_INSTANCE_PROPERTY(url, getUrl); + JSG_LAZY_READONLY_INSTANCE_PROPERTY(bodySize, getBodySize); JSG_METHOD(getUnredacted); } @@ -250,13 +254,16 @@ class TraceItem::FetchEventInfo::Response final: public jsg::Object { explicit Response(const Trace& trace, const tracing::FetchResponseInfo& responseInfo); uint16_t getStatus(); + jsg::Optional getBodySize(); JSG_RESOURCE_TYPE(Response) { JSG_LAZY_READONLY_INSTANCE_PROPERTY(status, getStatus); + JSG_LAZY_READONLY_INSTANCE_PROPERTY(bodySize, getBodySize); } private: uint16_t status; + uint64_t bodySize; }; class TraceItem::JsRpcEventInfo final: public jsg::Object { diff --git a/src/workerd/io/trace.c++ b/src/workerd/io/trace.c++ index 8cf6f1d9080..0a6a2093a9e 100644 --- a/src/workerd/io/trace.c++ +++ b/src/workerd/io/trace.c++ @@ -323,17 +323,22 @@ static kj::HttpMethod validateMethod(capnp::HttpMethod method) { } // namespace -FetchEventInfo::FetchEventInfo( - kj::HttpMethod method, kj::String url, kj::String cfJson, kj::Array
headers) +FetchEventInfo::FetchEventInfo(kj::HttpMethod method, + kj::String url, + kj::String cfJson, + kj::Array
headers, + uint64_t requestSize) : method(method), url(kj::mv(url)), cfJson(kj::mv(cfJson)), - headers(kj::mv(headers)) {} + headers(kj::mv(headers)), + requestSize(requestSize) {} FetchEventInfo::FetchEventInfo(rpc::Trace::FetchEventInfo::Reader reader) : method(validateMethod(reader.getMethod())), url(kj::str(reader.getUrl())), - cfJson(kj::str(reader.getCfJson())) { + cfJson(kj::str(reader.getCfJson())), + requestSize(reader.getRequestSize()) { kj::Vector
v; v.addAll(reader.getHeaders()); headers = v.releaseAsArray(); @@ -343,6 +348,7 @@ void FetchEventInfo::copyTo(rpc::Trace::FetchEventInfo::Builder builder) const { builder.setMethod(static_cast(method)); builder.setUrl(url); builder.setCfJson(cfJson); + builder.setRequestSize(requestSize); auto list = builder.initHeaders(headers.size()); for (auto i: kj::indices(headers)) { @@ -352,7 +358,7 @@ void FetchEventInfo::copyTo(rpc::Trace::FetchEventInfo::Builder builder) const { FetchEventInfo FetchEventInfo::clone() const { return FetchEventInfo( - method, kj::str(url), kj::str(cfJson), KJ_MAP(h, headers) { return h.clone(); }); + method, kj::str(url), kj::str(cfJson), KJ_MAP(h, headers) { return h.clone(); }, requestSize); } kj::String FetchEventInfo::toString() const { @@ -595,17 +601,21 @@ HibernatableWebSocketEventInfo::Type HibernatableWebSocketEventInfo::readFrom( } } -FetchResponseInfo::FetchResponseInfo(uint16_t statusCode): statusCode(statusCode) {} +FetchResponseInfo::FetchResponseInfo(uint16_t statusCode, uint64_t bodySize) + : statusCode(statusCode), + bodySize(bodySize) {} FetchResponseInfo::FetchResponseInfo(rpc::Trace::FetchResponseInfo::Reader reader) - : statusCode(reader.getStatusCode()) {} + : statusCode(reader.getStatusCode()), + bodySize(reader.getBodySize()) {} void FetchResponseInfo::copyTo(rpc::Trace::FetchResponseInfo::Builder builder) const { builder.setStatusCode(statusCode); + builder.setBodySize(bodySize); } FetchResponseInfo FetchResponseInfo::clone() const { - return FetchResponseInfo(statusCode); + return FetchResponseInfo(statusCode, bodySize); } Log::Log(kj::Date timestamp, LogLevel logLevel, kj::String message) diff --git a/src/workerd/io/trace.h b/src/workerd/io/trace.h index fdd643a70d1..e71e172b68b 100644 --- a/src/workerd/io/trace.h +++ b/src/workerd/io/trace.h @@ -309,8 +309,11 @@ kj::String KJ_STRINGIFY(const SpanContext& context); struct FetchEventInfo final { struct Header; - explicit FetchEventInfo( - kj::HttpMethod method, kj::String url, kj::String cfJson, kj::Array
headers); + explicit FetchEventInfo(kj::HttpMethod method, + kj::String url, + kj::String cfJson, + kj::Array
headers, + uint64_t requestSize = 0); FetchEventInfo(rpc::Trace::FetchEventInfo::Reader reader); FetchEventInfo(FetchEventInfo&&) = default; FetchEventInfo& operator=(FetchEventInfo&&) = default; @@ -341,6 +344,7 @@ struct FetchEventInfo final { // TODO(perf): It might be more efficient to store some sort of parsed JSON result instead? kj::String cfJson; kj::Array
headers; + uint64_t requestSize = 0; // Request body size in bytes. 0 if unknown or no body. void copyTo(rpc::Trace::FetchEventInfo::Builder builder) const; FetchEventInfo clone() const; @@ -484,13 +488,14 @@ struct CustomEventInfo final { // Describes a fetch response struct FetchResponseInfo final { - explicit FetchResponseInfo(uint16_t statusCode); + explicit FetchResponseInfo(uint16_t statusCode, uint64_t bodySize = 0); FetchResponseInfo(rpc::Trace::FetchResponseInfo::Reader reader); FetchResponseInfo(FetchResponseInfo&&) = default; FetchResponseInfo& operator=(FetchResponseInfo&&) = default; KJ_DISALLOW_COPY(FetchResponseInfo); uint16_t statusCode; + uint64_t bodySize = 0; // Response body size in bytes. 0 if unknown or no body. void copyTo(rpc::Trace::FetchResponseInfo::Builder builder) const; FetchResponseInfo clone() const; diff --git a/src/workerd/io/worker-entrypoint.c++ b/src/workerd/io/worker-entrypoint.c++ index 655b5e8a1fc..528b9aee9da 100644 --- a/src/workerd/io/worker-entrypoint.c++ +++ b/src/workerd/io/worker-entrypoint.c++ @@ -138,6 +138,9 @@ class WorkerEntrypoint::ResponseSentTracker final: public kj::HttpService::Respo uint getHttpResponseStatus() const { return httpResponseStatus; } + kj::Maybe getExpectedBodySize() const { + return expectedBodySize; + } kj::Own send(uint statusCode, kj::StringPtr statusText, @@ -147,6 +150,7 @@ class WorkerEntrypoint::ResponseSentTracker final: public kj::HttpService::Respo "workerd", "WorkerEntrypoint::ResponseSentTracker::send()", "statusCode", statusCode); sent = true; httpResponseStatus = statusCode; + this->expectedBodySize = expectedBodySize; return inner.send(statusCode, statusText, headers, expectedBodySize); } @@ -158,6 +162,7 @@ class WorkerEntrypoint::ResponseSentTracker final: public kj::HttpService::Respo private: uint httpResponseStatus = 0; + kj::Maybe expectedBodySize; kj::HttpService::Response& inner; bool sent = false; }; @@ -286,8 +291,20 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, return tracing::FetchEventInfo::Header(kj::mv(entry.key), kj::strArray(entry.value, ", ")); }; + // Extract request body size from Content-Length header if present + uint64_t requestSize = 0; + KJ_IF_SOME(contentLength, headers.get(kj::HttpHeaderId::CONTENT_LENGTH)) { + // Parse the Content-Length value. If parsing fails, we leave requestSize as 0. + char* end; + auto parsed = strtoull(contentLength.cStr(), &end, 10); + if (end != contentLength.cStr() && *end == '\0') { + requestSize = parsed; + } + } + t.setEventInfo(*incomingRequest, - tracing::FetchEventInfo(method, kj::str(url), kj::mv(cfJson), kj::mv(traceHeadersArray))); + tracing::FetchEventInfo( + method, kj::str(url), kj::mv(cfJson), kj::mv(traceHeadersArray), requestSize)); workerTracer = t; } @@ -331,7 +348,9 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, KJ_IF_SOME(t, workerTracer) { auto httpResponseStatus = wrappedResponse.getHttpResponseStatus(); if (httpResponseStatus != 0) { - t.setReturn(context.now(), tracing::FetchResponseInfo(httpResponseStatus)); + uint64_t responseBodySize = wrappedResponse.getExpectedBodySize().orDefault(0); + t.setReturn( + context.now(), tracing::FetchResponseInfo(httpResponseStatus, responseBodySize)); } else { t.setReturn(context.now()); } diff --git a/src/workerd/io/worker-interface.capnp b/src/workerd/io/worker-interface.capnp index 027bec0f0bd..f2889625583 100644 --- a/src/workerd/io/worker-interface.capnp +++ b/src/workerd/io/worker-interface.capnp @@ -108,6 +108,8 @@ struct Trace @0x8e8d911203762d34 { name @0 :Text; value @1 :Text; } + requestSize @4 :UInt64; + # Request body size in bytes. 0 if unknown or no body. } struct JsRpcEventInfo { @@ -158,6 +160,8 @@ struct Trace @0x8e8d911203762d34 { response @8 :FetchResponseInfo; struct FetchResponseInfo { statusCode @0 :UInt16; + bodySize @1 :UInt64; + # Response body size in bytes. 0 if unknown or no body. } cpuTime @10 :UInt64; From 5206364ff817806a6098e5faae17cec03979711b Mon Sep 17 00:00:00 2001 From: Luca Steeb Date: Sat, 17 Jan 2026 17:47:40 +0000 Subject: [PATCH 02/10] Address PR review comments for body size tracking - Fix Content-Length parsing to handle leading/trailing whitespace - Rename requestSize to bodySize in FetchEventInfo for naming consistency - Add precision limitation comments for uint64_t to double conversion - Add tests for FetchEventInfo bodySize serialization/deserialization - Add tests for FetchResponseInfo bodySize serialization/deserialization Co-Authored-By: Claude Opus 4.5 --- src/workerd/api/trace.c++ | 20 ++++++----- src/workerd/api/trace.h | 4 +-- src/workerd/io/trace-test.c++ | 51 +++++++++++++++++++++++++++ src/workerd/io/trace.c++ | 10 +++--- src/workerd/io/trace.h | 4 +-- src/workerd/io/worker-entrypoint.c++ | 17 +++++---- src/workerd/io/worker-interface.capnp | 2 +- 7 files changed, 84 insertions(+), 24 deletions(-) diff --git a/src/workerd/api/trace.c++ b/src/workerd/api/trace.c++ index f5412935ee9..7e971479701 100644 --- a/src/workerd/api/trace.c++ +++ b/src/workerd/api/trace.c++ @@ -127,8 +127,8 @@ kj::Own getFetchRequestDetail( }; }; - return kj::refcounted(getCf(), getHeaders(), - kj::str(eventInfo.method), kj::str(eventInfo.url), eventInfo.requestSize); + return kj::refcounted( + getCf(), getHeaders(), kj::str(eventInfo.method), kj::str(eventInfo.url), eventInfo.bodySize); } kj::Maybe getTraceEvent(jsg::Lock& js, const Trace& trace) { @@ -305,12 +305,12 @@ TraceItem::FetchEventInfo::Request::Detail::Detail(jsg::Optional headers, kj::String method, kj::String url, - uint64_t requestSize) + uint64_t bodySize) : cf(kj::mv(cf)), headers(kj::mv(headers)), method(kj::mv(method)), url(kj::mv(url)), - requestSize(requestSize) {} + bodySize(bodySize) {} jsg::Ref TraceItem::FetchEventInfo::getRequest() { return request.addRef(); @@ -364,11 +364,13 @@ kj::String TraceItem::FetchEventInfo::Request::getUrl() { } jsg::Optional TraceItem::FetchEventInfo::Request::getBodySize() { - // Return null if requestSize is 0 (unknown/no body), otherwise return the size - if (detail->requestSize == 0) { + // Return null if bodySize is 0 (unknown/no body), otherwise return the size. + // Note: Converting uint64_t to double may lose precision for sizes larger than 2^53 bytes + // (approximately 9 petabytes), though this is unlikely in practice. + if (detail->bodySize == 0) { return kj::none; } - return static_cast(detail->requestSize); + return static_cast(detail->bodySize); } jsg::Ref TraceItem::FetchEventInfo::Request::getUnredacted( @@ -386,7 +388,9 @@ uint16_t TraceItem::FetchEventInfo::Response::getStatus() { } jsg::Optional TraceItem::FetchEventInfo::Response::getBodySize() { - // Return null if bodySize is 0 (unknown/no body), otherwise return the size + // Return null if bodySize is 0 (unknown/no body), otherwise return the size. + // Note: Converting uint64_t to double may lose precision for sizes larger than 2^53 bytes + // (approximately 9 petabytes), though this is unlikely in practice. if (bodySize == 0) { return kj::none; } diff --git a/src/workerd/api/trace.h b/src/workerd/api/trace.h index 4908ce86906..061048b1a3c 100644 --- a/src/workerd/api/trace.h +++ b/src/workerd/api/trace.h @@ -199,13 +199,13 @@ class TraceItem::FetchEventInfo::Request final: public jsg::Object { kj::Array headers; kj::String method; kj::String url; - uint64_t requestSize; + uint64_t bodySize; Detail(jsg::Optional> cf, kj::Array headers, kj::String method, kj::String url, - uint64_t requestSize); + uint64_t bodySize); JSG_MEMORY_INFO(Detail) { tracker.trackField("cf", cf); diff --git a/src/workerd/io/trace-test.c++ b/src/workerd/io/trace-test.c++ index aab27b2ac23..b6c0d6954b9 100644 --- a/src/workerd/io/trace-test.c++ +++ b/src/workerd/io/trace-test.c++ @@ -176,6 +176,7 @@ KJ_TEST("Read/Write FetchEventInfo works") { KJ_ASSERT(info2.headers.size() == 1); KJ_ASSERT(info2.headers[0].name == "foo"_kj); KJ_ASSERT(info2.headers[0].value == "bar"_kj); + KJ_ASSERT(info2.bodySize == 0); // Default value FetchEventInfo info3 = info.clone(); KJ_ASSERT(info3.method == kj::HttpMethod::GET); @@ -184,6 +185,33 @@ KJ_TEST("Read/Write FetchEventInfo works") { KJ_ASSERT(info3.headers.size() == 1); KJ_ASSERT(info3.headers[0].name == "foo"_kj); KJ_ASSERT(info3.headers[0].value == "bar"_kj); + KJ_ASSERT(info3.bodySize == 0); // Default value +} + +KJ_TEST("Read/Write FetchEventInfo with bodySize works") { + capnp::MallocMessageBuilder builder; + auto fetchInfoBuilder = builder.initRoot(); + + kj::Vector headers; + headers.add(FetchEventInfo::Header(kj::str("content-type"), kj::str("application/json"))); + + uint64_t bodySize = 12345; + FetchEventInfo info(kj::HttpMethod::POST, kj::str("https://example.com/api"), kj::str("{}"), + headers.releaseAsArray(), bodySize); + + info.copyTo(fetchInfoBuilder); + + auto reader = fetchInfoBuilder.asReader(); + + FetchEventInfo info2(reader); + KJ_ASSERT(info2.method == kj::HttpMethod::POST); + KJ_ASSERT(info2.url == "https://example.com/api"_kj); + KJ_ASSERT(info2.bodySize == 12345); + + FetchEventInfo info3 = info.clone(); + KJ_ASSERT(info3.method == kj::HttpMethod::POST); + KJ_ASSERT(info3.url == "https://example.com/api"_kj); + KJ_ASSERT(info3.bodySize == 12345); } KJ_TEST("Read/Write JsRpcEventInfo works") { @@ -417,10 +445,33 @@ KJ_TEST("Read/Write Return works") { Return info2(reader); auto& fetchInfo2 = KJ_ASSERT_NONNULL(info2.info); KJ_ASSERT(fetchInfo2.statusCode == 123); + KJ_ASSERT(fetchInfo2.bodySize == 0); // Default value Return info3 = info.clone(); auto& fetchInfo3 = KJ_ASSERT_NONNULL(info3.info); KJ_ASSERT(fetchInfo3.statusCode == 123); + KJ_ASSERT(fetchInfo3.bodySize == 0); // Default value +} + +KJ_TEST("Read/Write Return with bodySize works") { + capnp::MallocMessageBuilder builder; + auto infoBuilder = builder.initRoot(); + + uint64_t bodySize = 54321; + FetchResponseInfo fetchInfo(200, bodySize); + Return info(kj::mv(fetchInfo)); + info.copyTo(infoBuilder); + + auto reader = infoBuilder.asReader(); + Return info2(reader); + auto& fetchInfo2 = KJ_ASSERT_NONNULL(info2.info); + KJ_ASSERT(fetchInfo2.statusCode == 200); + KJ_ASSERT(fetchInfo2.bodySize == 54321); + + Return info3 = info.clone(); + auto& fetchInfo3 = KJ_ASSERT_NONNULL(info3.info); + KJ_ASSERT(fetchInfo3.statusCode == 200); + KJ_ASSERT(fetchInfo3.bodySize == 54321); } KJ_TEST("Read/Write SpanOpen works") { diff --git a/src/workerd/io/trace.c++ b/src/workerd/io/trace.c++ index 0a6a2093a9e..3aeb7fb04a6 100644 --- a/src/workerd/io/trace.c++ +++ b/src/workerd/io/trace.c++ @@ -327,18 +327,18 @@ FetchEventInfo::FetchEventInfo(kj::HttpMethod method, kj::String url, kj::String cfJson, kj::Array
headers, - uint64_t requestSize) + uint64_t bodySize) : method(method), url(kj::mv(url)), cfJson(kj::mv(cfJson)), headers(kj::mv(headers)), - requestSize(requestSize) {} + bodySize(bodySize) {} FetchEventInfo::FetchEventInfo(rpc::Trace::FetchEventInfo::Reader reader) : method(validateMethod(reader.getMethod())), url(kj::str(reader.getUrl())), cfJson(kj::str(reader.getCfJson())), - requestSize(reader.getRequestSize()) { + bodySize(reader.getBodySize()) { kj::Vector
v; v.addAll(reader.getHeaders()); headers = v.releaseAsArray(); @@ -348,7 +348,7 @@ void FetchEventInfo::copyTo(rpc::Trace::FetchEventInfo::Builder builder) const { builder.setMethod(static_cast(method)); builder.setUrl(url); builder.setCfJson(cfJson); - builder.setRequestSize(requestSize); + builder.setBodySize(bodySize); auto list = builder.initHeaders(headers.size()); for (auto i: kj::indices(headers)) { @@ -358,7 +358,7 @@ void FetchEventInfo::copyTo(rpc::Trace::FetchEventInfo::Builder builder) const { FetchEventInfo FetchEventInfo::clone() const { return FetchEventInfo( - method, kj::str(url), kj::str(cfJson), KJ_MAP(h, headers) { return h.clone(); }, requestSize); + method, kj::str(url), kj::str(cfJson), KJ_MAP(h, headers) { return h.clone(); }, bodySize); } kj::String FetchEventInfo::toString() const { diff --git a/src/workerd/io/trace.h b/src/workerd/io/trace.h index e71e172b68b..ca011f15f2c 100644 --- a/src/workerd/io/trace.h +++ b/src/workerd/io/trace.h @@ -313,7 +313,7 @@ struct FetchEventInfo final { kj::String url, kj::String cfJson, kj::Array
headers, - uint64_t requestSize = 0); + uint64_t bodySize = 0); FetchEventInfo(rpc::Trace::FetchEventInfo::Reader reader); FetchEventInfo(FetchEventInfo&&) = default; FetchEventInfo& operator=(FetchEventInfo&&) = default; @@ -344,7 +344,7 @@ struct FetchEventInfo final { // TODO(perf): It might be more efficient to store some sort of parsed JSON result instead? kj::String cfJson; kj::Array
headers; - uint64_t requestSize = 0; // Request body size in bytes. 0 if unknown or no body. + uint64_t bodySize = 0; // Request body size in bytes. 0 if unknown or no body. void copyTo(rpc::Trace::FetchEventInfo::Builder builder) const; FetchEventInfo clone() const; diff --git a/src/workerd/io/worker-entrypoint.c++ b/src/workerd/io/worker-entrypoint.c++ index 528b9aee9da..a320ae9e012 100644 --- a/src/workerd/io/worker-entrypoint.c++ +++ b/src/workerd/io/worker-entrypoint.c++ @@ -292,19 +292,24 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, }; // Extract request body size from Content-Length header if present - uint64_t requestSize = 0; + uint64_t bodySize = 0; KJ_IF_SOME(contentLength, headers.get(kj::HttpHeaderId::CONTENT_LENGTH)) { - // Parse the Content-Length value. If parsing fails, we leave requestSize as 0. + // Parse the Content-Length value. Skip leading whitespace first since HTTP headers + // can include leading/trailing whitespace. If parsing fails, we leave bodySize as 0. + const char* ptr = contentLength.cStr(); + while (*ptr == ' ' || *ptr == '\t') ptr++; // Skip leading whitespace char* end; - auto parsed = strtoull(contentLength.cStr(), &end, 10); - if (end != contentLength.cStr() && *end == '\0') { - requestSize = parsed; + auto parsed = strtoull(ptr, &end, 10); + // Check that we parsed something and only trailing whitespace remains + while (*end == ' ' || *end == '\t') end++; // Skip trailing whitespace + if (end != ptr && *end == '\0') { + bodySize = parsed; } } t.setEventInfo(*incomingRequest, tracing::FetchEventInfo( - method, kj::str(url), kj::mv(cfJson), kj::mv(traceHeadersArray), requestSize)); + method, kj::str(url), kj::mv(cfJson), kj::mv(traceHeadersArray), bodySize)); workerTracer = t; } diff --git a/src/workerd/io/worker-interface.capnp b/src/workerd/io/worker-interface.capnp index f2889625583..bcb11ce85f9 100644 --- a/src/workerd/io/worker-interface.capnp +++ b/src/workerd/io/worker-interface.capnp @@ -108,7 +108,7 @@ struct Trace @0x8e8d911203762d34 { name @0 :Text; value @1 :Text; } - requestSize @4 :UInt64; + bodySize @4 :UInt64; # Request body size in bytes. 0 if unknown or no body. } From 12ec572cd6719e8df593a838a19be0aae13a239e Mon Sep 17 00:00:00 2001 From: Luca Steeb Date: Sat, 17 Jan 2026 19:23:44 +0000 Subject: [PATCH 03/10] Defer body size reporting until after response streaming completes The previous implementation captured body size from Content-Length headers before streaming started. This is incorrect because: - Content-Length may not be present (chunked encoding) - Actual bytes streamed may differ from declared length - True body size is only known after streaming completes This change: - Adds ByteCountingOutputStream wrapper to track actual bytes written - Wraps response output stream in ResponseSentTracker::send() - Defers setReturn() call until proxyTask completes - Reports actual byte count instead of Content-Length header value The byte counter uses std::atomic for thread safety since proxyTask may run on a different thread than the original request handler. Co-Authored-By: Claude Opus 4.5 --- src/workerd/api/streams/writable-sink.h | 41 ++++++++ src/workerd/io/worker-entrypoint.c++ | 129 +++++++++++++++++++++--- 2 files changed, 157 insertions(+), 13 deletions(-) diff --git a/src/workerd/api/streams/writable-sink.h b/src/workerd/api/streams/writable-sink.h index b518009c1e7..15a4f404764 100644 --- a/src/workerd/api/streams/writable-sink.h +++ b/src/workerd/api/streams/writable-sink.h @@ -4,6 +4,8 @@ #include +#include + namespace kj { class AsyncOutputStream; } @@ -138,5 +140,44 @@ kj::Own newEncodedWritableSink( kj::Own newIoContextWrappedWritableSink( IoContext& ioContext, kj::Own inner); +// A refcounted byte counter that can be shared between a stream wrapper and +// the code that needs to read the final byte count after streaming completes. +// Using atomic for thread safety since proxyTask may run on different thread. +struct ByteCounter: public kj::Refcounted { + std::atomic bytesWritten{0}; + + void add(size_t bytes) { + bytesWritten.fetch_add(bytes, std::memory_order_relaxed); + } + + uint64_t get() const { + return bytesWritten.load(std::memory_order_relaxed); + } +}; + +// A WritableSink wrapper that counts the total bytes written to the underlying sink. +// This is used to track actual response body sizes for trace events. +class ByteCountingWritableSink final: public WritableSinkWrapper { + public: + ByteCountingWritableSink(kj::Own inner, kj::Own counter) + : WritableSinkWrapper(kj::mv(inner)), + counter(kj::mv(counter)) {} + + kj::Promise write(kj::ArrayPtr buffer) override { + counter->add(buffer.size()); + return WritableSinkWrapper::write(buffer); + } + + kj::Promise write(kj::ArrayPtr> pieces) override { + for (const auto& piece: pieces) { + counter->add(piece.size()); + } + return WritableSinkWrapper::write(pieces); + } + + private: + kj::Own counter; +}; + } // namespace api::streams } // namespace workerd diff --git a/src/workerd/io/worker-entrypoint.c++ b/src/workerd/io/worker-entrypoint.c++ index a320ae9e012..2d531e0dd59 100644 --- a/src/workerd/io/worker-entrypoint.c++ +++ b/src/workerd/io/worker-entrypoint.c++ @@ -22,9 +22,15 @@ #include #include +#include + namespace workerd { namespace { + +// Forward declaration for deferred body size tracking +struct ResponseBodyByteCounter; + // Wrapper around a Worker that handles receiving a new event from the outside. In particular, // this handles: // - Creating a IoContext and making it current. @@ -98,6 +104,11 @@ class WorkerEntrypoint final: public WorkerInterface { bool loggedExceptionEarlier = false; kj::Maybe> abortController; + // For deferred trace reporting after response body streaming completes + kj::Maybe> traceByteCounter; + kj::Maybe deferredWorkerTracer; + uint deferredHttpResponseStatus = 0; + void init(kj::Own worker, kj::Maybe> actor, kj::Own limitEnforcer, @@ -125,8 +136,52 @@ class WorkerEntrypoint final: public WorkerInterface { kj::Maybe cfBlobJson); }; +// A refcounted byte counter that can be shared between the stream wrapper and +// the code that needs to read the final byte count after streaming completes. +struct ResponseBodyByteCounter: public kj::Refcounted { + std::atomic bytesWritten{0}; + + void add(size_t bytes) { + bytesWritten.fetch_add(bytes, std::memory_order_relaxed); + } + + uint64_t get() const { + return bytesWritten.load(std::memory_order_relaxed); + } +}; + +// Wraps an AsyncOutputStream to count bytes written. Used to track actual +// response body size for trace events (as opposed to Content-Length header). +class ByteCountingOutputStream final: public kj::AsyncOutputStream { + public: + ByteCountingOutputStream( + kj::Own inner, kj::Own counter) + : inner(kj::mv(inner)), + counter(kj::mv(counter)) {} + + kj::Promise write(kj::ArrayPtr buffer) override { + counter->add(buffer.size()); + return inner->write(buffer); + } + + kj::Promise write(kj::ArrayPtr> pieces) override { + for (const auto& piece: pieces) { + counter->add(piece.size()); + } + return inner->write(pieces); + } + + kj::Promise whenWriteDisconnected() override { + return inner->whenWriteDisconnected(); + } + + private: + kj::Own inner; + kj::Own counter; +}; + // Simple wrapper around `HttpService::Response` to let us know if the response was sent -// already. +// already. Also wraps the output stream with byte counting for trace events. class WorkerEntrypoint::ResponseSentTracker final: public kj::HttpService::Response { public: ResponseSentTracker(kj::HttpService::Response& inner): inner(inner) {} @@ -142,6 +197,12 @@ class WorkerEntrypoint::ResponseSentTracker final: public kj::HttpService::Respo return expectedBodySize; } + // Returns a reference to the byte counter for deferred access after streaming. + // The returned ownership should be held until after proxyTask completes. + kj::Maybe> takeByteCounter() { + return kj::mv(byteCounter); + } + kj::Own send(uint statusCode, kj::StringPtr statusText, const kj::HttpHeaders& headers, @@ -151,7 +212,13 @@ class WorkerEntrypoint::ResponseSentTracker final: public kj::HttpService::Respo sent = true; httpResponseStatus = statusCode; this->expectedBodySize = expectedBodySize; - return inner.send(statusCode, statusText, headers, expectedBodySize); + + auto stream = inner.send(statusCode, statusText, headers, expectedBodySize); + + // Wrap with byte counting for trace events + auto counter = kj::refcounted(); + byteCounter = kj::addRef(*counter); + return kj::heap(kj::mv(stream), kj::mv(counter)); } kj::Own acceptWebSocket(const kj::HttpHeaders& headers) override { @@ -163,6 +230,7 @@ class WorkerEntrypoint::ResponseSentTracker final: public kj::HttpService::Respo private: uint httpResponseStatus = 0; kj::Maybe expectedBodySize; + kj::Maybe> byteCounter; kj::HttpService::Response& inner; bool sent = false; }; @@ -291,7 +359,10 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, return tracing::FetchEventInfo::Header(kj::mv(entry.key), kj::strArray(entry.value, ", ")); }; - // Extract request body size from Content-Length header if present + // Extract request body size from Content-Length header if present. + // TODO(someday): Track actual bytes consumed from request body stream instead of + // relying on Content-Length header. This is less critical than response body size + // since request bodies typically have accurate Content-Length. uint64_t bodySize = 0; KJ_IF_SOME(contentLength, headers.get(kj::HttpHeaderId::CONTENT_LENGTH)) { // Parse the Content-Length value. Skip leading whitespace first since HTTP headers @@ -345,20 +416,19 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, cfBlobJson, lock, lock.getExportedHandler(entrypointName, kj::mv(props), context.getActor()), kj::mv(signal)); }) - .then([this, &context, &wrappedResponse = *wrappedResponse, workerTracer]( + .then([this, &wrappedResponse = *wrappedResponse, workerTracer]( api::DeferredProxy deferredProxy) { TRACE_EVENT("workerd", "WorkerEntrypoint::request() deferred proxy step", PERFETTO_FLOW_FROM_POINTER(this)); proxyTask = kj::mv(deferredProxy.proxyTask); + + // Save info for deferred trace reporting after response body streaming completes. + // We defer setReturn() until proxyTask completes so we can report actual body size + // instead of the expected size from Content-Length header. KJ_IF_SOME(t, workerTracer) { - auto httpResponseStatus = wrappedResponse.getHttpResponseStatus(); - if (httpResponseStatus != 0) { - uint64_t responseBodySize = wrappedResponse.getExpectedBodySize().orDefault(0); - t.setReturn( - context.now(), tracing::FetchResponseInfo(httpResponseStatus, responseBodySize)); - } else { - t.setReturn(context.now()); - } + deferredWorkerTracer = t; + deferredHttpResponseStatus = wrappedResponse.getHttpResponseStatus(); + traceByteCounter = wrappedResponse.takeByteCounter(); } }) .catch_([this, &context](kj::Exception&& exception) mutable -> kj::Promise { @@ -413,11 +483,44 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, // Now that the IoContext is dropped (unless it had waitUntil()s), we can finish proxying // without pinning it or the isolate into memory. KJ_IF_SOME(p, proxyTask) { - return p.catch_([metrics = kj::mv(metrics)](kj::Exception&& e) mutable -> kj::Promise { + return p + .then([this]() { + // proxyTask completed successfully - report actual body size to tracer. + // We deferred setReturn() to here so we can report actual bytes written + // instead of the Content-Length header value. + KJ_IF_SOME(t, deferredWorkerTracer) { + if (deferredHttpResponseStatus != 0) { + uint64_t actualBodySize = 0; + KJ_IF_SOME(counter, traceByteCounter) { + actualBodySize = counter->get(); + } + t.setReturn( + kj::none, tracing::FetchResponseInfo(deferredHttpResponseStatus, actualBodySize)); + } else { + t.setReturn(kj::none); + } + } + // Clean up deferred trace state + deferredWorkerTracer = kj::none; + traceByteCounter = kj::none; + }).catch_([this, metrics = kj::mv(metrics)](kj::Exception&& e) mutable -> kj::Promise { + // Clean up deferred trace state on failure too + deferredWorkerTracer = kj::none; + traceByteCounter = kj::none; metrics->reportFailure(e, RequestObserver::FailureSource::DEFERRED_PROXY); return kj::mv(e); }); } else { + // No proxyTask means no streaming body - report trace now if we have deferred info + KJ_IF_SOME(t, deferredWorkerTracer) { + if (deferredHttpResponseStatus != 0) { + t.setReturn(kj::none, tracing::FetchResponseInfo(deferredHttpResponseStatus, 0)); + } else { + t.setReturn(kj::none); + } + } + deferredWorkerTracer = kj::none; + traceByteCounter = kj::none; return kj::READY_NOW; } }) From d331f00dac3379061698c9467a64763963573727 Mon Sep 17 00:00:00 2001 From: Luca Steeb Date: Sat, 17 Jan 2026 19:37:29 +0000 Subject: [PATCH 04/10] Add bodySize serialization to streaming tail worker events - Add BODYSIZE_STR constant to trace-stream.c++ - Update ToJs(FetchEventInfo) to include bodySize for request body - Update ToJs(FetchResponseInfo) to include bodySize for response body - Update tail-worker-test.js expected output with bodySize values Note: Integration tests (tail-worker-test@, http-test@) are failing with pre-existing segfaults unrelated to these changes. Co-Authored-By: Claude Opus 4.5 --- src/workerd/api/tests/tail-worker-test.js | 4 ++-- src/workerd/io/trace-stream.c++ | 17 ++++++++++++++--- 2 files changed, 16 insertions(+), 5 deletions(-) diff --git a/src/workerd/api/tests/tail-worker-test.js b/src/workerd/api/tests/tail-worker-test.js index 752a0fc1d8f..eb0bfa5d54f 100644 --- a/src/workerd/api/tests/tail-worker-test.js +++ b/src/workerd/api/tests/tail-worker-test.js @@ -86,8 +86,8 @@ export const test = { // http-test.js: fetch and scheduled events get reported correctly. // First event is emitted by the test() event, which allows us to get some coverage for span tracing. '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"custom"}}{"type":"spanOpen","name":"fetch","spanId":"0000000000000001"}{"type":"attributes","info":[{"name":"network.protocol.name","value":"http"},{"name":"network.protocol.version","value":"HTTP/1.1"},{"name":"http.request.method","value":"POST"},{"name":"url.full","value":"http://placeholder/body-length"},{"name":"http.request.body.size","value":"3"},{"name":"http.response.status_code","value":"200"},{"name":"http.response.body.size","value":"22"}]}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"fetch","spanId":"0000000000000002"}{"type":"attributes","info":[{"name":"network.protocol.name","value":"http"},{"name":"network.protocol.version","value":"HTTP/1.1"},{"name":"http.request.method","value":"POST"},{"name":"url.full","value":"http://placeholder/body-length"},{"name":"http.response.status_code","value":"200"},{"name":"http.response.body.size","value":"31"}]}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"scheduled","spanId":"0000000000000003"}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"scheduled","spanId":"0000000000000004"}{"type":"spanClose","outcome":"ok"}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', - '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"POST","url":"http://placeholder/body-length","headers":[]}}{"type":"return","info":{"type":"fetch","statusCode":200}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', - '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"POST","url":"http://placeholder/body-length","headers":[]}}{"type":"return","info":{"type":"fetch","statusCode":200}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', + '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"POST","url":"http://placeholder/body-length","headers":[],"bodySize":3}}{"type":"return","info":{"type":"fetch","statusCode":200,"bodySize":22}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', + '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"POST","url":"http://placeholder/body-length","headers":[]}}{"type":"return","info":{"type":"fetch","statusCode":200,"bodySize":31}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"scheduled","scheduledTime":"1970-01-01T00:00:00.000Z","cron":""}}{"type":"return"}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"scheduled","scheduledTime":"1970-01-01T00:00:00.000Z","cron":"* * * * 30"}}{"type":"return"}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","entrypoint":"cacheMode","scriptTags":[],"info":{"type":"custom"}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', diff --git a/src/workerd/io/trace-stream.c++ b/src/workerd/io/trace-stream.c++ index 8c6045e7c3b..0ee657fcf75 100644 --- a/src/workerd/io/trace-stream.c++ +++ b/src/workerd/io/trace-stream.c++ @@ -19,6 +19,7 @@ namespace { V(ALARM, "alarm") \ V(ATTRIBUTES, "attributes") \ V(BATCHSIZE, "batchSize") \ + V(BODYSIZE, "bodySize") \ V(CANCELED, "canceled") \ V(CHANNEL, "channel") \ V(CFJSON, "cfJson") \ @@ -175,9 +176,14 @@ jsg::JsValue ToJs(jsg::Lock& js, kj::ArrayPtr attributes, Strin } jsg::JsValue ToJs(jsg::Lock& js, const FetchResponseInfo& info, StringCache& cache) { - static const kj::StringPtr keys[] = {TYPE_STR, STATUSCODE_STR}; - jsg::JsValue values[] = {cache.get(js, FETCH_STR), js.num(info.statusCode)}; - return js.obj(kj::arrayPtr(keys), kj::arrayPtr(values)); + auto obj = js.obj(); + obj.set(js, TYPE_STR, cache.get(js, FETCH_STR)); + obj.set(js, STATUSCODE_STR, js.num(info.statusCode)); + // Only include bodySize if it's non-zero (indicating actual body size was tracked) + if (info.bodySize > 0) { + obj.set(js, BODYSIZE_STR, js.num(static_cast(info.bodySize))); + } + return obj; } jsg::JsValue ToJs(jsg::Lock& js, const FetchEventInfo& info, StringCache& cache) { @@ -200,6 +206,11 @@ jsg::JsValue ToJs(jsg::Lock& js, const FetchEventInfo& info, StringCache& cache) js.arr(info.headers.asPtr(), [&cache, &ToJs](jsg::Lock& js, const auto& header) { return ToJs(js, header, cache); })); + // Only include bodySize if it's non-zero (indicating request body size was tracked) + if (info.bodySize > 0) { + obj.set(js, BODYSIZE_STR, js.num(static_cast(info.bodySize))); + } + return obj; } From 38f0b4089d6cbed510f4759a846e901cdf0a7bab Mon Sep 17 00:00:00 2001 From: Luca Steeb Date: Wed, 21 Jan 2026 13:00:22 +0000 Subject: [PATCH 05/10] Address PR review comments for body size tracking Changes based on @jasnell's review: - Remove unused ByteCountingWritableSink from writable-sink.h - Only enable byte counting when tracing is enabled to avoid performance overhead for workers without tail workers - Remove std::atomic since kj I/O objects are single-threaded - Use kj::StringPtr::tryParseAs() instead of custom strtoull parsing for Content-Length - Fix takeByteCounter() comment to indicate it transfers ownership - Add comment explaining why tryPumpFrom() is not overridden (need to count bytes, so use non-optimized write path) Note on bodySize semantics: 0 is used for both "no Content-Length" and "Content-Length: 0". While these are semantically different in HTTP, for trace events both indicate no/empty body data which is acceptable for monitoring purposes. Co-Authored-By: Claude Opus 4.5 --- src/workerd/api/streams/writable-sink.h | 41 ------------------- src/workerd/io/worker-entrypoint.c++ | 54 +++++++++++++++---------- 2 files changed, 32 insertions(+), 63 deletions(-) diff --git a/src/workerd/api/streams/writable-sink.h b/src/workerd/api/streams/writable-sink.h index 15a4f404764..b518009c1e7 100644 --- a/src/workerd/api/streams/writable-sink.h +++ b/src/workerd/api/streams/writable-sink.h @@ -4,8 +4,6 @@ #include -#include - namespace kj { class AsyncOutputStream; } @@ -140,44 +138,5 @@ kj::Own newEncodedWritableSink( kj::Own newIoContextWrappedWritableSink( IoContext& ioContext, kj::Own inner); -// A refcounted byte counter that can be shared between a stream wrapper and -// the code that needs to read the final byte count after streaming completes. -// Using atomic for thread safety since proxyTask may run on different thread. -struct ByteCounter: public kj::Refcounted { - std::atomic bytesWritten{0}; - - void add(size_t bytes) { - bytesWritten.fetch_add(bytes, std::memory_order_relaxed); - } - - uint64_t get() const { - return bytesWritten.load(std::memory_order_relaxed); - } -}; - -// A WritableSink wrapper that counts the total bytes written to the underlying sink. -// This is used to track actual response body sizes for trace events. -class ByteCountingWritableSink final: public WritableSinkWrapper { - public: - ByteCountingWritableSink(kj::Own inner, kj::Own counter) - : WritableSinkWrapper(kj::mv(inner)), - counter(kj::mv(counter)) {} - - kj::Promise write(kj::ArrayPtr buffer) override { - counter->add(buffer.size()); - return WritableSinkWrapper::write(buffer); - } - - kj::Promise write(kj::ArrayPtr> pieces) override { - for (const auto& piece: pieces) { - counter->add(piece.size()); - } - return WritableSinkWrapper::write(pieces); - } - - private: - kj::Own counter; -}; - } // namespace api::streams } // namespace workerd diff --git a/src/workerd/io/worker-entrypoint.c++ b/src/workerd/io/worker-entrypoint.c++ index 2d531e0dd59..7e212d53ef8 100644 --- a/src/workerd/io/worker-entrypoint.c++ +++ b/src/workerd/io/worker-entrypoint.c++ @@ -22,8 +22,6 @@ #include #include -#include - namespace workerd { namespace { @@ -138,20 +136,23 @@ class WorkerEntrypoint final: public WorkerInterface { // A refcounted byte counter that can be shared between the stream wrapper and // the code that needs to read the final byte count after streaming completes. +// Note: kj I/O objects are single-threaded, so no atomic operations are needed. struct ResponseBodyByteCounter: public kj::Refcounted { - std::atomic bytesWritten{0}; + uint64_t bytesWritten = 0; void add(size_t bytes) { - bytesWritten.fetch_add(bytes, std::memory_order_relaxed); + bytesWritten += bytes; } uint64_t get() const { - return bytesWritten.load(std::memory_order_relaxed); + return bytesWritten; } }; // Wraps an AsyncOutputStream to count bytes written. Used to track actual // response body size for trace events (as opposed to Content-Length header). +// Note: This wrapper intentionally doesn't implement tryPumpFrom() optimization +// to ensure all bytes flow through write() where we can count them. class ByteCountingOutputStream final: public kj::AsyncOutputStream { public: ByteCountingOutputStream( @@ -175,16 +176,23 @@ class ByteCountingOutputStream final: public kj::AsyncOutputStream { return inner->whenWriteDisconnected(); } + // We intentionally don't override tryPumpFrom() because we need to count bytes + // and the optimized pump paths don't give us access to the byte count. + // Returning kj::none causes fallback to the regular write() path. + private: kj::Own inner; kj::Own counter; }; // Simple wrapper around `HttpService::Response` to let us know if the response was sent -// already. Also wraps the output stream with byte counting for trace events. +// already. Also optionally wraps the output stream with byte counting for trace events +// when tracing is enabled. class WorkerEntrypoint::ResponseSentTracker final: public kj::HttpService::Response { public: - ResponseSentTracker(kj::HttpService::Response& inner): inner(inner) {} + ResponseSentTracker(kj::HttpService::Response& inner, bool enableByteCount) + : inner(inner), + enableByteCount(enableByteCount) {} KJ_DISALLOW_COPY_AND_MOVE(ResponseSentTracker); bool isSent() const { @@ -197,7 +205,8 @@ class WorkerEntrypoint::ResponseSentTracker final: public kj::HttpService::Respo return expectedBodySize; } - // Returns a reference to the byte counter for deferred access after streaming. + // Transfers ownership of the byte counter for deferred access after streaming. + // Returns kj::none if byte counting is not enabled or if already called. // The returned ownership should be held until after proxyTask completes. kj::Maybe> takeByteCounter() { return kj::mv(byteCounter); @@ -215,10 +224,14 @@ class WorkerEntrypoint::ResponseSentTracker final: public kj::HttpService::Respo auto stream = inner.send(statusCode, statusText, headers, expectedBodySize); - // Wrap with byte counting for trace events - auto counter = kj::refcounted(); - byteCounter = kj::addRef(*counter); - return kj::heap(kj::mv(stream), kj::mv(counter)); + // Only wrap with byte counting when tracing is enabled to avoid performance + // overhead for workers without tail workers. + if (enableByteCount) { + auto counter = kj::refcounted(); + byteCounter = kj::addRef(*counter); + return kj::heap(kj::mv(stream), kj::mv(counter)); + } + return stream; } kj::Own acceptWebSocket(const kj::HttpHeaders& headers) override { @@ -233,6 +246,7 @@ class WorkerEntrypoint::ResponseSentTracker final: public kj::HttpService::Respo kj::Maybe> byteCounter; kj::HttpService::Response& inner; bool sent = false; + bool enableByteCount = false; }; kj::Own WorkerEntrypoint::construct(ThreadContext& threadContext, @@ -327,7 +341,9 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, this->incomingRequest = kj::none; auto& context = incomingRequest->getContext(); - auto wrappedResponse = kj::heap(response); + // Enable byte counting only when tracing is enabled to avoid performance overhead. + bool hasTracer = incomingRequest->getWorkerTracer() != kj::none; + auto wrappedResponse = kj::heap(response, hasTracer); bool isActor = context.getActor() != kj::none; // HACK: Capture workerTracer directly, it's unclear how to acquire the right tracer from context @@ -363,17 +379,11 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, // TODO(someday): Track actual bytes consumed from request body stream instead of // relying on Content-Length header. This is less critical than response body size // since request bodies typically have accurate Content-Length. + // Note: bodySize of 0 means either no Content-Length header or Content-Length: 0; + // this is acceptable for trace events as both semantically indicate no/empty body data. uint64_t bodySize = 0; KJ_IF_SOME(contentLength, headers.get(kj::HttpHeaderId::CONTENT_LENGTH)) { - // Parse the Content-Length value. Skip leading whitespace first since HTTP headers - // can include leading/trailing whitespace. If parsing fails, we leave bodySize as 0. - const char* ptr = contentLength.cStr(); - while (*ptr == ' ' || *ptr == '\t') ptr++; // Skip leading whitespace - char* end; - auto parsed = strtoull(ptr, &end, 10); - // Check that we parsed something and only trailing whitespace remains - while (*end == ' ' || *end == '\t') end++; // Skip trailing whitespace - if (end != ptr && *end == '\0') { + KJ_IF_SOME(parsed, contentLength.tryParseAs()) { bodySize = parsed; } } From 946bd8e656ce94f41c2f01cd85239f42d1b6c743 Mon Sep 17 00:00:00 2001 From: Luca Steeb Date: Wed, 21 Jan 2026 13:07:44 +0000 Subject: [PATCH 06/10] Use kj::Maybe for bodySize to distinguish unknown from zero This change allows differentiating between: - kj::none: Body size is unknown (no Content-Length header) - Some(0): Body size is explicitly zero (Content-Length: 0) - Some(N): Body size is N bytes Changes: - Add hasBodySize boolean field to capnp schema for FetchEventInfo and FetchResponseInfo to indicate whether bodySize is valid - Update trace.h structs to use kj::Maybe instead of uint64_t - Update trace.c++ serialization to read/write hasBodySize flag - Update trace-stream.c++ ToJs to only include bodySize when known - Update api/trace.h and api/trace.c++ for the new type - Update worker-entrypoint.c++ to pass kj::Maybe for bodySize - Add new test cases for zero bodySize vs unknown bodySize The JavaScript API returns null when bodySize is unknown, and the actual numeric value (including 0) when it's known. Co-Authored-By: Claude Opus 4.5 --- src/workerd/api/trace.c++ | 18 ++++---- src/workerd/api/trace.h | 6 +-- src/workerd/io/trace-stream.c++ | 12 ++--- src/workerd/io/trace-test.c++ | 66 +++++++++++++++++++++++---- src/workerd/io/trace.c++ | 29 ++++++++---- src/workerd/io/trace.h | 8 ++-- src/workerd/io/worker-entrypoint.c++ | 12 ++--- src/workerd/io/worker-interface.capnp | 8 +++- 8 files changed, 111 insertions(+), 48 deletions(-) diff --git a/src/workerd/api/trace.c++ b/src/workerd/api/trace.c++ index 7e971479701..c4a4ea358d4 100644 --- a/src/workerd/api/trace.c++ +++ b/src/workerd/api/trace.c++ @@ -305,7 +305,7 @@ TraceItem::FetchEventInfo::Request::Detail::Detail(jsg::Optional headers, kj::String method, kj::String url, - uint64_t bodySize) + kj::Maybe bodySize) : cf(kj::mv(cf)), headers(kj::mv(headers)), method(kj::mv(method)), @@ -364,13 +364,13 @@ kj::String TraceItem::FetchEventInfo::Request::getUrl() { } jsg::Optional TraceItem::FetchEventInfo::Request::getBodySize() { - // Return null if bodySize is 0 (unknown/no body), otherwise return the size. + // Return null if bodySize is unknown (kj::none), otherwise return the size. // Note: Converting uint64_t to double may lose precision for sizes larger than 2^53 bytes // (approximately 9 petabytes), though this is unlikely in practice. - if (detail->bodySize == 0) { - return kj::none; + KJ_IF_SOME(size, detail->bodySize) { + return static_cast(size); } - return static_cast(detail->bodySize); + return kj::none; } jsg::Ref TraceItem::FetchEventInfo::Request::getUnredacted( @@ -388,13 +388,13 @@ uint16_t TraceItem::FetchEventInfo::Response::getStatus() { } jsg::Optional TraceItem::FetchEventInfo::Response::getBodySize() { - // Return null if bodySize is 0 (unknown/no body), otherwise return the size. + // Return null if bodySize is unknown (kj::none), otherwise return the size. // Note: Converting uint64_t to double may lose precision for sizes larger than 2^53 bytes // (approximately 9 petabytes), though this is unlikely in practice. - if (bodySize == 0) { - return kj::none; + KJ_IF_SOME(size, bodySize) { + return static_cast(size); } - return static_cast(bodySize); + return kj::none; } TraceItem::JsRpcEventInfo::JsRpcEventInfo( diff --git a/src/workerd/api/trace.h b/src/workerd/api/trace.h index 061048b1a3c..3063485fe0e 100644 --- a/src/workerd/api/trace.h +++ b/src/workerd/api/trace.h @@ -199,13 +199,13 @@ class TraceItem::FetchEventInfo::Request final: public jsg::Object { kj::Array headers; kj::String method; kj::String url; - uint64_t bodySize; + kj::Maybe bodySize; Detail(jsg::Optional> cf, kj::Array headers, kj::String method, kj::String url, - uint64_t bodySize); + kj::Maybe bodySize); JSG_MEMORY_INFO(Detail) { tracker.trackField("cf", cf); @@ -263,7 +263,7 @@ class TraceItem::FetchEventInfo::Response final: public jsg::Object { private: uint16_t status; - uint64_t bodySize; + kj::Maybe bodySize; }; class TraceItem::JsRpcEventInfo final: public jsg::Object { diff --git a/src/workerd/io/trace-stream.c++ b/src/workerd/io/trace-stream.c++ index 0ee657fcf75..4e5f9f9a2d9 100644 --- a/src/workerd/io/trace-stream.c++ +++ b/src/workerd/io/trace-stream.c++ @@ -179,9 +179,9 @@ jsg::JsValue ToJs(jsg::Lock& js, const FetchResponseInfo& info, StringCache& cac auto obj = js.obj(); obj.set(js, TYPE_STR, cache.get(js, FETCH_STR)); obj.set(js, STATUSCODE_STR, js.num(info.statusCode)); - // Only include bodySize if it's non-zero (indicating actual body size was tracked) - if (info.bodySize > 0) { - obj.set(js, BODYSIZE_STR, js.num(static_cast(info.bodySize))); + // Include bodySize if it's known (kj::Maybe has a value) + KJ_IF_SOME(size, info.bodySize) { + obj.set(js, BODYSIZE_STR, js.num(static_cast(size))); } return obj; } @@ -206,9 +206,9 @@ jsg::JsValue ToJs(jsg::Lock& js, const FetchEventInfo& info, StringCache& cache) js.arr(info.headers.asPtr(), [&cache, &ToJs](jsg::Lock& js, const auto& header) { return ToJs(js, header, cache); })); - // Only include bodySize if it's non-zero (indicating request body size was tracked) - if (info.bodySize > 0) { - obj.set(js, BODYSIZE_STR, js.num(static_cast(info.bodySize))); + // Include bodySize if it's known (kj::Maybe has a value) + KJ_IF_SOME(size, info.bodySize) { + obj.set(js, BODYSIZE_STR, js.num(static_cast(size))); } return obj; diff --git a/src/workerd/io/trace-test.c++ b/src/workerd/io/trace-test.c++ index b6c0d6954b9..a798995fa83 100644 --- a/src/workerd/io/trace-test.c++ +++ b/src/workerd/io/trace-test.c++ @@ -176,7 +176,7 @@ KJ_TEST("Read/Write FetchEventInfo works") { KJ_ASSERT(info2.headers.size() == 1); KJ_ASSERT(info2.headers[0].name == "foo"_kj); KJ_ASSERT(info2.headers[0].value == "bar"_kj); - KJ_ASSERT(info2.bodySize == 0); // Default value + KJ_ASSERT(info2.bodySize == kj::none); // Default value (unknown) FetchEventInfo info3 = info.clone(); KJ_ASSERT(info3.method == kj::HttpMethod::GET); @@ -185,7 +185,7 @@ KJ_TEST("Read/Write FetchEventInfo works") { KJ_ASSERT(info3.headers.size() == 1); KJ_ASSERT(info3.headers[0].name == "foo"_kj); KJ_ASSERT(info3.headers[0].value == "bar"_kj); - KJ_ASSERT(info3.bodySize == 0); // Default value + KJ_ASSERT(info3.bodySize == kj::none); // Default value (unknown) } KJ_TEST("Read/Write FetchEventInfo with bodySize works") { @@ -195,7 +195,7 @@ KJ_TEST("Read/Write FetchEventInfo with bodySize works") { kj::Vector headers; headers.add(FetchEventInfo::Header(kj::str("content-type"), kj::str("application/json"))); - uint64_t bodySize = 12345; + kj::Maybe bodySize = 12345; FetchEventInfo info(kj::HttpMethod::POST, kj::str("https://example.com/api"), kj::str("{}"), headers.releaseAsArray(), bodySize); @@ -206,12 +206,36 @@ KJ_TEST("Read/Write FetchEventInfo with bodySize works") { FetchEventInfo info2(reader); KJ_ASSERT(info2.method == kj::HttpMethod::POST); KJ_ASSERT(info2.url == "https://example.com/api"_kj); - KJ_ASSERT(info2.bodySize == 12345); + KJ_ASSERT(KJ_ASSERT_NONNULL(info2.bodySize) == 12345); FetchEventInfo info3 = info.clone(); KJ_ASSERT(info3.method == kj::HttpMethod::POST); KJ_ASSERT(info3.url == "https://example.com/api"_kj); - KJ_ASSERT(info3.bodySize == 12345); + KJ_ASSERT(KJ_ASSERT_NONNULL(info3.bodySize) == 12345); +} + +KJ_TEST("Read/Write FetchEventInfo with zero bodySize works") { + capnp::MallocMessageBuilder builder; + auto fetchInfoBuilder = builder.initRoot(); + + kj::Vector headers; + headers.add(FetchEventInfo::Header(kj::str("content-length"), kj::str("0"))); + + // Content-Length: 0 should be distinguishable from unknown + kj::Maybe bodySize = uint64_t{0}; + FetchEventInfo info(kj::HttpMethod::POST, kj::str("https://example.com/api"), kj::str("{}"), + headers.releaseAsArray(), bodySize); + + info.copyTo(fetchInfoBuilder); + + auto reader = fetchInfoBuilder.asReader(); + + FetchEventInfo info2(reader); + KJ_ASSERT(info2.method == kj::HttpMethod::POST); + KJ_ASSERT(KJ_ASSERT_NONNULL(info2.bodySize) == 0); // Known to be zero, not unknown + + FetchEventInfo info3 = info.clone(); + KJ_ASSERT(KJ_ASSERT_NONNULL(info3.bodySize) == 0); // Known to be zero, not unknown } KJ_TEST("Read/Write JsRpcEventInfo works") { @@ -445,19 +469,19 @@ KJ_TEST("Read/Write Return works") { Return info2(reader); auto& fetchInfo2 = KJ_ASSERT_NONNULL(info2.info); KJ_ASSERT(fetchInfo2.statusCode == 123); - KJ_ASSERT(fetchInfo2.bodySize == 0); // Default value + KJ_ASSERT(fetchInfo2.bodySize == kj::none); // Default value (unknown) Return info3 = info.clone(); auto& fetchInfo3 = KJ_ASSERT_NONNULL(info3.info); KJ_ASSERT(fetchInfo3.statusCode == 123); - KJ_ASSERT(fetchInfo3.bodySize == 0); // Default value + KJ_ASSERT(fetchInfo3.bodySize == kj::none); // Default value (unknown) } KJ_TEST("Read/Write Return with bodySize works") { capnp::MallocMessageBuilder builder; auto infoBuilder = builder.initRoot(); - uint64_t bodySize = 54321; + kj::Maybe bodySize = 54321; FetchResponseInfo fetchInfo(200, bodySize); Return info(kj::mv(fetchInfo)); info.copyTo(infoBuilder); @@ -466,12 +490,34 @@ KJ_TEST("Read/Write Return with bodySize works") { Return info2(reader); auto& fetchInfo2 = KJ_ASSERT_NONNULL(info2.info); KJ_ASSERT(fetchInfo2.statusCode == 200); - KJ_ASSERT(fetchInfo2.bodySize == 54321); + KJ_ASSERT(KJ_ASSERT_NONNULL(fetchInfo2.bodySize) == 54321); Return info3 = info.clone(); auto& fetchInfo3 = KJ_ASSERT_NONNULL(info3.info); KJ_ASSERT(fetchInfo3.statusCode == 200); - KJ_ASSERT(fetchInfo3.bodySize == 54321); + KJ_ASSERT(KJ_ASSERT_NONNULL(fetchInfo3.bodySize) == 54321); +} + +KJ_TEST("Read/Write Return with zero bodySize works") { + capnp::MallocMessageBuilder builder; + auto infoBuilder = builder.initRoot(); + + // Zero body size should be distinguishable from unknown + kj::Maybe bodySize = uint64_t{0}; + FetchResponseInfo fetchInfo(204, bodySize); + Return info(kj::mv(fetchInfo)); + info.copyTo(infoBuilder); + + auto reader = infoBuilder.asReader(); + Return info2(reader); + auto& fetchInfo2 = KJ_ASSERT_NONNULL(info2.info); + KJ_ASSERT(fetchInfo2.statusCode == 204); + KJ_ASSERT(KJ_ASSERT_NONNULL(fetchInfo2.bodySize) == 0); // Known to be zero, not unknown + + Return info3 = info.clone(); + auto& fetchInfo3 = KJ_ASSERT_NONNULL(info3.info); + KJ_ASSERT(fetchInfo3.statusCode == 204); + KJ_ASSERT(KJ_ASSERT_NONNULL(fetchInfo3.bodySize) == 0); // Known to be zero, not unknown } KJ_TEST("Read/Write SpanOpen works") { diff --git a/src/workerd/io/trace.c++ b/src/workerd/io/trace.c++ index 3aeb7fb04a6..6b5e7591325 100644 --- a/src/workerd/io/trace.c++ +++ b/src/workerd/io/trace.c++ @@ -327,7 +327,7 @@ FetchEventInfo::FetchEventInfo(kj::HttpMethod method, kj::String url, kj::String cfJson, kj::Array
headers, - uint64_t bodySize) + kj::Maybe bodySize) : method(method), url(kj::mv(url)), cfJson(kj::mv(cfJson)), @@ -337,8 +337,11 @@ FetchEventInfo::FetchEventInfo(kj::HttpMethod method, FetchEventInfo::FetchEventInfo(rpc::Trace::FetchEventInfo::Reader reader) : method(validateMethod(reader.getMethod())), url(kj::str(reader.getUrl())), - cfJson(kj::str(reader.getCfJson())), - bodySize(reader.getBodySize()) { + cfJson(kj::str(reader.getCfJson())) { + // Only set bodySize if hasBodySize is true + if (reader.getHasBodySize()) { + bodySize = reader.getBodySize(); + } kj::Vector
v; v.addAll(reader.getHeaders()); headers = v.releaseAsArray(); @@ -348,7 +351,10 @@ void FetchEventInfo::copyTo(rpc::Trace::FetchEventInfo::Builder builder) const { builder.setMethod(static_cast(method)); builder.setUrl(url); builder.setCfJson(cfJson); - builder.setBodySize(bodySize); + KJ_IF_SOME(size, bodySize) { + builder.setBodySize(size); + builder.setHasBodySize(true); + } auto list = builder.initHeaders(headers.size()); for (auto i: kj::indices(headers)) { @@ -601,17 +607,24 @@ HibernatableWebSocketEventInfo::Type HibernatableWebSocketEventInfo::readFrom( } } -FetchResponseInfo::FetchResponseInfo(uint16_t statusCode, uint64_t bodySize) +FetchResponseInfo::FetchResponseInfo(uint16_t statusCode, kj::Maybe bodySize) : statusCode(statusCode), bodySize(bodySize) {} FetchResponseInfo::FetchResponseInfo(rpc::Trace::FetchResponseInfo::Reader reader) - : statusCode(reader.getStatusCode()), - bodySize(reader.getBodySize()) {} + : statusCode(reader.getStatusCode()) { + // Only set bodySize if hasBodySize is true + if (reader.getHasBodySize()) { + bodySize = reader.getBodySize(); + } +} void FetchResponseInfo::copyTo(rpc::Trace::FetchResponseInfo::Builder builder) const { builder.setStatusCode(statusCode); - builder.setBodySize(bodySize); + KJ_IF_SOME(size, bodySize) { + builder.setBodySize(size); + builder.setHasBodySize(true); + } } FetchResponseInfo FetchResponseInfo::clone() const { diff --git a/src/workerd/io/trace.h b/src/workerd/io/trace.h index ca011f15f2c..c3ac6dd1dad 100644 --- a/src/workerd/io/trace.h +++ b/src/workerd/io/trace.h @@ -313,7 +313,7 @@ struct FetchEventInfo final { kj::String url, kj::String cfJson, kj::Array
headers, - uint64_t bodySize = 0); + kj::Maybe bodySize = kj::none); FetchEventInfo(rpc::Trace::FetchEventInfo::Reader reader); FetchEventInfo(FetchEventInfo&&) = default; FetchEventInfo& operator=(FetchEventInfo&&) = default; @@ -344,7 +344,7 @@ struct FetchEventInfo final { // TODO(perf): It might be more efficient to store some sort of parsed JSON result instead? kj::String cfJson; kj::Array
headers; - uint64_t bodySize = 0; // Request body size in bytes. 0 if unknown or no body. + kj::Maybe bodySize; // Request body size in bytes. kj::none if unknown. void copyTo(rpc::Trace::FetchEventInfo::Builder builder) const; FetchEventInfo clone() const; @@ -488,14 +488,14 @@ struct CustomEventInfo final { // Describes a fetch response struct FetchResponseInfo final { - explicit FetchResponseInfo(uint16_t statusCode, uint64_t bodySize = 0); + explicit FetchResponseInfo(uint16_t statusCode, kj::Maybe bodySize = kj::none); FetchResponseInfo(rpc::Trace::FetchResponseInfo::Reader reader); FetchResponseInfo(FetchResponseInfo&&) = default; FetchResponseInfo& operator=(FetchResponseInfo&&) = default; KJ_DISALLOW_COPY(FetchResponseInfo); uint16_t statusCode; - uint64_t bodySize = 0; // Response body size in bytes. 0 if unknown or no body. + kj::Maybe bodySize; // Response body size in bytes. kj::none if unknown. void copyTo(rpc::Trace::FetchResponseInfo::Builder builder) const; FetchResponseInfo clone() const; diff --git a/src/workerd/io/worker-entrypoint.c++ b/src/workerd/io/worker-entrypoint.c++ index 7e212d53ef8..dba5e865e53 100644 --- a/src/workerd/io/worker-entrypoint.c++ +++ b/src/workerd/io/worker-entrypoint.c++ @@ -379,9 +379,8 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, // TODO(someday): Track actual bytes consumed from request body stream instead of // relying on Content-Length header. This is less critical than response body size // since request bodies typically have accurate Content-Length. - // Note: bodySize of 0 means either no Content-Length header or Content-Length: 0; - // this is acceptable for trace events as both semantically indicate no/empty body data. - uint64_t bodySize = 0; + // bodySize is kj::none if no Content-Length header was present (unknown size). + kj::Maybe bodySize; KJ_IF_SOME(contentLength, headers.get(kj::HttpHeaderId::CONTENT_LENGTH)) { KJ_IF_SOME(parsed, contentLength.tryParseAs()) { bodySize = parsed; @@ -500,7 +499,7 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, // instead of the Content-Length header value. KJ_IF_SOME(t, deferredWorkerTracer) { if (deferredHttpResponseStatus != 0) { - uint64_t actualBodySize = 0; + kj::Maybe actualBodySize; KJ_IF_SOME(counter, traceByteCounter) { actualBodySize = counter->get(); } @@ -521,10 +520,11 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, return kj::mv(e); }); } else { - // No proxyTask means no streaming body - report trace now if we have deferred info + // No proxyTask means no streaming body - report trace now if we have deferred info. + // bodySize is kj::none since we don't have the byte counter to track actual size. KJ_IF_SOME(t, deferredWorkerTracer) { if (deferredHttpResponseStatus != 0) { - t.setReturn(kj::none, tracing::FetchResponseInfo(deferredHttpResponseStatus, 0)); + t.setReturn(kj::none, tracing::FetchResponseInfo(deferredHttpResponseStatus)); } else { t.setReturn(kj::none); } diff --git a/src/workerd/io/worker-interface.capnp b/src/workerd/io/worker-interface.capnp index bcb11ce85f9..68d2a942898 100644 --- a/src/workerd/io/worker-interface.capnp +++ b/src/workerd/io/worker-interface.capnp @@ -109,7 +109,9 @@ struct Trace @0x8e8d911203762d34 { value @1 :Text; } bodySize @4 :UInt64; - # Request body size in bytes. 0 if unknown or no body. + # Request body size in bytes. Only valid if hasBodySize is true. + hasBodySize @5 :Bool; + # True if bodySize contains a valid value (from Content-Length header). } struct JsRpcEventInfo { @@ -161,7 +163,9 @@ struct Trace @0x8e8d911203762d34 { struct FetchResponseInfo { statusCode @0 :UInt16; bodySize @1 :UInt64; - # Response body size in bytes. 0 if unknown or no body. + # Response body size in bytes. Only valid if hasBodySize is true. + hasBodySize @2 :Bool; + # True if bodySize contains a valid value (actual bytes written). } cpuTime @10 :UInt64; From 71dcfde54d63316d6e485dbfbdca2f1c3560a7ab Mon Sep 17 00:00:00 2001 From: Luca Steeb Date: Wed, 21 Jan 2026 22:57:20 +0000 Subject: [PATCH 07/10] Move request body size from onset to return event Addresses PR feedback: request body size should be tracked after the body is consumed, not at onset time using Content-Length header. - Remove bodySize from FetchEventInfo (onset event) - Add requestBodySize to FetchResponseInfo (return event) - Add ByteCountingInputStream to track actual request bytes consumed - Both request and response body sizes are now reported after streaming - Byte counting only enabled when tail workers are active (no perf impact) Co-Authored-By: Claude Opus 4.5 --- src/workerd/api/tests/http-test.js | 40 +++++++ src/workerd/api/tests/tail-worker-test.js | 12 +- src/workerd/api/trace.c++ | 29 +++-- src/workerd/api/trace.h | 11 +- src/workerd/io/trace-stream.c++ | 13 ++- src/workerd/io/trace-test.c++ | 129 +++++++++++----------- src/workerd/io/trace.c++ | 39 +++---- src/workerd/io/trace.h | 17 +-- src/workerd/io/worker-entrypoint.c++ | 119 +++++++++++++++----- src/workerd/io/worker-interface.capnp | 13 ++- 10 files changed, 272 insertions(+), 150 deletions(-) diff --git a/src/workerd/api/tests/http-test.js b/src/workerd/api/tests/http-test.js index 33ec6e0bd35..6b5d6b40853 100644 --- a/src/workerd/api/tests/http-test.js +++ b/src/workerd/api/tests/http-test.js @@ -13,6 +13,22 @@ export default { if (pathname === '/body-length') { return Response.json(Object.fromEntries(request.headers)); } + if (pathname === '/consume-body') { + // Actually consume the request body to test request body size tracking + const body = await request.text(); + return new Response(`Received ${body.length} bytes`); + } + if (pathname === '/streaming-response') { + // Streaming response to test response body size tracking + const stream = new ReadableStream({ + start(controller) { + controller.enqueue(new TextEncoder().encode('chunk1')); + controller.enqueue(new TextEncoder().encode('chunk2')); + controller.close(); + }, + }); + return new Response(stream); + } if (pathname === '/web-socket') { const pair = new WebSocketPair(); pair[0].addEventListener('message', (event) => { @@ -89,6 +105,30 @@ export default { assert.strictEqual(scheduledLastCtrl.scheduledTime, 1000); assert.strictEqual(scheduledLastCtrl.cron, '* * * * 30'); } + + // Test request body consumption - body size should be tracked + { + const response = await env.SERVICE.fetch( + 'http://placeholder/consume-body', + { + method: 'POST', + body: 'hello', + } + ); + const text = await response.text(); + assert.strictEqual(text, 'Received 5 bytes'); + } + + // Test streaming response - body size should be tracked after streaming + { + const response = await env.SERVICE.fetch( + 'http://placeholder/streaming-response' + ); + const text = await response.text(); + // "chunk1" + "chunk2" = 12 bytes + assert.strictEqual(text, 'chunk1chunk2'); + assert.strictEqual(text.length, 12); + } }, }; diff --git a/src/workerd/api/tests/tail-worker-test.js b/src/workerd/api/tests/tail-worker-test.js index eb0bfa5d54f..5c32933a522 100644 --- a/src/workerd/api/tests/tail-worker-test.js +++ b/src/workerd/api/tests/tail-worker-test.js @@ -85,11 +85,17 @@ export const test = { let expected = [ // http-test.js: fetch and scheduled events get reported correctly. // First event is emitted by the test() event, which allows us to get some coverage for span tracing. - '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"custom"}}{"type":"spanOpen","name":"fetch","spanId":"0000000000000001"}{"type":"attributes","info":[{"name":"network.protocol.name","value":"http"},{"name":"network.protocol.version","value":"HTTP/1.1"},{"name":"http.request.method","value":"POST"},{"name":"url.full","value":"http://placeholder/body-length"},{"name":"http.request.body.size","value":"3"},{"name":"http.response.status_code","value":"200"},{"name":"http.response.body.size","value":"22"}]}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"fetch","spanId":"0000000000000002"}{"type":"attributes","info":[{"name":"network.protocol.name","value":"http"},{"name":"network.protocol.version","value":"HTTP/1.1"},{"name":"http.request.method","value":"POST"},{"name":"url.full","value":"http://placeholder/body-length"},{"name":"http.response.status_code","value":"200"},{"name":"http.response.body.size","value":"31"}]}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"scheduled","spanId":"0000000000000003"}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"scheduled","spanId":"0000000000000004"}{"type":"spanClose","outcome":"ok"}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', - '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"POST","url":"http://placeholder/body-length","headers":[],"bodySize":3}}{"type":"return","info":{"type":"fetch","statusCode":200,"bodySize":22}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', - '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"POST","url":"http://placeholder/body-length","headers":[]}}{"type":"return","info":{"type":"fetch","statusCode":200,"bodySize":31}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', + // Note: Span attributes use OpenTelemetry-style names (http.request.body.size, http.response.body.size) + '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"custom"}}{"type":"spanOpen","name":"fetch","spanId":"0000000000000001"}{"type":"attributes","info":[{"name":"network.protocol.name","value":"http"},{"name":"network.protocol.version","value":"HTTP/1.1"},{"name":"http.request.method","value":"POST"},{"name":"url.full","value":"http://placeholder/body-length"},{"name":"http.request.body.size","value":"3"},{"name":"http.response.status_code","value":"200"},{"name":"http.response.body.size","value":"22"}]}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"fetch","spanId":"0000000000000002"}{"type":"attributes","info":[{"name":"network.protocol.name","value":"http"},{"name":"network.protocol.version","value":"HTTP/1.1"},{"name":"http.request.method","value":"POST"},{"name":"url.full","value":"http://placeholder/body-length"},{"name":"http.response.status_code","value":"200"},{"name":"http.response.body.size","value":"31"}]}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"scheduled","spanId":"0000000000000003"}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"scheduled","spanId":"0000000000000004"}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"fetch","spanId":"0000000000000005"}{"type":"attributes","info":[{"name":"network.protocol.name","value":"http"},{"name":"network.protocol.version","value":"HTTP/1.1"},{"name":"http.request.method","value":"POST"},{"name":"url.full","value":"http://placeholder/consume-body"},{"name":"http.request.body.size","value":"5"},{"name":"http.response.status_code","value":"200"},{"name":"http.response.body.size","value":"16"}]}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"fetch","spanId":"0000000000000006"}{"type":"attributes","info":[{"name":"network.protocol.name","value":"http"},{"name":"network.protocol.version","value":"HTTP/1.1"},{"name":"http.request.method","value":"GET"},{"name":"url.full","value":"http://placeholder/streaming-response"},{"name":"http.response.status_code","value":"200"},{"name":"http.response.body.size","value":"12"}]}{"type":"spanClose","outcome":"ok"}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', + // Note: Request body size is now in the return event, not the onset event + '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"POST","url":"http://placeholder/body-length","headers":[]}}{"type":"return","info":{"type":"fetch","statusCode":200,"bodySize":22,"requestBodySize":3}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', + '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"POST","url":"http://placeholder/body-length","headers":[]}}{"type":"return","info":{"type":"fetch","statusCode":200,"bodySize":31,"requestBodySize":3}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"scheduled","scheduledTime":"1970-01-01T00:00:00.000Z","cron":""}}{"type":"return"}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"scheduled","scheduledTime":"1970-01-01T00:00:00.000Z","cron":"* * * * 30"}}{"type":"return"}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', + // Test consume-body endpoint - request body size tracked after body consumed + '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"POST","url":"http://placeholder/consume-body","headers":[]}}{"type":"return","info":{"type":"fetch","statusCode":200,"bodySize":16,"requestBodySize":5}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', + // Test streaming-response endpoint - response body size tracked after streaming + '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"GET","url":"http://placeholder/streaming-response","headers":[]}}{"type":"return","info":{"type":"fetch","statusCode":200,"bodySize":12}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","entrypoint":"cacheMode","scriptTags":[],"info":{"type":"custom"}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"GET","url":"http://placeholder/not-found","headers":[]}}{"type":"return","info":{"type":"fetch","statusCode":404}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"GET","url":"http://placeholder/web-socket","headers":[{"name":"upgrade","value":"websocket"}]}}{"type":"exception","name":"Error","message":"The Workers runtime canceled this request because it detected that your Worker\'s code had hung and would never generate a response. Refer to: https://developers.cloudflare.com/workers/observability/errors/"}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', diff --git a/src/workerd/api/trace.c++ b/src/workerd/api/trace.c++ index c4a4ea358d4..1272a6d2d8b 100644 --- a/src/workerd/api/trace.c++ +++ b/src/workerd/api/trace.c++ @@ -128,7 +128,7 @@ kj::Own getFetchRequestDetail( }; return kj::refcounted( - getCf(), getHeaders(), kj::str(eventInfo.method), kj::str(eventInfo.url), eventInfo.bodySize); + getCf(), getHeaders(), kj::str(eventInfo.method), kj::str(eventInfo.url)); } kj::Maybe getTraceEvent(jsg::Lock& js, const Trace& trace) { @@ -304,13 +304,11 @@ TraceItem::FetchEventInfo::FetchEventInfo(jsg::Lock& js, TraceItem::FetchEventInfo::Request::Detail::Detail(jsg::Optional> cf, kj::Array headers, kj::String method, - kj::String url, - kj::Maybe bodySize) + kj::String url) : cf(kj::mv(cf)), headers(kj::mv(headers)), method(kj::mv(method)), - url(kj::mv(url)), - bodySize(bodySize) {} + url(kj::mv(url)) {} jsg::Ref TraceItem::FetchEventInfo::getRequest() { return request.addRef(); @@ -363,16 +361,6 @@ kj::String TraceItem::FetchEventInfo::Request::getUrl() { return (redacted ? redactUrl(detail->url) : kj::str(detail->url)); } -jsg::Optional TraceItem::FetchEventInfo::Request::getBodySize() { - // Return null if bodySize is unknown (kj::none), otherwise return the size. - // Note: Converting uint64_t to double may lose precision for sizes larger than 2^53 bytes - // (approximately 9 petabytes), though this is unlikely in practice. - KJ_IF_SOME(size, detail->bodySize) { - return static_cast(size); - } - return kj::none; -} - jsg::Ref TraceItem::FetchEventInfo::Request::getUnredacted( jsg::Lock& js) { return js.alloc(*detail, false /* details are not redacted */); @@ -381,7 +369,8 @@ jsg::Ref TraceItem::FetchEventInfo::Request: TraceItem::FetchEventInfo::Response::Response( const Trace& trace, const tracing::FetchResponseInfo& responseInfo) : status(responseInfo.statusCode), - bodySize(responseInfo.bodySize) {} + bodySize(responseInfo.bodySize), + requestBodySize(responseInfo.requestBodySize) {} uint16_t TraceItem::FetchEventInfo::Response::getStatus() { return status; @@ -397,6 +386,14 @@ jsg::Optional TraceItem::FetchEventInfo::Response::getBodySize() { return kj::none; } +jsg::Optional TraceItem::FetchEventInfo::Response::getRequestBodySize() { + // Return null if requestBodySize is unknown (kj::none), otherwise return the size. + KJ_IF_SOME(size, requestBodySize) { + return static_cast(size); + } + return kj::none; +} + TraceItem::JsRpcEventInfo::JsRpcEventInfo( const Trace& trace, const tracing::JsRpcEventInfo& eventInfo) : rpcMethod(kj::str(eventInfo.methodName)) {} diff --git a/src/workerd/api/trace.h b/src/workerd/api/trace.h index 3063485fe0e..cb886f18f2a 100644 --- a/src/workerd/api/trace.h +++ b/src/workerd/api/trace.h @@ -199,13 +199,13 @@ class TraceItem::FetchEventInfo::Request final: public jsg::Object { kj::Array headers; kj::String method; kj::String url; - kj::Maybe bodySize; + // Note: Request body size is tracked in Response, not here, because + // it's only known after the request body is fully consumed. Detail(jsg::Optional> cf, kj::Array headers, kj::String method, - kj::String url, - kj::Maybe bodySize); + kj::String url); JSG_MEMORY_INFO(Detail) { tracker.trackField("cf", cf); @@ -226,7 +226,6 @@ class TraceItem::FetchEventInfo::Request final: public jsg::Object { jsg::Dict getHeaders(jsg::Lock& js); kj::StringPtr getMethod(); kj::String getUrl(); - jsg::Optional getBodySize(); jsg::Ref getUnredacted(jsg::Lock& js); @@ -235,7 +234,6 @@ class TraceItem::FetchEventInfo::Request final: public jsg::Object { JSG_LAZY_READONLY_INSTANCE_PROPERTY(headers, getHeaders); JSG_LAZY_READONLY_INSTANCE_PROPERTY(method, getMethod); JSG_LAZY_READONLY_INSTANCE_PROPERTY(url, getUrl); - JSG_LAZY_READONLY_INSTANCE_PROPERTY(bodySize, getBodySize); JSG_METHOD(getUnredacted); } @@ -255,15 +253,18 @@ class TraceItem::FetchEventInfo::Response final: public jsg::Object { uint16_t getStatus(); jsg::Optional getBodySize(); + jsg::Optional getRequestBodySize(); JSG_RESOURCE_TYPE(Response) { JSG_LAZY_READONLY_INSTANCE_PROPERTY(status, getStatus); JSG_LAZY_READONLY_INSTANCE_PROPERTY(bodySize, getBodySize); + JSG_LAZY_READONLY_INSTANCE_PROPERTY(requestBodySize, getRequestBodySize); } private: uint16_t status; kj::Maybe bodySize; + kj::Maybe requestBodySize; }; class TraceItem::JsRpcEventInfo final: public jsg::Object { diff --git a/src/workerd/io/trace-stream.c++ b/src/workerd/io/trace-stream.c++ index 4e5f9f9a2d9..2e2caf8deb0 100644 --- a/src/workerd/io/trace-stream.c++ +++ b/src/workerd/io/trace-stream.c++ @@ -20,6 +20,7 @@ namespace { V(ATTRIBUTES, "attributes") \ V(BATCHSIZE, "batchSize") \ V(BODYSIZE, "bodySize") \ + V(REQUESTBODYSIZE, "requestBodySize") \ V(CANCELED, "canceled") \ V(CHANNEL, "channel") \ V(CFJSON, "cfJson") \ @@ -179,10 +180,14 @@ jsg::JsValue ToJs(jsg::Lock& js, const FetchResponseInfo& info, StringCache& cac auto obj = js.obj(); obj.set(js, TYPE_STR, cache.get(js, FETCH_STR)); obj.set(js, STATUSCODE_STR, js.num(info.statusCode)); - // Include bodySize if it's known (kj::Maybe has a value) + // Include bodySize (response body) if it's known KJ_IF_SOME(size, info.bodySize) { obj.set(js, BODYSIZE_STR, js.num(static_cast(size))); } + // Include requestBodySize if it's known + KJ_IF_SOME(size, info.requestBodySize) { + obj.set(js, REQUESTBODYSIZE_STR, js.num(static_cast(size))); + } return obj; } @@ -206,10 +211,8 @@ jsg::JsValue ToJs(jsg::Lock& js, const FetchEventInfo& info, StringCache& cache) js.arr(info.headers.asPtr(), [&cache, &ToJs](jsg::Lock& js, const auto& header) { return ToJs(js, header, cache); })); - // Include bodySize if it's known (kj::Maybe has a value) - KJ_IF_SOME(size, info.bodySize) { - obj.set(js, BODYSIZE_STR, js.num(static_cast(size))); - } + // Note: Request body size is tracked in FetchResponseInfo, not here, + // because it's only known after the request body is fully consumed. return obj; } diff --git a/src/workerd/io/trace-test.c++ b/src/workerd/io/trace-test.c++ index a798995fa83..8d58cc2e865 100644 --- a/src/workerd/io/trace-test.c++ +++ b/src/workerd/io/trace-test.c++ @@ -176,7 +176,6 @@ KJ_TEST("Read/Write FetchEventInfo works") { KJ_ASSERT(info2.headers.size() == 1); KJ_ASSERT(info2.headers[0].name == "foo"_kj); KJ_ASSERT(info2.headers[0].value == "bar"_kj); - KJ_ASSERT(info2.bodySize == kj::none); // Default value (unknown) FetchEventInfo info3 = info.clone(); KJ_ASSERT(info3.method == kj::HttpMethod::GET); @@ -185,57 +184,6 @@ KJ_TEST("Read/Write FetchEventInfo works") { KJ_ASSERT(info3.headers.size() == 1); KJ_ASSERT(info3.headers[0].name == "foo"_kj); KJ_ASSERT(info3.headers[0].value == "bar"_kj); - KJ_ASSERT(info3.bodySize == kj::none); // Default value (unknown) -} - -KJ_TEST("Read/Write FetchEventInfo with bodySize works") { - capnp::MallocMessageBuilder builder; - auto fetchInfoBuilder = builder.initRoot(); - - kj::Vector headers; - headers.add(FetchEventInfo::Header(kj::str("content-type"), kj::str("application/json"))); - - kj::Maybe bodySize = 12345; - FetchEventInfo info(kj::HttpMethod::POST, kj::str("https://example.com/api"), kj::str("{}"), - headers.releaseAsArray(), bodySize); - - info.copyTo(fetchInfoBuilder); - - auto reader = fetchInfoBuilder.asReader(); - - FetchEventInfo info2(reader); - KJ_ASSERT(info2.method == kj::HttpMethod::POST); - KJ_ASSERT(info2.url == "https://example.com/api"_kj); - KJ_ASSERT(KJ_ASSERT_NONNULL(info2.bodySize) == 12345); - - FetchEventInfo info3 = info.clone(); - KJ_ASSERT(info3.method == kj::HttpMethod::POST); - KJ_ASSERT(info3.url == "https://example.com/api"_kj); - KJ_ASSERT(KJ_ASSERT_NONNULL(info3.bodySize) == 12345); -} - -KJ_TEST("Read/Write FetchEventInfo with zero bodySize works") { - capnp::MallocMessageBuilder builder; - auto fetchInfoBuilder = builder.initRoot(); - - kj::Vector headers; - headers.add(FetchEventInfo::Header(kj::str("content-length"), kj::str("0"))); - - // Content-Length: 0 should be distinguishable from unknown - kj::Maybe bodySize = uint64_t{0}; - FetchEventInfo info(kj::HttpMethod::POST, kj::str("https://example.com/api"), kj::str("{}"), - headers.releaseAsArray(), bodySize); - - info.copyTo(fetchInfoBuilder); - - auto reader = fetchInfoBuilder.asReader(); - - FetchEventInfo info2(reader); - KJ_ASSERT(info2.method == kj::HttpMethod::POST); - KJ_ASSERT(KJ_ASSERT_NONNULL(info2.bodySize) == 0); // Known to be zero, not unknown - - FetchEventInfo info3 = info.clone(); - KJ_ASSERT(KJ_ASSERT_NONNULL(info3.bodySize) == 0); // Known to be zero, not unknown } KJ_TEST("Read/Write JsRpcEventInfo works") { @@ -378,9 +326,56 @@ KJ_TEST("Read/Write FetchResponseInfo works") { auto reader = infoBuilder.asReader(); FetchResponseInfo info2(reader); KJ_ASSERT(info2.statusCode == 123); + KJ_ASSERT(info2.bodySize == kj::none); // Default value (unknown) + KJ_ASSERT(info2.requestBodySize == kj::none); // Default value (unknown) FetchResponseInfo info3 = info.clone(); KJ_ASSERT(info3.statusCode == 123); + KJ_ASSERT(info3.bodySize == kj::none); // Default value (unknown) + KJ_ASSERT(info3.requestBodySize == kj::none); // Default value (unknown) +} + +KJ_TEST("Read/Write FetchResponseInfo with requestBodySize works") { + capnp::MallocMessageBuilder builder; + auto infoBuilder = builder.initRoot(); + + kj::Maybe responseBodySize = 54321; + kj::Maybe requestBodySize = 12345; + FetchResponseInfo info(200, responseBodySize, requestBodySize); + info.copyTo(infoBuilder); + + auto reader = infoBuilder.asReader(); + FetchResponseInfo info2(reader); + KJ_ASSERT(info2.statusCode == 200); + KJ_ASSERT(KJ_ASSERT_NONNULL(info2.bodySize) == 54321); + KJ_ASSERT(KJ_ASSERT_NONNULL(info2.requestBodySize) == 12345); + + FetchResponseInfo info3 = info.clone(); + KJ_ASSERT(info3.statusCode == 200); + KJ_ASSERT(KJ_ASSERT_NONNULL(info3.bodySize) == 54321); + KJ_ASSERT(KJ_ASSERT_NONNULL(info3.requestBodySize) == 12345); +} + +KJ_TEST("Read/Write FetchResponseInfo with zero body sizes works") { + capnp::MallocMessageBuilder builder; + auto infoBuilder = builder.initRoot(); + + // Zero body sizes should be distinguishable from unknown + kj::Maybe responseBodySize = uint64_t{0}; + kj::Maybe requestBodySize = uint64_t{0}; + FetchResponseInfo info(204, responseBodySize, requestBodySize); + info.copyTo(infoBuilder); + + auto reader = infoBuilder.asReader(); + FetchResponseInfo info2(reader); + KJ_ASSERT(info2.statusCode == 204); + KJ_ASSERT(KJ_ASSERT_NONNULL(info2.bodySize) == 0); // Known to be zero, not unknown + KJ_ASSERT(KJ_ASSERT_NONNULL(info2.requestBodySize) == 0); // Known to be zero, not unknown + + FetchResponseInfo info3 = info.clone(); + KJ_ASSERT(info3.statusCode == 204); + KJ_ASSERT(KJ_ASSERT_NONNULL(info3.bodySize) == 0); // Known to be zero, not unknown + KJ_ASSERT(KJ_ASSERT_NONNULL(info3.requestBodySize) == 0); // Known to be zero, not unknown } KJ_TEST("Read/Write DiagnosticChannelEvent works") { @@ -469,20 +464,23 @@ KJ_TEST("Read/Write Return works") { Return info2(reader); auto& fetchInfo2 = KJ_ASSERT_NONNULL(info2.info); KJ_ASSERT(fetchInfo2.statusCode == 123); - KJ_ASSERT(fetchInfo2.bodySize == kj::none); // Default value (unknown) + KJ_ASSERT(fetchInfo2.bodySize == kj::none); // Default value (unknown) + KJ_ASSERT(fetchInfo2.requestBodySize == kj::none); // Default value (unknown) Return info3 = info.clone(); auto& fetchInfo3 = KJ_ASSERT_NONNULL(info3.info); KJ_ASSERT(fetchInfo3.statusCode == 123); - KJ_ASSERT(fetchInfo3.bodySize == kj::none); // Default value (unknown) + KJ_ASSERT(fetchInfo3.bodySize == kj::none); // Default value (unknown) + KJ_ASSERT(fetchInfo3.requestBodySize == kj::none); // Default value (unknown) } -KJ_TEST("Read/Write Return with bodySize works") { +KJ_TEST("Read/Write Return with body sizes works") { capnp::MallocMessageBuilder builder; auto infoBuilder = builder.initRoot(); - kj::Maybe bodySize = 54321; - FetchResponseInfo fetchInfo(200, bodySize); + kj::Maybe responseBodySize = 54321; + kj::Maybe requestBodySize = 12345; + FetchResponseInfo fetchInfo(200, responseBodySize, requestBodySize); Return info(kj::mv(fetchInfo)); info.copyTo(infoBuilder); @@ -491,20 +489,23 @@ KJ_TEST("Read/Write Return with bodySize works") { auto& fetchInfo2 = KJ_ASSERT_NONNULL(info2.info); KJ_ASSERT(fetchInfo2.statusCode == 200); KJ_ASSERT(KJ_ASSERT_NONNULL(fetchInfo2.bodySize) == 54321); + KJ_ASSERT(KJ_ASSERT_NONNULL(fetchInfo2.requestBodySize) == 12345); Return info3 = info.clone(); auto& fetchInfo3 = KJ_ASSERT_NONNULL(info3.info); KJ_ASSERT(fetchInfo3.statusCode == 200); KJ_ASSERT(KJ_ASSERT_NONNULL(fetchInfo3.bodySize) == 54321); + KJ_ASSERT(KJ_ASSERT_NONNULL(fetchInfo3.requestBodySize) == 12345); } -KJ_TEST("Read/Write Return with zero bodySize works") { +KJ_TEST("Read/Write Return with zero body sizes works") { capnp::MallocMessageBuilder builder; auto infoBuilder = builder.initRoot(); - // Zero body size should be distinguishable from unknown - kj::Maybe bodySize = uint64_t{0}; - FetchResponseInfo fetchInfo(204, bodySize); + // Zero body sizes should be distinguishable from unknown + kj::Maybe responseBodySize = uint64_t{0}; + kj::Maybe requestBodySize = uint64_t{0}; + FetchResponseInfo fetchInfo(204, responseBodySize, requestBodySize); Return info(kj::mv(fetchInfo)); info.copyTo(infoBuilder); @@ -512,12 +513,14 @@ KJ_TEST("Read/Write Return with zero bodySize works") { Return info2(reader); auto& fetchInfo2 = KJ_ASSERT_NONNULL(info2.info); KJ_ASSERT(fetchInfo2.statusCode == 204); - KJ_ASSERT(KJ_ASSERT_NONNULL(fetchInfo2.bodySize) == 0); // Known to be zero, not unknown + KJ_ASSERT(KJ_ASSERT_NONNULL(fetchInfo2.bodySize) == 0); // Known to be zero, not unknown + KJ_ASSERT(KJ_ASSERT_NONNULL(fetchInfo2.requestBodySize) == 0); // Known to be zero, not unknown Return info3 = info.clone(); auto& fetchInfo3 = KJ_ASSERT_NONNULL(info3.info); KJ_ASSERT(fetchInfo3.statusCode == 204); - KJ_ASSERT(KJ_ASSERT_NONNULL(fetchInfo3.bodySize) == 0); // Known to be zero, not unknown + KJ_ASSERT(KJ_ASSERT_NONNULL(fetchInfo3.bodySize) == 0); // Known to be zero, not unknown + KJ_ASSERT(KJ_ASSERT_NONNULL(fetchInfo3.requestBodySize) == 0); // Known to be zero, not unknown } KJ_TEST("Read/Write SpanOpen works") { diff --git a/src/workerd/io/trace.c++ b/src/workerd/io/trace.c++ index 6b5e7591325..72de377f791 100644 --- a/src/workerd/io/trace.c++ +++ b/src/workerd/io/trace.c++ @@ -323,25 +323,19 @@ static kj::HttpMethod validateMethod(capnp::HttpMethod method) { } // namespace -FetchEventInfo::FetchEventInfo(kj::HttpMethod method, - kj::String url, - kj::String cfJson, - kj::Array
headers, - kj::Maybe bodySize) +FetchEventInfo::FetchEventInfo( + kj::HttpMethod method, kj::String url, kj::String cfJson, kj::Array
headers) : method(method), url(kj::mv(url)), cfJson(kj::mv(cfJson)), - headers(kj::mv(headers)), - bodySize(bodySize) {} + headers(kj::mv(headers)) {} FetchEventInfo::FetchEventInfo(rpc::Trace::FetchEventInfo::Reader reader) : method(validateMethod(reader.getMethod())), url(kj::str(reader.getUrl())), cfJson(kj::str(reader.getCfJson())) { - // Only set bodySize if hasBodySize is true - if (reader.getHasBodySize()) { - bodySize = reader.getBodySize(); - } + // Note: Request body size is now tracked in FetchResponseInfo, not here. + // The obsolete4/obsolete5 fields in the schema are ignored. kj::Vector
v; v.addAll(reader.getHeaders()); headers = v.releaseAsArray(); @@ -351,10 +345,7 @@ void FetchEventInfo::copyTo(rpc::Trace::FetchEventInfo::Builder builder) const { builder.setMethod(static_cast(method)); builder.setUrl(url); builder.setCfJson(cfJson); - KJ_IF_SOME(size, bodySize) { - builder.setBodySize(size); - builder.setHasBodySize(true); - } + // Note: Request body size is now tracked in FetchResponseInfo, not here. auto list = builder.initHeaders(headers.size()); for (auto i: kj::indices(headers)) { @@ -364,7 +355,7 @@ void FetchEventInfo::copyTo(rpc::Trace::FetchEventInfo::Builder builder) const { FetchEventInfo FetchEventInfo::clone() const { return FetchEventInfo( - method, kj::str(url), kj::str(cfJson), KJ_MAP(h, headers) { return h.clone(); }, bodySize); + method, kj::str(url), kj::str(cfJson), KJ_MAP(h, headers) { return h.clone(); }); } kj::String FetchEventInfo::toString() const { @@ -607,9 +598,11 @@ HibernatableWebSocketEventInfo::Type HibernatableWebSocketEventInfo::readFrom( } } -FetchResponseInfo::FetchResponseInfo(uint16_t statusCode, kj::Maybe bodySize) +FetchResponseInfo::FetchResponseInfo( + uint16_t statusCode, kj::Maybe bodySize, kj::Maybe requestBodySize) : statusCode(statusCode), - bodySize(bodySize) {} + bodySize(bodySize), + requestBodySize(requestBodySize) {} FetchResponseInfo::FetchResponseInfo(rpc::Trace::FetchResponseInfo::Reader reader) : statusCode(reader.getStatusCode()) { @@ -617,6 +610,10 @@ FetchResponseInfo::FetchResponseInfo(rpc::Trace::FetchResponseInfo::Reader reade if (reader.getHasBodySize()) { bodySize = reader.getBodySize(); } + // Only set requestBodySize if hasRequestBodySize is true + if (reader.getHasRequestBodySize()) { + requestBodySize = reader.getRequestBodySize(); + } } void FetchResponseInfo::copyTo(rpc::Trace::FetchResponseInfo::Builder builder) const { @@ -625,10 +622,14 @@ void FetchResponseInfo::copyTo(rpc::Trace::FetchResponseInfo::Builder builder) c builder.setBodySize(size); builder.setHasBodySize(true); } + KJ_IF_SOME(size, requestBodySize) { + builder.setRequestBodySize(size); + builder.setHasRequestBodySize(true); + } } FetchResponseInfo FetchResponseInfo::clone() const { - return FetchResponseInfo(statusCode, bodySize); + return FetchResponseInfo(statusCode, bodySize, requestBodySize); } Log::Log(kj::Date timestamp, LogLevel logLevel, kj::String message) diff --git a/src/workerd/io/trace.h b/src/workerd/io/trace.h index c3ac6dd1dad..ec7a06fc11f 100644 --- a/src/workerd/io/trace.h +++ b/src/workerd/io/trace.h @@ -309,11 +309,8 @@ kj::String KJ_STRINGIFY(const SpanContext& context); struct FetchEventInfo final { struct Header; - explicit FetchEventInfo(kj::HttpMethod method, - kj::String url, - kj::String cfJson, - kj::Array
headers, - kj::Maybe bodySize = kj::none); + explicit FetchEventInfo( + kj::HttpMethod method, kj::String url, kj::String cfJson, kj::Array
headers); FetchEventInfo(rpc::Trace::FetchEventInfo::Reader reader); FetchEventInfo(FetchEventInfo&&) = default; FetchEventInfo& operator=(FetchEventInfo&&) = default; @@ -344,7 +341,8 @@ struct FetchEventInfo final { // TODO(perf): It might be more efficient to store some sort of parsed JSON result instead? kj::String cfJson; kj::Array
headers; - kj::Maybe bodySize; // Request body size in bytes. kj::none if unknown. + // Note: Request body size is tracked in FetchResponseInfo, not here, because + // it's only known after the request body is fully consumed. void copyTo(rpc::Trace::FetchEventInfo::Builder builder) const; FetchEventInfo clone() const; @@ -488,14 +486,17 @@ struct CustomEventInfo final { // Describes a fetch response struct FetchResponseInfo final { - explicit FetchResponseInfo(uint16_t statusCode, kj::Maybe bodySize = kj::none); + explicit FetchResponseInfo(uint16_t statusCode, + kj::Maybe bodySize = kj::none, + kj::Maybe requestBodySize = kj::none); FetchResponseInfo(rpc::Trace::FetchResponseInfo::Reader reader); FetchResponseInfo(FetchResponseInfo&&) = default; FetchResponseInfo& operator=(FetchResponseInfo&&) = default; KJ_DISALLOW_COPY(FetchResponseInfo); uint16_t statusCode; - kj::Maybe bodySize; // Response body size in bytes. kj::none if unknown. + kj::Maybe bodySize; // Response body size in bytes. kj::none if unknown. + kj::Maybe requestBodySize; // Request body size in bytes. kj::none if unknown. void copyTo(rpc::Trace::FetchResponseInfo::Builder builder) const; FetchResponseInfo clone() const; diff --git a/src/workerd/io/worker-entrypoint.c++ b/src/workerd/io/worker-entrypoint.c++ index dba5e865e53..dbf5a37e040 100644 --- a/src/workerd/io/worker-entrypoint.c++ +++ b/src/workerd/io/worker-entrypoint.c++ @@ -26,8 +26,9 @@ namespace workerd { namespace { -// Forward declaration for deferred body size tracking +// Forward declarations for deferred body size tracking struct ResponseBodyByteCounter; +struct RequestBodyByteCounter; // Wrapper around a Worker that handles receiving a new event from the outside. In particular, // this handles: @@ -104,6 +105,7 @@ class WorkerEntrypoint final: public WorkerInterface { // For deferred trace reporting after response body streaming completes kj::Maybe> traceByteCounter; + kj::Maybe> traceRequestByteCounter; kj::Maybe deferredWorkerTracer; uint deferredHttpResponseStatus = 0; @@ -149,6 +151,19 @@ struct ResponseBodyByteCounter: public kj::Refcounted { } }; +// A refcounted byte counter for tracking request body bytes read. +struct RequestBodyByteCounter: public kj::Refcounted { + uint64_t bytesRead = 0; + + void add(size_t bytes) { + bytesRead += bytes; + } + + uint64_t get() const { + return bytesRead; + } +}; + // Wraps an AsyncOutputStream to count bytes written. Used to track actual // response body size for trace events (as opposed to Content-Length header). // Note: This wrapper intentionally doesn't implement tryPumpFrom() optimization @@ -185,6 +200,37 @@ class ByteCountingOutputStream final: public kj::AsyncOutputStream { kj::Own counter; }; +// Wraps an AsyncInputStream to count bytes read. Used to track actual +// request body size for trace events. +class ByteCountingInputStream final: public kj::AsyncInputStream { + public: + ByteCountingInputStream(kj::AsyncInputStream& inner, kj::Own counter) + : inner(inner), + counter(kj::mv(counter)) {} + + kj::Promise tryRead(void* buffer, size_t minBytes, size_t maxBytes) override { + return inner.tryRead(buffer, minBytes, maxBytes).then([this](size_t bytesRead) { + counter->add(bytesRead); + return bytesRead; + }); + } + + kj::Maybe tryGetLength() override { + return inner.tryGetLength(); + } + + kj::Promise pumpTo(kj::AsyncOutputStream& output, uint64_t amount) override { + // We can't use the optimized pumpTo from the inner stream because we need + // to count the bytes. Instead, we use the default implementation which + // calls tryRead() in a loop, allowing us to count each chunk. + return kj::AsyncInputStream::pumpTo(output, amount); + } + + private: + kj::AsyncInputStream& inner; + kj::Own counter; +}; + // Simple wrapper around `HttpService::Response` to let us know if the response was sent // already. Also optionally wraps the output stream with byte counting for trace events // when tracing is enabled. @@ -375,21 +421,11 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, return tracing::FetchEventInfo::Header(kj::mv(entry.key), kj::strArray(entry.value, ", ")); }; - // Extract request body size from Content-Length header if present. - // TODO(someday): Track actual bytes consumed from request body stream instead of - // relying on Content-Length header. This is less critical than response body size - // since request bodies typically have accurate Content-Length. - // bodySize is kj::none if no Content-Length header was present (unknown size). - kj::Maybe bodySize; - KJ_IF_SOME(contentLength, headers.get(kj::HttpHeaderId::CONTENT_LENGTH)) { - KJ_IF_SOME(parsed, contentLength.tryParseAs()) { - bodySize = parsed; - } - } + // Note: Request body size is tracked separately and reported in FetchResponseInfo + // after the body is fully consumed, not here in FetchEventInfo. t.setEventInfo(*incomingRequest, - tracing::FetchEventInfo( - method, kj::str(url), kj::mv(cfJson), kj::mv(traceHeadersArray), bodySize)); + tracing::FetchEventInfo(method, kj::str(url), kj::mv(cfJson), kj::mv(traceHeadersArray))); workerTracer = t; } @@ -401,8 +437,24 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, TRACE_EVENT_BEGIN("workerd", "WorkerEntrypoint::request() waiting on context", PERFETTO_TRACK_FROM_POINTER(&context), PERFETTO_FLOW_FROM_POINTER(this)); + // Create request body byte counter if tracing is enabled. + // We wrap the request body stream to count actual bytes consumed. + kj::Maybe> wrappedRequestBody; + if (hasTracer) { + auto counter = kj::refcounted(); + traceRequestByteCounter = kj::addRef(*counter); + wrappedRequestBody = kj::heap(requestBody, kj::mv(counter)); + } + + // Get reference to the appropriate request body stream to pass to handler. + // If tracing is enabled, use the wrapped stream; otherwise use the original. + kj::AsyncInputStream& requestBodyForHandler = + wrappedRequestBody.map([](auto& wrapped) -> kj::AsyncInputStream& { + return *wrapped; + }).orDefault(requestBody); + return context - .run([this, &context, method, url, &headers, &requestBody, + .run([this, &context, method, url, &headers, &requestBodyForHandler, &metrics = incomingRequest->getMetrics(), &wrappedResponse = *wrappedResponse, entrypointName = entrypointName](Worker::Lock& lock) mutable { TRACE_EVENT_END("workerd", PERFETTO_TRACK_FROM_POINTER(&context)); @@ -421,8 +473,8 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, ->getSignal()); } - return lock.getGlobalScope().request(method, url, headers, requestBody, wrappedResponse, - cfBlobJson, lock, + return lock.getGlobalScope().request(method, url, headers, requestBodyForHandler, + wrappedResponse, cfBlobJson, lock, lock.getExportedHandler(entrypointName, kj::mv(props), context.getActor()), kj::mv(signal)); }) .then([this, &wrappedResponse = *wrappedResponse, workerTracer]( @@ -494,17 +546,22 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, KJ_IF_SOME(p, proxyTask) { return p .then([this]() { - // proxyTask completed successfully - report actual body size to tracer. - // We deferred setReturn() to here so we can report actual bytes written - // instead of the Content-Length header value. + // proxyTask completed successfully - report actual body sizes to tracer. + // We deferred setReturn() to here so we can report actual bytes written/read + // instead of Content-Length header values. KJ_IF_SOME(t, deferredWorkerTracer) { if (deferredHttpResponseStatus != 0) { - kj::Maybe actualBodySize; + kj::Maybe responseBodySize; KJ_IF_SOME(counter, traceByteCounter) { - actualBodySize = counter->get(); + responseBodySize = counter->get(); + } + kj::Maybe requestBodySize; + KJ_IF_SOME(counter, traceRequestByteCounter) { + requestBodySize = counter->get(); } - t.setReturn( - kj::none, tracing::FetchResponseInfo(deferredHttpResponseStatus, actualBodySize)); + t.setReturn(kj::none, + tracing::FetchResponseInfo( + deferredHttpResponseStatus, responseBodySize, requestBodySize)); } else { t.setReturn(kj::none); } @@ -512,25 +569,32 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, // Clean up deferred trace state deferredWorkerTracer = kj::none; traceByteCounter = kj::none; + traceRequestByteCounter = kj::none; }).catch_([this, metrics = kj::mv(metrics)](kj::Exception&& e) mutable -> kj::Promise { // Clean up deferred trace state on failure too deferredWorkerTracer = kj::none; traceByteCounter = kj::none; + traceRequestByteCounter = kj::none; metrics->reportFailure(e, RequestObserver::FailureSource::DEFERRED_PROXY); return kj::mv(e); }); } else { // No proxyTask means no streaming body - report trace now if we have deferred info. - // bodySize is kj::none since we don't have the byte counter to track actual size. KJ_IF_SOME(t, deferredWorkerTracer) { if (deferredHttpResponseStatus != 0) { - t.setReturn(kj::none, tracing::FetchResponseInfo(deferredHttpResponseStatus)); + kj::Maybe requestBodySize; + KJ_IF_SOME(counter, traceRequestByteCounter) { + requestBodySize = counter->get(); + } + t.setReturn(kj::none, + tracing::FetchResponseInfo(deferredHttpResponseStatus, kj::none, requestBodySize)); } else { t.setReturn(kj::none); } } deferredWorkerTracer = kj::none; traceByteCounter = kj::none; + traceRequestByteCounter = kj::none; return kj::READY_NOW; } }) @@ -538,7 +602,8 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, // If we're being cancelled, we need to make sure `proxyTask` gets canceled. proxyTask = kj::none; })) - .catch_([this, wrappedResponse = kj::mv(wrappedResponse), isActor, method, url, &headers, + .catch_([this, wrappedResponse = kj::mv(wrappedResponse), + wrappedRequestBody = kj::mv(wrappedRequestBody), isActor, method, url, &headers, &requestBody, metrics = kj::mv(metricsForCatch), workerTracer](kj::Exception&& exception) mutable -> kj::Promise { // Don't return errors to end user. diff --git a/src/workerd/io/worker-interface.capnp b/src/workerd/io/worker-interface.capnp index 68d2a942898..8166c8de2db 100644 --- a/src/workerd/io/worker-interface.capnp +++ b/src/workerd/io/worker-interface.capnp @@ -108,10 +108,10 @@ struct Trace @0x8e8d911203762d34 { name @0 :Text; value @1 :Text; } - bodySize @4 :UInt64; - # Request body size in bytes. Only valid if hasBodySize is true. - hasBodySize @5 :Bool; - # True if bodySize contains a valid value (from Content-Length header). + # Fields @4 and @5 were request body size fields that have been moved to + # FetchResponseInfo where they can be populated after the body is consumed. + obsolete4 @4 :UInt64; + obsolete5 @5 :Bool; } struct JsRpcEventInfo { @@ -166,6 +166,11 @@ struct Trace @0x8e8d911203762d34 { # Response body size in bytes. Only valid if hasBodySize is true. hasBodySize @2 :Bool; # True if bodySize contains a valid value (actual bytes written). + requestBodySize @3 :UInt64; + # Request body size in bytes. Only valid if hasRequestBodySize is true. + # This is actual bytes consumed, not Content-Length header. + hasRequestBodySize @4 :Bool; + # True if requestBodySize contains a valid value. } cpuTime @10 :UInt64; From 16b8dba834c2b822d6f1c96d43125ba245797ee2 Mon Sep 17 00:00:00 2001 From: Luca Steeb Date: Thu, 22 Jan 2026 20:53:41 +0000 Subject: [PATCH 08/10] Move body sizes from return event to outcome event Per HTTP spec, body size is only definitively known after the body has been fully transmitted. The Outcome event is emitted after all work completes (including body streaming), making it the correct place to report body sizes. Changes: - Remove body sizes from FetchResponseInfo (return event) - Add responseBodySize and requestBodySize to Outcome struct - Add setBodySizes() method to tracer for deferred body size reporting - Update streaming tail worker JS serialization for new schema - Update buffered tail worker API to read body sizes from Trace object Co-Authored-By: Claude Opus 4.5 --- src/workerd/api/tests/tail-worker-test.js | 14 +- src/workerd/api/trace.c++ | 7 +- src/workerd/io/trace-stream.c++ | 26 ++-- src/workerd/io/trace-test.c++ | 156 ++++++++-------------- src/workerd/io/trace.c++ | 56 ++++---- src/workerd/io/trace.h | 28 ++-- src/workerd/io/tracer.c++ | 27 +++- src/workerd/io/tracer.h | 21 ++- src/workerd/io/worker-entrypoint.c++ | 42 +++--- src/workerd/io/worker-interface.capnp | 23 ++-- 10 files changed, 210 insertions(+), 190 deletions(-) diff --git a/src/workerd/api/tests/tail-worker-test.js b/src/workerd/api/tests/tail-worker-test.js index 5c32933a522..7798b8a7908 100644 --- a/src/workerd/api/tests/tail-worker-test.js +++ b/src/workerd/api/tests/tail-worker-test.js @@ -87,15 +87,15 @@ export const test = { // First event is emitted by the test() event, which allows us to get some coverage for span tracing. // Note: Span attributes use OpenTelemetry-style names (http.request.body.size, http.response.body.size) '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"custom"}}{"type":"spanOpen","name":"fetch","spanId":"0000000000000001"}{"type":"attributes","info":[{"name":"network.protocol.name","value":"http"},{"name":"network.protocol.version","value":"HTTP/1.1"},{"name":"http.request.method","value":"POST"},{"name":"url.full","value":"http://placeholder/body-length"},{"name":"http.request.body.size","value":"3"},{"name":"http.response.status_code","value":"200"},{"name":"http.response.body.size","value":"22"}]}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"fetch","spanId":"0000000000000002"}{"type":"attributes","info":[{"name":"network.protocol.name","value":"http"},{"name":"network.protocol.version","value":"HTTP/1.1"},{"name":"http.request.method","value":"POST"},{"name":"url.full","value":"http://placeholder/body-length"},{"name":"http.response.status_code","value":"200"},{"name":"http.response.body.size","value":"31"}]}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"scheduled","spanId":"0000000000000003"}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"scheduled","spanId":"0000000000000004"}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"fetch","spanId":"0000000000000005"}{"type":"attributes","info":[{"name":"network.protocol.name","value":"http"},{"name":"network.protocol.version","value":"HTTP/1.1"},{"name":"http.request.method","value":"POST"},{"name":"url.full","value":"http://placeholder/consume-body"},{"name":"http.request.body.size","value":"5"},{"name":"http.response.status_code","value":"200"},{"name":"http.response.body.size","value":"16"}]}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"fetch","spanId":"0000000000000006"}{"type":"attributes","info":[{"name":"network.protocol.name","value":"http"},{"name":"network.protocol.version","value":"HTTP/1.1"},{"name":"http.request.method","value":"GET"},{"name":"url.full","value":"http://placeholder/streaming-response"},{"name":"http.response.status_code","value":"200"},{"name":"http.response.body.size","value":"12"}]}{"type":"spanClose","outcome":"ok"}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', - // Note: Request body size is now in the return event, not the onset event - '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"POST","url":"http://placeholder/body-length","headers":[]}}{"type":"return","info":{"type":"fetch","statusCode":200,"bodySize":22,"requestBodySize":3}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', - '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"POST","url":"http://placeholder/body-length","headers":[]}}{"type":"return","info":{"type":"fetch","statusCode":200,"bodySize":31,"requestBodySize":3}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', + // Note: Body sizes are now in the outcome event (per HTTP spec, body size is only known after body streaming completes) + '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"POST","url":"http://placeholder/body-length","headers":[]}}{"type":"return","info":{"type":"fetch","statusCode":200}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0,"responseBodySize":22,"requestBodySize":3}', + '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"POST","url":"http://placeholder/body-length","headers":[]}}{"type":"return","info":{"type":"fetch","statusCode":200}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0,"responseBodySize":31,"requestBodySize":3}', '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"scheduled","scheduledTime":"1970-01-01T00:00:00.000Z","cron":""}}{"type":"return"}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"scheduled","scheduledTime":"1970-01-01T00:00:00.000Z","cron":"* * * * 30"}}{"type":"return"}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', - // Test consume-body endpoint - request body size tracked after body consumed - '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"POST","url":"http://placeholder/consume-body","headers":[]}}{"type":"return","info":{"type":"fetch","statusCode":200,"bodySize":16,"requestBodySize":5}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', - // Test streaming-response endpoint - response body size tracked after streaming - '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"GET","url":"http://placeholder/streaming-response","headers":[]}}{"type":"return","info":{"type":"fetch","statusCode":200,"bodySize":12}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', + // Test consume-body endpoint - request body size tracked in outcome event + '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"POST","url":"http://placeholder/consume-body","headers":[]}}{"type":"return","info":{"type":"fetch","statusCode":200}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0,"responseBodySize":16,"requestBodySize":5}', + // Test streaming-response endpoint - response body size tracked in outcome event + '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"GET","url":"http://placeholder/streaming-response","headers":[]}}{"type":"return","info":{"type":"fetch","statusCode":200}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0,"responseBodySize":12}', '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","entrypoint":"cacheMode","scriptTags":[],"info":{"type":"custom"}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"GET","url":"http://placeholder/not-found","headers":[]}}{"type":"return","info":{"type":"fetch","statusCode":404}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"GET","url":"http://placeholder/web-socket","headers":[{"name":"upgrade","value":"websocket"}]}}{"type":"exception","name":"Error","message":"The Workers runtime canceled this request because it detected that your Worker\'s code had hung and would never generate a response. Refer to: https://developers.cloudflare.com/workers/observability/errors/"}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', diff --git a/src/workerd/api/trace.c++ b/src/workerd/api/trace.c++ index 1272a6d2d8b..dd6cf370c7c 100644 --- a/src/workerd/api/trace.c++ +++ b/src/workerd/api/trace.c++ @@ -369,8 +369,11 @@ jsg::Ref TraceItem::FetchEventInfo::Request: TraceItem::FetchEventInfo::Response::Response( const Trace& trace, const tracing::FetchResponseInfo& responseInfo) : status(responseInfo.statusCode), - bodySize(responseInfo.bodySize), - requestBodySize(responseInfo.requestBodySize) {} + // Body sizes are now stored on the Trace object (in Outcome), not FetchResponseInfo + // (in Return event). This is because body sizes are only known after body streaming + // completes, which happens after the return event. + bodySize(trace.responseBodySize), + requestBodySize(trace.requestBodySize) {} uint16_t TraceItem::FetchEventInfo::Response::getStatus() { return status; diff --git a/src/workerd/io/trace-stream.c++ b/src/workerd/io/trace-stream.c++ index 2e2caf8deb0..36c7f3d08e3 100644 --- a/src/workerd/io/trace-stream.c++ +++ b/src/workerd/io/trace-stream.c++ @@ -19,7 +19,7 @@ namespace { V(ALARM, "alarm") \ V(ATTRIBUTES, "attributes") \ V(BATCHSIZE, "batchSize") \ - V(BODYSIZE, "bodySize") \ + V(RESPONSEBODYSIZE, "responseBodySize") \ V(REQUESTBODYSIZE, "requestBodySize") \ V(CANCELED, "canceled") \ V(CHANNEL, "channel") \ @@ -180,14 +180,8 @@ jsg::JsValue ToJs(jsg::Lock& js, const FetchResponseInfo& info, StringCache& cac auto obj = js.obj(); obj.set(js, TYPE_STR, cache.get(js, FETCH_STR)); obj.set(js, STATUSCODE_STR, js.num(info.statusCode)); - // Include bodySize (response body) if it's known - KJ_IF_SOME(size, info.bodySize) { - obj.set(js, BODYSIZE_STR, js.num(static_cast(size))); - } - // Include requestBodySize if it's known - KJ_IF_SOME(size, info.requestBodySize) { - obj.set(js, REQUESTBODYSIZE_STR, js.num(static_cast(size))); - } + // Note: Body sizes are now in Outcome, not FetchResponseInfo, + // because they're only known after body streaming completes. return obj; } @@ -211,8 +205,8 @@ jsg::JsValue ToJs(jsg::Lock& js, const FetchEventInfo& info, StringCache& cache) js.arr(info.headers.asPtr(), [&cache, &ToJs](jsg::Lock& js, const auto& header) { return ToJs(js, header, cache); })); - // Note: Request body size is tracked in FetchResponseInfo, not here, - // because it's only known after the request body is fully consumed. + // Note: Body sizes are tracked in Outcome, not here, + // because they're only known after body streaming completes. return obj; } @@ -418,6 +412,16 @@ jsg::JsValue ToJs(jsg::Lock& js, const Outcome& outcome, StringCache& cache) { obj.set(js, CPUTIME_STR, js.num(cpuTime)); obj.set(js, WALLTIME_STR, js.num(wallTime)); + // Body sizes are included in Outcome because this is when streaming has + // definitively completed. Per HTTP spec, body size is only known after + // the body has been fully transmitted. + KJ_IF_SOME(size, outcome.responseBodySize) { + obj.set(js, RESPONSEBODYSIZE_STR, js.num(static_cast(size))); + } + KJ_IF_SOME(size, outcome.requestBodySize) { + obj.set(js, REQUESTBODYSIZE_STR, js.num(static_cast(size))); + } + return obj; } diff --git a/src/workerd/io/trace-test.c++ b/src/workerd/io/trace-test.c++ index 8d58cc2e865..fea5a51077f 100644 --- a/src/workerd/io/trace-test.c++ +++ b/src/workerd/io/trace-test.c++ @@ -320,62 +320,17 @@ KJ_TEST("Read/Write FetchResponseInfo works") { capnp::MallocMessageBuilder builder; auto infoBuilder = builder.initRoot(); + // FetchResponseInfo now only contains statusCode. + // Body sizes have been moved to Outcome where they can be populated after body streaming completes. FetchResponseInfo info(123); info.copyTo(infoBuilder); auto reader = infoBuilder.asReader(); FetchResponseInfo info2(reader); KJ_ASSERT(info2.statusCode == 123); - KJ_ASSERT(info2.bodySize == kj::none); // Default value (unknown) - KJ_ASSERT(info2.requestBodySize == kj::none); // Default value (unknown) FetchResponseInfo info3 = info.clone(); KJ_ASSERT(info3.statusCode == 123); - KJ_ASSERT(info3.bodySize == kj::none); // Default value (unknown) - KJ_ASSERT(info3.requestBodySize == kj::none); // Default value (unknown) -} - -KJ_TEST("Read/Write FetchResponseInfo with requestBodySize works") { - capnp::MallocMessageBuilder builder; - auto infoBuilder = builder.initRoot(); - - kj::Maybe responseBodySize = 54321; - kj::Maybe requestBodySize = 12345; - FetchResponseInfo info(200, responseBodySize, requestBodySize); - info.copyTo(infoBuilder); - - auto reader = infoBuilder.asReader(); - FetchResponseInfo info2(reader); - KJ_ASSERT(info2.statusCode == 200); - KJ_ASSERT(KJ_ASSERT_NONNULL(info2.bodySize) == 54321); - KJ_ASSERT(KJ_ASSERT_NONNULL(info2.requestBodySize) == 12345); - - FetchResponseInfo info3 = info.clone(); - KJ_ASSERT(info3.statusCode == 200); - KJ_ASSERT(KJ_ASSERT_NONNULL(info3.bodySize) == 54321); - KJ_ASSERT(KJ_ASSERT_NONNULL(info3.requestBodySize) == 12345); -} - -KJ_TEST("Read/Write FetchResponseInfo with zero body sizes works") { - capnp::MallocMessageBuilder builder; - auto infoBuilder = builder.initRoot(); - - // Zero body sizes should be distinguishable from unknown - kj::Maybe responseBodySize = uint64_t{0}; - kj::Maybe requestBodySize = uint64_t{0}; - FetchResponseInfo info(204, responseBodySize, requestBodySize); - info.copyTo(infoBuilder); - - auto reader = infoBuilder.asReader(); - FetchResponseInfo info2(reader); - KJ_ASSERT(info2.statusCode == 204); - KJ_ASSERT(KJ_ASSERT_NONNULL(info2.bodySize) == 0); // Known to be zero, not unknown - KJ_ASSERT(KJ_ASSERT_NONNULL(info2.requestBodySize) == 0); // Known to be zero, not unknown - - FetchResponseInfo info3 = info.clone(); - KJ_ASSERT(info3.statusCode == 204); - KJ_ASSERT(KJ_ASSERT_NONNULL(info3.bodySize) == 0); // Known to be zero, not unknown - KJ_ASSERT(KJ_ASSERT_NONNULL(info3.requestBodySize) == 0); // Known to be zero, not unknown } KJ_TEST("Read/Write DiagnosticChannelEvent works") { @@ -456,6 +411,8 @@ KJ_TEST("Read/Write Return works") { capnp::MallocMessageBuilder builder; auto infoBuilder = builder.initRoot(); + // FetchResponseInfo now only contains statusCode. + // Body sizes have been moved to Outcome where they can be populated after body streaming completes. FetchResponseInfo fetchInfo(123); Return info(kj::mv(fetchInfo)); info.copyTo(infoBuilder); @@ -464,63 +421,10 @@ KJ_TEST("Read/Write Return works") { Return info2(reader); auto& fetchInfo2 = KJ_ASSERT_NONNULL(info2.info); KJ_ASSERT(fetchInfo2.statusCode == 123); - KJ_ASSERT(fetchInfo2.bodySize == kj::none); // Default value (unknown) - KJ_ASSERT(fetchInfo2.requestBodySize == kj::none); // Default value (unknown) Return info3 = info.clone(); auto& fetchInfo3 = KJ_ASSERT_NONNULL(info3.info); KJ_ASSERT(fetchInfo3.statusCode == 123); - KJ_ASSERT(fetchInfo3.bodySize == kj::none); // Default value (unknown) - KJ_ASSERT(fetchInfo3.requestBodySize == kj::none); // Default value (unknown) -} - -KJ_TEST("Read/Write Return with body sizes works") { - capnp::MallocMessageBuilder builder; - auto infoBuilder = builder.initRoot(); - - kj::Maybe responseBodySize = 54321; - kj::Maybe requestBodySize = 12345; - FetchResponseInfo fetchInfo(200, responseBodySize, requestBodySize); - Return info(kj::mv(fetchInfo)); - info.copyTo(infoBuilder); - - auto reader = infoBuilder.asReader(); - Return info2(reader); - auto& fetchInfo2 = KJ_ASSERT_NONNULL(info2.info); - KJ_ASSERT(fetchInfo2.statusCode == 200); - KJ_ASSERT(KJ_ASSERT_NONNULL(fetchInfo2.bodySize) == 54321); - KJ_ASSERT(KJ_ASSERT_NONNULL(fetchInfo2.requestBodySize) == 12345); - - Return info3 = info.clone(); - auto& fetchInfo3 = KJ_ASSERT_NONNULL(info3.info); - KJ_ASSERT(fetchInfo3.statusCode == 200); - KJ_ASSERT(KJ_ASSERT_NONNULL(fetchInfo3.bodySize) == 54321); - KJ_ASSERT(KJ_ASSERT_NONNULL(fetchInfo3.requestBodySize) == 12345); -} - -KJ_TEST("Read/Write Return with zero body sizes works") { - capnp::MallocMessageBuilder builder; - auto infoBuilder = builder.initRoot(); - - // Zero body sizes should be distinguishable from unknown - kj::Maybe responseBodySize = uint64_t{0}; - kj::Maybe requestBodySize = uint64_t{0}; - FetchResponseInfo fetchInfo(204, responseBodySize, requestBodySize); - Return info(kj::mv(fetchInfo)); - info.copyTo(infoBuilder); - - auto reader = infoBuilder.asReader(); - Return info2(reader); - auto& fetchInfo2 = KJ_ASSERT_NONNULL(info2.info); - KJ_ASSERT(fetchInfo2.statusCode == 204); - KJ_ASSERT(KJ_ASSERT_NONNULL(fetchInfo2.bodySize) == 0); // Known to be zero, not unknown - KJ_ASSERT(KJ_ASSERT_NONNULL(fetchInfo2.requestBodySize) == 0); // Known to be zero, not unknown - - Return info3 = info.clone(); - auto& fetchInfo3 = KJ_ASSERT_NONNULL(info3.info); - KJ_ASSERT(fetchInfo3.statusCode == 204); - KJ_ASSERT(KJ_ASSERT_NONNULL(fetchInfo3.bodySize) == 0); // Known to be zero, not unknown - KJ_ASSERT(KJ_ASSERT_NONNULL(fetchInfo3.requestBodySize) == 0); // Known to be zero, not unknown } KJ_TEST("Read/Write SpanOpen works") { @@ -596,11 +500,63 @@ KJ_TEST("Read/Write Outcome works") { KJ_ASSERT(info2.outcome == EventOutcome::EXCEPTION); KJ_ASSERT(info2.wallTime == 2 * kj::MILLISECONDS); KJ_ASSERT(info2.cpuTime == 1 * kj::MILLISECONDS); + KJ_ASSERT(info2.responseBodySize == kj::none); // Default value (unknown) + KJ_ASSERT(info2.requestBodySize == kj::none); // Default value (unknown) Outcome info3 = info.clone(); KJ_ASSERT(info3.outcome == EventOutcome::EXCEPTION); KJ_ASSERT(info3.wallTime == 2 * kj::MILLISECONDS); KJ_ASSERT(info3.cpuTime == 1 * kj::MILLISECONDS); + KJ_ASSERT(info3.responseBodySize == kj::none); // Default value (unknown) + KJ_ASSERT(info3.requestBodySize == kj::none); // Default value (unknown) +} + +KJ_TEST("Read/Write Outcome with body sizes works") { + capnp::MallocMessageBuilder builder; + auto infoBuilder = builder.initRoot(); + + kj::Maybe responseBodySize = 54321; + kj::Maybe requestBodySize = 12345; + Outcome info(EventOutcome::OK, 1 * kj::MILLISECONDS, 2 * kj::MILLISECONDS, responseBodySize, + requestBodySize); + info.copyTo(infoBuilder); + + auto reader = infoBuilder.asReader(); + Outcome info2(reader); + KJ_ASSERT(info2.outcome == EventOutcome::OK); + KJ_ASSERT(info2.wallTime == 2 * kj::MILLISECONDS); + KJ_ASSERT(info2.cpuTime == 1 * kj::MILLISECONDS); + KJ_ASSERT(KJ_ASSERT_NONNULL(info2.responseBodySize) == 54321); + KJ_ASSERT(KJ_ASSERT_NONNULL(info2.requestBodySize) == 12345); + + Outcome info3 = info.clone(); + KJ_ASSERT(info3.outcome == EventOutcome::OK); + KJ_ASSERT(info3.wallTime == 2 * kj::MILLISECONDS); + KJ_ASSERT(info3.cpuTime == 1 * kj::MILLISECONDS); + KJ_ASSERT(KJ_ASSERT_NONNULL(info3.responseBodySize) == 54321); + KJ_ASSERT(KJ_ASSERT_NONNULL(info3.requestBodySize) == 12345); +} + +KJ_TEST("Read/Write Outcome with zero body sizes works") { + capnp::MallocMessageBuilder builder; + auto infoBuilder = builder.initRoot(); + + // Zero body sizes should be distinguishable from unknown + kj::Maybe responseBodySize = uint64_t{0}; + kj::Maybe requestBodySize = uint64_t{0}; + Outcome info(EventOutcome::OK, 1 * kj::MILLISECONDS, 2 * kj::MILLISECONDS, responseBodySize, + requestBodySize); + info.copyTo(infoBuilder); + + auto reader = infoBuilder.asReader(); + Outcome info2(reader); + KJ_ASSERT(info2.outcome == EventOutcome::OK); + KJ_ASSERT(KJ_ASSERT_NONNULL(info2.responseBodySize) == 0); // Known to be zero, not unknown + KJ_ASSERT(KJ_ASSERT_NONNULL(info2.requestBodySize) == 0); // Known to be zero, not unknown + + Outcome info3 = info.clone(); + KJ_ASSERT(KJ_ASSERT_NONNULL(info3.responseBodySize) == 0); // Known to be zero, not unknown + KJ_ASSERT(KJ_ASSERT_NONNULL(info3.requestBodySize) == 0); // Known to be zero, not unknown } KJ_TEST("Read/Write TailEvent works") { diff --git a/src/workerd/io/trace.c++ b/src/workerd/io/trace.c++ index 72de377f791..f87b19da21d 100644 --- a/src/workerd/io/trace.c++ +++ b/src/workerd/io/trace.c++ @@ -598,38 +598,17 @@ HibernatableWebSocketEventInfo::Type HibernatableWebSocketEventInfo::readFrom( } } -FetchResponseInfo::FetchResponseInfo( - uint16_t statusCode, kj::Maybe bodySize, kj::Maybe requestBodySize) - : statusCode(statusCode), - bodySize(bodySize), - requestBodySize(requestBodySize) {} +FetchResponseInfo::FetchResponseInfo(uint16_t statusCode): statusCode(statusCode) {} FetchResponseInfo::FetchResponseInfo(rpc::Trace::FetchResponseInfo::Reader reader) - : statusCode(reader.getStatusCode()) { - // Only set bodySize if hasBodySize is true - if (reader.getHasBodySize()) { - bodySize = reader.getBodySize(); - } - // Only set requestBodySize if hasRequestBodySize is true - if (reader.getHasRequestBodySize()) { - requestBodySize = reader.getRequestBodySize(); - } -} + : statusCode(reader.getStatusCode()) {} void FetchResponseInfo::copyTo(rpc::Trace::FetchResponseInfo::Builder builder) const { builder.setStatusCode(statusCode); - KJ_IF_SOME(size, bodySize) { - builder.setBodySize(size); - builder.setHasBodySize(true); - } - KJ_IF_SOME(size, requestBodySize) { - builder.setRequestBodySize(size); - builder.setHasRequestBodySize(true); - } } FetchResponseInfo FetchResponseInfo::clone() const { - return FetchResponseInfo(statusCode, bodySize, requestBodySize); + return FetchResponseInfo(statusCode); } Log::Log(kj::Date timestamp, LogLevel logLevel, kj::String message) @@ -1304,24 +1283,45 @@ Onset Onset::clone() const { KJ_MAP(attr, attributes) { return attr.clone(); }); } -Outcome::Outcome(EventOutcome outcome, kj::Duration cpuTime, kj::Duration wallTime) +Outcome::Outcome(EventOutcome outcome, + kj::Duration cpuTime, + kj::Duration wallTime, + kj::Maybe responseBodySize, + kj::Maybe requestBodySize) : outcome(outcome), cpuTime(cpuTime), - wallTime(wallTime) {} + wallTime(wallTime), + responseBodySize(responseBodySize), + requestBodySize(requestBodySize) {} Outcome::Outcome(rpc::Trace::Outcome::Reader reader) : outcome(reader.getOutcome()), cpuTime(reader.getCpuTime() * kj::MILLISECONDS), - wallTime(reader.getWallTime() * kj::MILLISECONDS) {} + wallTime(reader.getWallTime() * kj::MILLISECONDS) { + if (reader.getHasResponseBodySize()) { + responseBodySize = reader.getResponseBodySize(); + } + if (reader.getHasRequestBodySize()) { + requestBodySize = reader.getRequestBodySize(); + } +} void Outcome::copyTo(rpc::Trace::Outcome::Builder builder) const { builder.setOutcome(outcome); builder.setCpuTime(cpuTime / kj::MILLISECONDS); builder.setWallTime(wallTime / kj::MILLISECONDS); + KJ_IF_SOME(size, responseBodySize) { + builder.setResponseBodySize(size); + builder.setHasResponseBodySize(true); + } + KJ_IF_SOME(size, requestBodySize) { + builder.setRequestBodySize(size); + builder.setHasRequestBodySize(true); + } } Outcome Outcome::clone() const { - return Outcome(outcome, cpuTime, wallTime); + return Outcome(outcome, cpuTime, wallTime, responseBodySize, requestBodySize); } TailEvent::TailEvent( diff --git a/src/workerd/io/trace.h b/src/workerd/io/trace.h index ec7a06fc11f..4a2cd9fe053 100644 --- a/src/workerd/io/trace.h +++ b/src/workerd/io/trace.h @@ -341,8 +341,8 @@ struct FetchEventInfo final { // TODO(perf): It might be more efficient to store some sort of parsed JSON result instead? kj::String cfJson; kj::Array
headers; - // Note: Request body size is tracked in FetchResponseInfo, not here, because - // it's only known after the request body is fully consumed. + // Note: Body sizes are tracked in Outcome, not here, because + // they're only known after body streaming completes. void copyTo(rpc::Trace::FetchEventInfo::Builder builder) const; FetchEventInfo clone() const; @@ -486,17 +486,16 @@ struct CustomEventInfo final { // Describes a fetch response struct FetchResponseInfo final { - explicit FetchResponseInfo(uint16_t statusCode, - kj::Maybe bodySize = kj::none, - kj::Maybe requestBodySize = kj::none); + explicit FetchResponseInfo(uint16_t statusCode); FetchResponseInfo(rpc::Trace::FetchResponseInfo::Reader reader); FetchResponseInfo(FetchResponseInfo&&) = default; FetchResponseInfo& operator=(FetchResponseInfo&&) = default; KJ_DISALLOW_COPY(FetchResponseInfo); uint16_t statusCode; - kj::Maybe bodySize; // Response body size in bytes. kj::none if unknown. - kj::Maybe requestBodySize; // Request body size in bytes. kj::none if unknown. + // Body sizes have been moved to Outcome where they can be populated after + // body streaming completes. Per HTTP spec, body size is only known after + // the body has been fully transmitted. void copyTo(rpc::Trace::FetchResponseInfo::Builder builder) const; FetchResponseInfo clone() const; @@ -741,7 +740,11 @@ Onset::Info readOnsetInfo(const rpc::Trace::Onset::Info::Reader& info); void writeOnsetInfo(const tracing::Onset::Info& info, rpc::Trace::Onset::Info::Builder& builder); struct Outcome final { - explicit Outcome(EventOutcome outcome, kj::Duration cpuTime, kj::Duration wallTime); + explicit Outcome(EventOutcome outcome, + kj::Duration cpuTime, + kj::Duration wallTime, + kj::Maybe responseBodySize = kj::none, + kj::Maybe requestBodySize = kj::none); Outcome(rpc::Trace::Outcome::Reader reader); Outcome(Outcome&&) = default; Outcome& operator=(Outcome&&) = default; @@ -750,6 +753,11 @@ struct Outcome final { EventOutcome outcome = EventOutcome::OK; kj::Duration cpuTime; kj::Duration wallTime; + // Body sizes are reported in Outcome because this is when streaming has + // definitively completed. Per HTTP spec, body size is only known after + // the body has been fully transmitted. + kj::Maybe responseBodySize; // Response body size in bytes. kj::none if unknown. + kj::Maybe requestBodySize; // Request body size in bytes. kj::none if unknown. void copyTo(rpc::Trace::Outcome::Builder builder) const; Outcome clone() const; @@ -875,6 +883,10 @@ class Trace final: public kj::Refcounted { kj::Duration cpuTime; kj::Duration wallTime; + // Body sizes are stored here for the Outcome event. They're only known after + // body streaming completes, which is why they're separate from FetchResponseInfo. + kj::Maybe responseBodySize; + kj::Maybe requestBodySize; bool truncated = false; bool exceededLogLimit = false; diff --git a/src/workerd/io/tracer.c++ b/src/workerd/io/tracer.c++ index b11314a23d5..002d63cb602 100644 --- a/src/workerd/io/tracer.c++ +++ b/src/workerd/io/tracer.c++ @@ -57,11 +57,14 @@ WorkerTracer::~WorkerTracer() noexcept(false) { } if (isPredictableModeForTest()) { writer->report(spanContext, - tracing::Outcome(trace->outcome, 0 * kj::MILLISECONDS, 0 * kj::MILLISECONDS), + tracing::Outcome(trace->outcome, 0 * kj::MILLISECONDS, 0 * kj::MILLISECONDS, + trace->responseBodySize, trace->requestBodySize), completeTime); } else { writer->report(spanContext, - tracing::Outcome(trace->outcome, trace->cpuTime, trace->wallTime), completeTime); + tracing::Outcome(trace->outcome, trace->cpuTime, trace->wallTime, + trace->responseBodySize, trace->requestBodySize), + completeTime); } } else if (!markedUnused) { // If no span context is available, we have a streaming tail worker set up but shut down the @@ -345,10 +348,22 @@ void WorkerTracer::setEventInfoInternal( } } -void WorkerTracer::setOutcome(EventOutcome outcome, kj::Duration cpuTime, kj::Duration wallTime) { +void WorkerTracer::setOutcome(EventOutcome outcome, + kj::Duration cpuTime, + kj::Duration wallTime, + kj::Maybe responseBodySize, + kj::Maybe requestBodySize) { trace->outcome = outcome; trace->cpuTime = cpuTime; trace->wallTime = wallTime; + // Body sizes can come from parameters or from pre-set values via setBodySizes(). + // Parameters take precedence if provided. + if (responseBodySize != kj::none) { + trace->responseBodySize = responseBodySize; + } + if (requestBodySize != kj::none) { + trace->requestBodySize = requestBodySize; + } // Defer reporting the actual outcome event to the WorkerTracer destructor: The outcome is // reported when the metrics request is deallocated, but with ctx.waitUntil() there might be spans @@ -359,6 +374,12 @@ void WorkerTracer::setOutcome(EventOutcome outcome, kj::Duration cpuTime, kj::Du // fixed size. } +void WorkerTracer::setBodySizes( + kj::Maybe responseBodySize, kj::Maybe requestBodySize) { + trace->responseBodySize = responseBodySize; + trace->requestBodySize = requestBodySize; +} + void WorkerTracer::recordTimestamp(kj::Date timestamp) { if (completeTime == kj::UNIX_EPOCH) { completeTime = timestamp; diff --git a/src/workerd/io/tracer.h b/src/workerd/io/tracer.h index cc1efefc14b..e23b99d7f9b 100644 --- a/src/workerd/io/tracer.h +++ b/src/workerd/io/tracer.h @@ -58,7 +58,18 @@ class BaseTracer: public kj::Refcounted { // Reports the outcome event of the worker invocation. For Streaming Tail Worker, this will be the // final event, causing the stream to terminate. - virtual void setOutcome(EventOutcome outcome, kj::Duration cpuTime, kj::Duration wallTime) = 0; + // Body sizes can be passed directly here, or pre-set via setBodySizes(). + virtual void setOutcome(EventOutcome outcome, + kj::Duration cpuTime, + kj::Duration wallTime, + kj::Maybe responseBodySize = kj::none, + kj::Maybe requestBodySize = kj::none) = 0; + + // Pre-sets body sizes to be included in the Outcome event when setOutcome is called. + // This allows body sizes to be set from worker-entrypoint.c++ when proxyTask completes, + // before setOutcome is called from the RequestObserver destructor. + virtual void setBodySizes( + kj::Maybe responseBodySize, kj::Maybe requestBodySize) = 0; // Report time as seen from the incoming Request when the request is complete, since it will not // be available afterwards. @@ -146,7 +157,13 @@ class WorkerTracer final: public BaseTracer { void setEventInfoInternal( const tracing::InvocationSpanContext& context, kj::Date timestamp, tracing::EventInfo&& info); - void setOutcome(EventOutcome outcome, kj::Duration cpuTime, kj::Duration wallTime) override; + void setOutcome(EventOutcome outcome, + kj::Duration cpuTime, + kj::Duration wallTime, + kj::Maybe responseBodySize = kj::none, + kj::Maybe requestBodySize = kj::none) override; + void setBodySizes( + kj::Maybe responseBodySize, kj::Maybe requestBodySize) override; virtual void recordTimestamp(kj::Date timestamp) override; // Set a worker-level tag/attribute to be provided in the onset event. diff --git a/src/workerd/io/worker-entrypoint.c++ b/src/workerd/io/worker-entrypoint.c++ index dbf5a37e040..61054a906cc 100644 --- a/src/workerd/io/worker-entrypoint.c++ +++ b/src/workerd/io/worker-entrypoint.c++ @@ -546,25 +546,26 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, KJ_IF_SOME(p, proxyTask) { return p .then([this]() { - // proxyTask completed successfully - report actual body sizes to tracer. - // We deferred setReturn() to here so we can report actual bytes written/read - // instead of Content-Length header values. + // proxyTask completed successfully - report trace events. + // setReturn() reports the response status code. + // setBodySizes() stores body sizes for the Outcome event (per HTTP spec, + // body size is only known after the body has been fully transmitted). KJ_IF_SOME(t, deferredWorkerTracer) { if (deferredHttpResponseStatus != 0) { - kj::Maybe responseBodySize; - KJ_IF_SOME(counter, traceByteCounter) { - responseBodySize = counter->get(); - } - kj::Maybe requestBodySize; - KJ_IF_SOME(counter, traceRequestByteCounter) { - requestBodySize = counter->get(); - } - t.setReturn(kj::none, - tracing::FetchResponseInfo( - deferredHttpResponseStatus, responseBodySize, requestBodySize)); + t.setReturn(kj::none, tracing::FetchResponseInfo(deferredHttpResponseStatus)); } else { t.setReturn(kj::none); } + // Set body sizes for the Outcome event + kj::Maybe responseBodySize; + KJ_IF_SOME(counter, traceByteCounter) { + responseBodySize = counter->get(); + } + kj::Maybe requestBodySize; + KJ_IF_SOME(counter, traceRequestByteCounter) { + requestBodySize = counter->get(); + } + t.setBodySizes(responseBodySize, requestBodySize); } // Clean up deferred trace state deferredWorkerTracer = kj::none; @@ -582,15 +583,16 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, // No proxyTask means no streaming body - report trace now if we have deferred info. KJ_IF_SOME(t, deferredWorkerTracer) { if (deferredHttpResponseStatus != 0) { - kj::Maybe requestBodySize; - KJ_IF_SOME(counter, traceRequestByteCounter) { - requestBodySize = counter->get(); - } - t.setReturn(kj::none, - tracing::FetchResponseInfo(deferredHttpResponseStatus, kj::none, requestBodySize)); + t.setReturn(kj::none, tracing::FetchResponseInfo(deferredHttpResponseStatus)); } else { t.setReturn(kj::none); } + // Set body sizes for the Outcome event (request body may still have been consumed) + kj::Maybe requestBodySize; + KJ_IF_SOME(counter, traceRequestByteCounter) { + requestBodySize = counter->get(); + } + t.setBodySizes(kj::none, requestBodySize); } deferredWorkerTracer = kj::none; traceByteCounter = kj::none; diff --git a/src/workerd/io/worker-interface.capnp b/src/workerd/io/worker-interface.capnp index 8166c8de2db..63272e61302 100644 --- a/src/workerd/io/worker-interface.capnp +++ b/src/workerd/io/worker-interface.capnp @@ -162,15 +162,8 @@ struct Trace @0x8e8d911203762d34 { response @8 :FetchResponseInfo; struct FetchResponseInfo { statusCode @0 :UInt16; - bodySize @1 :UInt64; - # Response body size in bytes. Only valid if hasBodySize is true. - hasBodySize @2 :Bool; - # True if bodySize contains a valid value (actual bytes written). - requestBodySize @3 :UInt64; - # Request body size in bytes. Only valid if hasRequestBodySize is true. - # This is actual bytes consumed, not Content-Length header. - hasRequestBodySize @4 :Bool; - # True if requestBodySize contains a valid value. + # Fields @1-@4 were body size fields that have been moved to Outcome + # where they can be populated after body streaming completes. } cpuTime @10 :UInt64; @@ -281,6 +274,18 @@ struct Trace @0x8e8d911203762d34 { outcome @0 :EventOutcome; cpuTime @1 :UInt64; wallTime @2 :UInt64; + # Body sizes are reported in Outcome because this is when streaming has + # definitively completed. Per HTTP spec, body size is only known after + # the body has been fully transmitted. + responseBodySize @3 :UInt64; + # Response body size in bytes. Only valid if hasResponseBodySize is true. + hasResponseBodySize @4 :Bool; + # True if responseBodySize contains a valid value (actual bytes written). + requestBodySize @5 :UInt64; + # Request body size in bytes. Only valid if hasRequestBodySize is true. + # This is actual bytes consumed, not Content-Length header. + hasRequestBodySize @6 :Bool; + # True if requestBodySize contains a valid value. } struct TailEvent { From c1e83b69b852fed781aeb56f8cd6dbcfdd591386 Mon Sep 17 00:00:00 2001 From: Luca Steeb Date: Wed, 28 Jan 2026 19:37:03 +0000 Subject: [PATCH 09/10] Remove verbose comments about body size tracking Clean up redundant comments that explained implementation details that are already self-evident from the code structure. Co-Authored-By: Claude Opus 4.5 --- src/workerd/api/tests/http-test.js | 4 ---- src/workerd/api/tests/tail-worker-test.js | 4 ---- src/workerd/api/trace.c++ | 3 --- src/workerd/api/trace.h | 2 -- src/workerd/io/trace-stream.c++ | 11 ----------- src/workerd/io/trace-test.c++ | 4 ---- src/workerd/io/trace.c++ | 3 --- src/workerd/io/trace.h | 14 ++------------ src/workerd/io/tracer.c++ | 2 -- src/workerd/io/tracer.h | 4 ---- src/workerd/io/worker-entrypoint.c++ | 22 ---------------------- 11 files changed, 2 insertions(+), 71 deletions(-) diff --git a/src/workerd/api/tests/http-test.js b/src/workerd/api/tests/http-test.js index 6b5d6b40853..b498f044725 100644 --- a/src/workerd/api/tests/http-test.js +++ b/src/workerd/api/tests/http-test.js @@ -14,12 +14,10 @@ export default { return Response.json(Object.fromEntries(request.headers)); } if (pathname === '/consume-body') { - // Actually consume the request body to test request body size tracking const body = await request.text(); return new Response(`Received ${body.length} bytes`); } if (pathname === '/streaming-response') { - // Streaming response to test response body size tracking const stream = new ReadableStream({ start(controller) { controller.enqueue(new TextEncoder().encode('chunk1')); @@ -106,7 +104,6 @@ export default { assert.strictEqual(scheduledLastCtrl.cron, '* * * * 30'); } - // Test request body consumption - body size should be tracked { const response = await env.SERVICE.fetch( 'http://placeholder/consume-body', @@ -119,7 +116,6 @@ export default { assert.strictEqual(text, 'Received 5 bytes'); } - // Test streaming response - body size should be tracked after streaming { const response = await env.SERVICE.fetch( 'http://placeholder/streaming-response' diff --git a/src/workerd/api/tests/tail-worker-test.js b/src/workerd/api/tests/tail-worker-test.js index 7798b8a7908..17387c86bb8 100644 --- a/src/workerd/api/tests/tail-worker-test.js +++ b/src/workerd/api/tests/tail-worker-test.js @@ -85,16 +85,12 @@ export const test = { let expected = [ // http-test.js: fetch and scheduled events get reported correctly. // First event is emitted by the test() event, which allows us to get some coverage for span tracing. - // Note: Span attributes use OpenTelemetry-style names (http.request.body.size, http.response.body.size) '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"custom"}}{"type":"spanOpen","name":"fetch","spanId":"0000000000000001"}{"type":"attributes","info":[{"name":"network.protocol.name","value":"http"},{"name":"network.protocol.version","value":"HTTP/1.1"},{"name":"http.request.method","value":"POST"},{"name":"url.full","value":"http://placeholder/body-length"},{"name":"http.request.body.size","value":"3"},{"name":"http.response.status_code","value":"200"},{"name":"http.response.body.size","value":"22"}]}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"fetch","spanId":"0000000000000002"}{"type":"attributes","info":[{"name":"network.protocol.name","value":"http"},{"name":"network.protocol.version","value":"HTTP/1.1"},{"name":"http.request.method","value":"POST"},{"name":"url.full","value":"http://placeholder/body-length"},{"name":"http.response.status_code","value":"200"},{"name":"http.response.body.size","value":"31"}]}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"scheduled","spanId":"0000000000000003"}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"scheduled","spanId":"0000000000000004"}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"fetch","spanId":"0000000000000005"}{"type":"attributes","info":[{"name":"network.protocol.name","value":"http"},{"name":"network.protocol.version","value":"HTTP/1.1"},{"name":"http.request.method","value":"POST"},{"name":"url.full","value":"http://placeholder/consume-body"},{"name":"http.request.body.size","value":"5"},{"name":"http.response.status_code","value":"200"},{"name":"http.response.body.size","value":"16"}]}{"type":"spanClose","outcome":"ok"}{"type":"spanOpen","name":"fetch","spanId":"0000000000000006"}{"type":"attributes","info":[{"name":"network.protocol.name","value":"http"},{"name":"network.protocol.version","value":"HTTP/1.1"},{"name":"http.request.method","value":"GET"},{"name":"url.full","value":"http://placeholder/streaming-response"},{"name":"http.response.status_code","value":"200"},{"name":"http.response.body.size","value":"12"}]}{"type":"spanClose","outcome":"ok"}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', - // Note: Body sizes are now in the outcome event (per HTTP spec, body size is only known after body streaming completes) '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"POST","url":"http://placeholder/body-length","headers":[]}}{"type":"return","info":{"type":"fetch","statusCode":200}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0,"responseBodySize":22,"requestBodySize":3}', '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"POST","url":"http://placeholder/body-length","headers":[]}}{"type":"return","info":{"type":"fetch","statusCode":200}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0,"responseBodySize":31,"requestBodySize":3}', '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"scheduled","scheduledTime":"1970-01-01T00:00:00.000Z","cron":""}}{"type":"return"}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"scheduled","scheduledTime":"1970-01-01T00:00:00.000Z","cron":"* * * * 30"}}{"type":"return"}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', - // Test consume-body endpoint - request body size tracked in outcome event '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"POST","url":"http://placeholder/consume-body","headers":[]}}{"type":"return","info":{"type":"fetch","statusCode":200}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0,"responseBodySize":16,"requestBodySize":5}', - // Test streaming-response endpoint - response body size tracked in outcome event '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"GET","url":"http://placeholder/streaming-response","headers":[]}}{"type":"return","info":{"type":"fetch","statusCode":200}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0,"responseBodySize":12}', '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","entrypoint":"cacheMode","scriptTags":[],"info":{"type":"custom"}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', '{"type":"onset","executionModel":"stateless","spanId":"0000000000000000","scriptTags":[],"info":{"type":"fetch","method":"GET","url":"http://placeholder/not-found","headers":[]}}{"type":"return","info":{"type":"fetch","statusCode":404}}{"type":"outcome","outcome":"ok","cpuTime":0,"wallTime":0}', diff --git a/src/workerd/api/trace.c++ b/src/workerd/api/trace.c++ index dd6cf370c7c..22f48967e11 100644 --- a/src/workerd/api/trace.c++ +++ b/src/workerd/api/trace.c++ @@ -369,9 +369,6 @@ jsg::Ref TraceItem::FetchEventInfo::Request: TraceItem::FetchEventInfo::Response::Response( const Trace& trace, const tracing::FetchResponseInfo& responseInfo) : status(responseInfo.statusCode), - // Body sizes are now stored on the Trace object (in Outcome), not FetchResponseInfo - // (in Return event). This is because body sizes are only known after body streaming - // completes, which happens after the return event. bodySize(trace.responseBodySize), requestBodySize(trace.requestBodySize) {} diff --git a/src/workerd/api/trace.h b/src/workerd/api/trace.h index cb886f18f2a..7d513086862 100644 --- a/src/workerd/api/trace.h +++ b/src/workerd/api/trace.h @@ -199,8 +199,6 @@ class TraceItem::FetchEventInfo::Request final: public jsg::Object { kj::Array headers; kj::String method; kj::String url; - // Note: Request body size is tracked in Response, not here, because - // it's only known after the request body is fully consumed. Detail(jsg::Optional> cf, kj::Array headers, diff --git a/src/workerd/io/trace-stream.c++ b/src/workerd/io/trace-stream.c++ index 36c7f3d08e3..9f088c4422a 100644 --- a/src/workerd/io/trace-stream.c++ +++ b/src/workerd/io/trace-stream.c++ @@ -180,8 +180,6 @@ jsg::JsValue ToJs(jsg::Lock& js, const FetchResponseInfo& info, StringCache& cac auto obj = js.obj(); obj.set(js, TYPE_STR, cache.get(js, FETCH_STR)); obj.set(js, STATUSCODE_STR, js.num(info.statusCode)); - // Note: Body sizes are now in Outcome, not FetchResponseInfo, - // because they're only known after body streaming completes. return obj; } @@ -204,10 +202,6 @@ jsg::JsValue ToJs(jsg::Lock& js, const FetchEventInfo& info, StringCache& cache) obj.set(js, HEADERS_STR, js.arr(info.headers.asPtr(), [&cache, &ToJs](jsg::Lock& js, const auto& header) { return ToJs(js, header, cache); })); - - // Note: Body sizes are tracked in Outcome, not here, - // because they're only known after body streaming completes. - return obj; } @@ -411,17 +405,12 @@ jsg::JsValue ToJs(jsg::Lock& js, const Outcome& outcome, StringCache& cache) { obj.set(js, CPUTIME_STR, js.num(cpuTime)); obj.set(js, WALLTIME_STR, js.num(wallTime)); - - // Body sizes are included in Outcome because this is when streaming has - // definitively completed. Per HTTP spec, body size is only known after - // the body has been fully transmitted. KJ_IF_SOME(size, outcome.responseBodySize) { obj.set(js, RESPONSEBODYSIZE_STR, js.num(static_cast(size))); } KJ_IF_SOME(size, outcome.requestBodySize) { obj.set(js, REQUESTBODYSIZE_STR, js.num(static_cast(size))); } - return obj; } diff --git a/src/workerd/io/trace-test.c++ b/src/workerd/io/trace-test.c++ index fea5a51077f..e005e7e5bf8 100644 --- a/src/workerd/io/trace-test.c++ +++ b/src/workerd/io/trace-test.c++ @@ -320,8 +320,6 @@ KJ_TEST("Read/Write FetchResponseInfo works") { capnp::MallocMessageBuilder builder; auto infoBuilder = builder.initRoot(); - // FetchResponseInfo now only contains statusCode. - // Body sizes have been moved to Outcome where they can be populated after body streaming completes. FetchResponseInfo info(123); info.copyTo(infoBuilder); @@ -411,8 +409,6 @@ KJ_TEST("Read/Write Return works") { capnp::MallocMessageBuilder builder; auto infoBuilder = builder.initRoot(); - // FetchResponseInfo now only contains statusCode. - // Body sizes have been moved to Outcome where they can be populated after body streaming completes. FetchResponseInfo fetchInfo(123); Return info(kj::mv(fetchInfo)); info.copyTo(infoBuilder); diff --git a/src/workerd/io/trace.c++ b/src/workerd/io/trace.c++ index f87b19da21d..2435aced9f0 100644 --- a/src/workerd/io/trace.c++ +++ b/src/workerd/io/trace.c++ @@ -334,8 +334,6 @@ FetchEventInfo::FetchEventInfo(rpc::Trace::FetchEventInfo::Reader reader) : method(validateMethod(reader.getMethod())), url(kj::str(reader.getUrl())), cfJson(kj::str(reader.getCfJson())) { - // Note: Request body size is now tracked in FetchResponseInfo, not here. - // The obsolete4/obsolete5 fields in the schema are ignored. kj::Vector
v; v.addAll(reader.getHeaders()); headers = v.releaseAsArray(); @@ -345,7 +343,6 @@ void FetchEventInfo::copyTo(rpc::Trace::FetchEventInfo::Builder builder) const { builder.setMethod(static_cast(method)); builder.setUrl(url); builder.setCfJson(cfJson); - // Note: Request body size is now tracked in FetchResponseInfo, not here. auto list = builder.initHeaders(headers.size()); for (auto i: kj::indices(headers)) { diff --git a/src/workerd/io/trace.h b/src/workerd/io/trace.h index 4a2cd9fe053..a65cf35267d 100644 --- a/src/workerd/io/trace.h +++ b/src/workerd/io/trace.h @@ -341,8 +341,6 @@ struct FetchEventInfo final { // TODO(perf): It might be more efficient to store some sort of parsed JSON result instead? kj::String cfJson; kj::Array
headers; - // Note: Body sizes are tracked in Outcome, not here, because - // they're only known after body streaming completes. void copyTo(rpc::Trace::FetchEventInfo::Builder builder) const; FetchEventInfo clone() const; @@ -493,9 +491,6 @@ struct FetchResponseInfo final { KJ_DISALLOW_COPY(FetchResponseInfo); uint16_t statusCode; - // Body sizes have been moved to Outcome where they can be populated after - // body streaming completes. Per HTTP spec, body size is only known after - // the body has been fully transmitted. void copyTo(rpc::Trace::FetchResponseInfo::Builder builder) const; FetchResponseInfo clone() const; @@ -753,11 +748,8 @@ struct Outcome final { EventOutcome outcome = EventOutcome::OK; kj::Duration cpuTime; kj::Duration wallTime; - // Body sizes are reported in Outcome because this is when streaming has - // definitively completed. Per HTTP spec, body size is only known after - // the body has been fully transmitted. - kj::Maybe responseBodySize; // Response body size in bytes. kj::none if unknown. - kj::Maybe requestBodySize; // Request body size in bytes. kj::none if unknown. + kj::Maybe responseBodySize; + kj::Maybe requestBodySize; void copyTo(rpc::Trace::Outcome::Builder builder) const; Outcome clone() const; @@ -883,8 +875,6 @@ class Trace final: public kj::Refcounted { kj::Duration cpuTime; kj::Duration wallTime; - // Body sizes are stored here for the Outcome event. They're only known after - // body streaming completes, which is why they're separate from FetchResponseInfo. kj::Maybe responseBodySize; kj::Maybe requestBodySize; diff --git a/src/workerd/io/tracer.c++ b/src/workerd/io/tracer.c++ index 002d63cb602..51eb231290f 100644 --- a/src/workerd/io/tracer.c++ +++ b/src/workerd/io/tracer.c++ @@ -356,8 +356,6 @@ void WorkerTracer::setOutcome(EventOutcome outcome, trace->outcome = outcome; trace->cpuTime = cpuTime; trace->wallTime = wallTime; - // Body sizes can come from parameters or from pre-set values via setBodySizes(). - // Parameters take precedence if provided. if (responseBodySize != kj::none) { trace->responseBodySize = responseBodySize; } diff --git a/src/workerd/io/tracer.h b/src/workerd/io/tracer.h index e23b99d7f9b..5d60071c1f9 100644 --- a/src/workerd/io/tracer.h +++ b/src/workerd/io/tracer.h @@ -58,16 +58,12 @@ class BaseTracer: public kj::Refcounted { // Reports the outcome event of the worker invocation. For Streaming Tail Worker, this will be the // final event, causing the stream to terminate. - // Body sizes can be passed directly here, or pre-set via setBodySizes(). virtual void setOutcome(EventOutcome outcome, kj::Duration cpuTime, kj::Duration wallTime, kj::Maybe responseBodySize = kj::none, kj::Maybe requestBodySize = kj::none) = 0; - // Pre-sets body sizes to be included in the Outcome event when setOutcome is called. - // This allows body sizes to be set from worker-entrypoint.c++ when proxyTask completes, - // before setOutcome is called from the RequestObserver destructor. virtual void setBodySizes( kj::Maybe responseBodySize, kj::Maybe requestBodySize) = 0; diff --git a/src/workerd/io/worker-entrypoint.c++ b/src/workerd/io/worker-entrypoint.c++ index 61054a906cc..8b5e1f597b6 100644 --- a/src/workerd/io/worker-entrypoint.c++ +++ b/src/workerd/io/worker-entrypoint.c++ @@ -26,7 +26,6 @@ namespace workerd { namespace { -// Forward declarations for deferred body size tracking struct ResponseBodyByteCounter; struct RequestBodyByteCounter; @@ -164,10 +163,6 @@ struct RequestBodyByteCounter: public kj::Refcounted { } }; -// Wraps an AsyncOutputStream to count bytes written. Used to track actual -// response body size for trace events (as opposed to Content-Length header). -// Note: This wrapper intentionally doesn't implement tryPumpFrom() optimization -// to ensure all bytes flow through write() where we can count them. class ByteCountingOutputStream final: public kj::AsyncOutputStream { public: ByteCountingOutputStream( @@ -200,8 +195,6 @@ class ByteCountingOutputStream final: public kj::AsyncOutputStream { kj::Own counter; }; -// Wraps an AsyncInputStream to count bytes read. Used to track actual -// request body size for trace events. class ByteCountingInputStream final: public kj::AsyncInputStream { public: ByteCountingInputStream(kj::AsyncInputStream& inner, kj::Own counter) @@ -421,9 +414,6 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, return tracing::FetchEventInfo::Header(kj::mv(entry.key), kj::strArray(entry.value, ", ")); }; - // Note: Request body size is tracked separately and reported in FetchResponseInfo - // after the body is fully consumed, not here in FetchEventInfo. - t.setEventInfo(*incomingRequest, tracing::FetchEventInfo(method, kj::str(url), kj::mv(cfJson), kj::mv(traceHeadersArray))); workerTracer = t; @@ -483,9 +473,6 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, PERFETTO_FLOW_FROM_POINTER(this)); proxyTask = kj::mv(deferredProxy.proxyTask); - // Save info for deferred trace reporting after response body streaming completes. - // We defer setReturn() until proxyTask completes so we can report actual body size - // instead of the expected size from Content-Length header. KJ_IF_SOME(t, workerTracer) { deferredWorkerTracer = t; deferredHttpResponseStatus = wrappedResponse.getHttpResponseStatus(); @@ -546,17 +533,12 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, KJ_IF_SOME(p, proxyTask) { return p .then([this]() { - // proxyTask completed successfully - report trace events. - // setReturn() reports the response status code. - // setBodySizes() stores body sizes for the Outcome event (per HTTP spec, - // body size is only known after the body has been fully transmitted). KJ_IF_SOME(t, deferredWorkerTracer) { if (deferredHttpResponseStatus != 0) { t.setReturn(kj::none, tracing::FetchResponseInfo(deferredHttpResponseStatus)); } else { t.setReturn(kj::none); } - // Set body sizes for the Outcome event kj::Maybe responseBodySize; KJ_IF_SOME(counter, traceByteCounter) { responseBodySize = counter->get(); @@ -567,12 +549,10 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, } t.setBodySizes(responseBodySize, requestBodySize); } - // Clean up deferred trace state deferredWorkerTracer = kj::none; traceByteCounter = kj::none; traceRequestByteCounter = kj::none; }).catch_([this, metrics = kj::mv(metrics)](kj::Exception&& e) mutable -> kj::Promise { - // Clean up deferred trace state on failure too deferredWorkerTracer = kj::none; traceByteCounter = kj::none; traceRequestByteCounter = kj::none; @@ -580,14 +560,12 @@ kj::Promise WorkerEntrypoint::request(kj::HttpMethod method, return kj::mv(e); }); } else { - // No proxyTask means no streaming body - report trace now if we have deferred info. KJ_IF_SOME(t, deferredWorkerTracer) { if (deferredHttpResponseStatus != 0) { t.setReturn(kj::none, tracing::FetchResponseInfo(deferredHttpResponseStatus)); } else { t.setReturn(kj::none); } - // Set body sizes for the Outcome event (request body may still have been consumed) kj::Maybe requestBodySize; KJ_IF_SOME(counter, traceRequestByteCounter) { requestBodySize = counter->get(); From 69b8f860df6779faae9f051ca0724193f691c5e2 Mon Sep 17 00:00:00 2001 From: Luca Steeb Date: Wed, 28 Jan 2026 19:43:16 +0000 Subject: [PATCH 10/10] Remove obsolete field markers and comments from capnp schema Co-Authored-By: Claude Opus 4.5 --- src/workerd/io/worker-interface.capnp | 14 -------------- 1 file changed, 14 deletions(-) diff --git a/src/workerd/io/worker-interface.capnp b/src/workerd/io/worker-interface.capnp index 63272e61302..b0c8ebf5ed6 100644 --- a/src/workerd/io/worker-interface.capnp +++ b/src/workerd/io/worker-interface.capnp @@ -108,10 +108,6 @@ struct Trace @0x8e8d911203762d34 { name @0 :Text; value @1 :Text; } - # Fields @4 and @5 were request body size fields that have been moved to - # FetchResponseInfo where they can be populated after the body is consumed. - obsolete4 @4 :UInt64; - obsolete5 @5 :Bool; } struct JsRpcEventInfo { @@ -162,8 +158,6 @@ struct Trace @0x8e8d911203762d34 { response @8 :FetchResponseInfo; struct FetchResponseInfo { statusCode @0 :UInt16; - # Fields @1-@4 were body size fields that have been moved to Outcome - # where they can be populated after body streaming completes. } cpuTime @10 :UInt64; @@ -274,18 +268,10 @@ struct Trace @0x8e8d911203762d34 { outcome @0 :EventOutcome; cpuTime @1 :UInt64; wallTime @2 :UInt64; - # Body sizes are reported in Outcome because this is when streaming has - # definitively completed. Per HTTP spec, body size is only known after - # the body has been fully transmitted. responseBodySize @3 :UInt64; - # Response body size in bytes. Only valid if hasResponseBodySize is true. hasResponseBodySize @4 :Bool; - # True if responseBodySize contains a valid value (actual bytes written). requestBodySize @5 :UInt64; - # Request body size in bytes. Only valid if hasRequestBodySize is true. - # This is actual bytes consumed, not Content-Length header. hasRequestBodySize @6 :Bool; - # True if requestBodySize contains a valid value. } struct TailEvent {