[o11y] Report SpanOpen event earlier

Author: fhanau

src/workerd/api/actor-kv-test-tail.js

@@ -11,6 +11,7 @@ export default testTailHandler;
 export const test = {
   async test(ctrl, env, ctx) {
     const expected = [
+      { name: 'durable_object_subrequest', closed: true },
       { name: 'durable_object_storage_put', closed: true },
       { name: 'durable_object_storage_put', closed: true },
       { name: 'durable_object_storage_get', closed: true },
@@ -23,7 +24,6 @@ export const test = {
       { name: 'durable_object_storage_deleteAlarm', closed: true },
       { name: 'durable_object_storage_transaction', closed: true },
       { name: 'durable_object_storage_sync', closed: true },
-      { name: 'durable_object_subrequest', closed: true },
     ];
 
     await Promise.allSettled(invocationPromises);

src/workerd/api/r2-instrumentation-test.js

@@ -192,12 +192,19 @@ export const test = {
         closed: true,
       },
       {
-        name: 'r2_put',
+        name: 'r2_get',
         'cloudflare.binding.type': 'r2',
         'cloudflare.binding.name': 'BUCKET',
-        'cloudflare.r2.operation': 'PutObject',
+        'cloudflare.r2.operation': 'GetObject',
         'cloudflare.r2.bucket': 'r2-test',
-        'cloudflare.r2.request.key': 'throwOnInvalidEtag',
+        'cloudflare.r2.request.key': 'rangeSuff',
+        'cloudflare.r2.request.range.suffix': 2n,
+        'cloudflare.r2.response.success': true,
+        'cloudflare.r2.response.etag': 'objectEtag',
+        'cloudflare.r2.response.size': 123,
+        'cloudflare.r2.response.uploaded': '2024-08-27T14:00:57.918Z',
+        'cloudflare.r2.response.storage_class': 'Standard',
+        'cloudflare.r2.response.custom_metadata': true,
         closed: true,
       },
       {
@@ -210,19 +217,12 @@ export const test = {
         closed: true,
       },
       {
-        name: 'r2_get',
+        name: 'r2_put',
         'cloudflare.binding.type': 'r2',
         'cloudflare.binding.name': 'BUCKET',
-        'cloudflare.r2.operation': 'GetObject',
+        'cloudflare.r2.operation': 'PutObject',
         'cloudflare.r2.bucket': 'r2-test',
-        'cloudflare.r2.request.key': 'rangeSuff',
-        'cloudflare.r2.request.range.suffix': 2n,
-        'cloudflare.r2.response.success': true,
-        'cloudflare.r2.response.etag': 'objectEtag',
-        'cloudflare.r2.response.size': 123,
-        'cloudflare.r2.response.uploaded': '2024-08-27T14:00:57.918Z',
-        'cloudflare.r2.response.storage_class': 'Standard',
-        'cloudflare.r2.response.custom_metadata': true,
+        'cloudflare.r2.request.key': 'throwOnInvalidEtag',
         closed: true,
       },
       {

src/workerd/api/tail-worker-test.js

@@ -1469,7 +1469,10 @@ SpanBuilder::SpanBuilder(kj::Maybe<kj::Own<SpanObserver>> observer,
   KJ_IF_SOME(obs, observer) {
     // TODO(o11y): Once we report the user tracing spanOpen event as soon as a span is created, we
     // should be able to fold this virtual call and just get the timestamp directly.
-    span.emplace(kj::mv(operationName), startTime.orDefault(obs->getTime()));
+    kj::Date time = startTime.orDefault([&]() { return obs->getTime(); });
+    // Report spanOpen event for user tracing spans
+    obs->reportStart(operationName, time);
+    span.emplace(kj::mv(operationName), time);
     this->observer = kj::mv(obs);
   }
 }
@@ -1612,7 +1615,6 @@ void CompleteSpan::copyTo(rpc::UserSpanData::Builder builder) const {
   builder.setStartTimeNs((startTime - kj::UNIX_EPOCH) / kj::NANOSECONDS);
   builder.setEndTimeNs((endTime - kj::UNIX_EPOCH) / kj::NANOSECONDS);
   builder.setSpanId(spanId);
-  builder.setParentSpanId(parentSpanId);
 
   auto tagsParam = builder.initTags(tags.size());
   auto i = 0;
@@ -1625,7 +1627,6 @@ void CompleteSpan::copyTo(rpc::UserSpanData::Builder builder) const {
 
 CompleteSpan::CompleteSpan(rpc::UserSpanData::Reader reader)
     : spanId(reader.getSpanId()),
-      parentSpanId(reader.getParentSpanId()),
       operationName(kj::str(reader.getOperationName())),
       startTime(kj::UNIX_EPOCH + reader.getStartTimeNs() * kj::NANOSECONDS),
       endTime(kj::UNIX_EPOCH + reader.getEndTimeNs() * kj::NANOSECONDS) {
@@ -1638,8 +1639,7 @@ CompleteSpan::CompleteSpan(rpc::UserSpanData::Reader reader)
 }
 
 CompleteSpan CompleteSpan::clone() const {
-  CompleteSpan copy(
-      spanId, parentSpanId, kj::ConstString(kj::str(operationName)), startTime, endTime);
+  CompleteSpan copy(spanId, kj::ConstString(kj::str(operationName)), startTime, endTime);
   copy.tags.reserve(tags.size());
   for (auto& tag: tags) {
     copy.tags.insert(kj::ConstString(kj::str(tag.key)), spanTagClone(tag.value));

src/workerd/io/trace.c++

@@ -611,8 +611,10 @@ kj::String KJ_STRINGIFY(const CustomInfo& customInfo);
 struct CompleteSpan {
   // Represents a completed span within user tracing.
   tracing::SpanId spanId;
-  tracing::SpanId parentSpanId;
 
+  // TODO(cleanup): operationName and startTime are not used in the spanClose event, but still used
+  // for diagnostics and a fallback timestamp in the implementation. Get rid of them once that is no
+  // longer needed.
   kj::ConstString operationName;
   kj::Date startTime;
   kj::Date endTime;
@@ -623,14 +625,12 @@ struct CompleteSpan {
   void copyTo(rpc::UserSpanData::Builder builder) const;
   CompleteSpan clone() const;
   explicit CompleteSpan(tracing::SpanId spanId,
-      tracing::SpanId parentSpanId,
       kj::ConstString operationName,
       kj::Date startTime,
       kj::Date endTime,
       kj::HashMap<kj::ConstString, tracing::Attribute::Value> tags =
           kj::HashMap<kj::ConstString, tracing::Attribute::Value>())
       : spanId(spanId),
-        parentSpanId(parentSpanId),
         operationName(kj::mv(operationName)),
         startTime(startTime),
         endTime(endTime),
@@ -1099,6 +1099,7 @@ class SpanObserver: public kj::Refcounted {
   //
   // This should always be called exactly once per observer.
   virtual void report(const Span& span) = 0;
+  virtual void reportStart(kj::ConstString& operationName, kj::Date startTime) = 0;
 
   // The current time to be provided for the span. For user tracing, we will override this to
   // provide I/O time. This *requires* that spans are only created when an IOContext is available

src/workerd/io/trace.h

@@ -220,34 +220,44 @@ void WorkerTracer::addSpan(CompleteSpan&& span) {
     }
   }
 
-  // Span events are transmitted together for now.
+  // Compose span events – attributes and spanClose are transmitted together for now.
   auto& topLevelContext = KJ_ASSERT_NONNULL(topLevelInvocationSpanContext);
-  // Compose span events. For SpanOpen, an all-zero spanId is interpreted as having no spans above
-  // this one, thus we use the Onset spanId instead (taken from topLevelContext). We go to great
-  // lengths to rule out getting an all-zero spanId by chance (see SpanId::fromEntropy()), so this
-  // should be safe.
-  tracing::SpanId parentSpanId = span.parentSpanId;
-  if (parentSpanId == tracing::SpanId::nullId) {
-    parentSpanId = topLevelContext.getSpanId();
-  }
-  // TODO(o11y): Actually report the spanOpen event at span creation time
-  auto spanOpenContext = tracing::InvocationSpanContext(
-      topLevelContext.getTraceId(), topLevelContext.getInvocationId(), parentSpanId);
   auto spanComponentContext = tracing::InvocationSpanContext(
       topLevelContext.getTraceId(), topLevelContext.getInvocationId(), span.spanId);
 
-  tailStreamWriter->report(
-      spanOpenContext, tracing::SpanOpen(span.spanId, kj::str(span.operationName)), span.startTime);
   // If a span manages to exceed the size limit, truncate it by not providing span attributes.
   if (span.tags.size() && messageSize <= MAX_TRACE_BYTES) {
     tracing::CustomInfo attr = KJ_MAP(tag, span.tags) {
-      return tracing::Attribute(kj::ConstString(kj::str(tag.key)), spanTagClone(tag.value));
+      return tracing::Attribute(kj::mv(tag.key), kj::mv(tag.value));
     };
     tailStreamWriter->report(spanComponentContext, kj::mv(attr), span.startTime);
   }
   tailStreamWriter->report(spanComponentContext, tracing::SpanClose(), span.endTime);
 }
 
+void WorkerTracer::addSpanOpen(tracing::SpanId spanId,
+    tracing::SpanId parentSpanId,
+    kj::ConstString& operationName,
+    kj::Date startTime) {
+  // This is where we'll actually encode the span.
+  if (pipelineLogLevel == PipelineLogLevel::NONE) {
+    return;
+  }
+
+  auto& tailStreamWriter = KJ_UNWRAP_OR_RETURN(maybeTailStreamWriter);
+  auto& topLevelContext = KJ_ASSERT_NONNULL(topLevelInvocationSpanContext);
+  // Compose SpanOpen. An all-zero spanId is interpreted as having no spans above this one, thus we
+  // use the Onset spanId instead (taken from topLevelContext). We go to great lengths to rule out
+  // getting an all-zero spanId by chance (see SpanId::fromEntropy()), so this should be safe.
+  if (parentSpanId == tracing::SpanId::nullId) {
+    parentSpanId = topLevelContext.getSpanId();
+  }
+  auto spanOpenContext = tracing::InvocationSpanContext(
+      topLevelContext.getTraceId(), topLevelContext.getInvocationId(), parentSpanId);
+  tailStreamWriter->report(
+      spanOpenContext, tracing::SpanOpen(spanId, kj::str(operationName)), startTime);
+}
+
 void WorkerTracer::addException(const tracing::InvocationSpanContext& context,
     kj::Date timestamp,
     kj::String name,

src/workerd/io/tracer.c++

@@ -104,6 +104,10 @@ class BaseTracer: public kj::Refcounted {
       kj::String message) = 0;
   // Add a span.
   virtual void addSpan(CompleteSpan&& span) = 0;
+  virtual void addSpanOpen(tracing::SpanId spanId,
+      tracing::SpanId parentSpanId,
+      kj::ConstString& operationName,
+      kj::Date startTime) = 0;
 
   virtual void addException(const tracing::InvocationSpanContext& context,
       kj::Date timestamp,
@@ -182,6 +186,10 @@ class WorkerTracer final: public BaseTracer {
       LogLevel logLevel,
       kj::String message) override;
   void addSpan(CompleteSpan&& span) override;
+  void addSpanOpen(tracing::SpanId spanId,
+      tracing::SpanId parentSpanId,
+      kj::ConstString& operationName,
+      kj::Date startTime) override;
   void addException(const tracing::InvocationSpanContext& context,
       kj::Date timestamp,
       kj::String name,

src/workerd/io/tracer.h

@@ -1702,11 +1702,11 @@ class SpanSubmitter final: public kj::Refcounted {
   SpanSubmitter(kj::Own<WorkerTracer> workerTracer)
       : predictableSpanId(0),
         workerTracer(kj::mv(workerTracer)) {}
-  void submitSpan(tracing::SpanId spanId, tracing::SpanId parentSpanId, const Span& span) {
+  void submitSpan(tracing::SpanId spanId, const Span& span) {
     // We largely recreate the span here which feels inefficient, but is hard to avoid given the
     // mismatch between the Span type and the full span information required for OTel.
-    CompleteSpan span2(spanId, parentSpanId, kj::ConstString(kj::str(span.operationName)),
-        span.startTime, span.endTime);
+    CompleteSpan span2(
+        spanId, kj::ConstString(kj::str(span.operationName)), span.startTime, span.endTime);
     span2.tags.reserve(span.tags.size());
     for (auto& tag: span.tags) {
       span2.tags.insert(kj::ConstString(kj::str(tag.key)), spanTagClone(tag.value));
@@ -1717,6 +1717,15 @@ class SpanSubmitter final: public kj::Refcounted {
 
     workerTracer->addSpan(kj::mv(span2));
   }
+  void submitSpanStart(tracing::SpanId spanId,
+      tracing::SpanId parentSpanId,
+      kj::ConstString& operationName,
+      kj::Date startTime) {
+    if (isPredictableModeForTest()) {
+      startTime = kj::UNIX_EPOCH;
+    }
+    workerTracer->addSpanOpen(spanId, parentSpanId, operationName, startTime);
+  }
 
   tracing::SpanId makeSpanId() {
     return tracing::SpanId(predictableSpanId++);
@@ -1743,7 +1752,10 @@ class WorkerTracerSpanObserver: public SpanObserver {
   }
 
   void report(const Span& span) override {
-    spanSubmitter->submitSpan(spanId, parentSpanId, span);
+    spanSubmitter->submitSpan(spanId, span);
+  }
+  void reportStart(kj::ConstString& operationName, kj::Date startTime) override {
+    spanSubmitter->submitSpanStart(spanId, parentSpanId, operationName, startTime);
   }
 
   // Provide I/O time to the tracing system for user spans.