Merge pull request #4978 from cloudflare/felix/090325-STW-QA

[o11y] 09-03-25 STW cleanup, QA, debug logging

Author: fhanau

src/workerd/api/worker-rpc.c++

@@ -1935,6 +1935,9 @@ kj::Promise<WorkerInterface::CustomEvent::Result> JsRpcSessionCustomEventImpl::r
   IoContext& ioctx = incomingRequest->getContext();
 
   incomingRequest->delivered();
+  KJ_IF_SOME(tracer, incomingRequest->getWorkerTracer()) {
+    tracer.setIsJsRpc();
+  }
 
   KJ_DEFER({
     // waitUntil() should allow extending execution on the server side even when the client

src/workerd/io/trace.h

@@ -1111,8 +1111,8 @@ inline SpanBuilder SpanBuilder::newChild(kj::ConstString operationName, kj::Date
 
 // Interface to track trace context including both Jaeger and User spans.
 // TODO(o11y): Consider fleshing this out to make it a proper class, support adding tags/child spans
-// to both,... We expect that tracking user spans will not needed in all places where we have the
-// existing spans, so synergies will likely be limited.
+// to both,... We expect that tracking user spans will not be needed in all places where we have the
+// existing spans, so synergies will be limited.
 struct TraceContext {
   TraceContext(SpanBuilder span, SpanBuilder userSpan)
       : span(kj::mv(span)),

src/workerd/io/tracer.c++

@@ -3,6 +3,7 @@
 //     https://opensource.org/licenses/Apache-2.0
 
 #include <workerd/io/tracer.h>
+#include <workerd/util/sentry.h>
 #include <workerd/util/thread-scopes.h>
 
 #include <capnp/message.h>  // for capnp::clone()
@@ -167,6 +168,10 @@ void WorkerTracer::addLog(const tracing::InvocationSpanContext& context,
   // available. If the given worker stage is only tailed by a streaming tail worker, adding the log
   // to the legacy trace object is not needed; this will be addressed in a future refactor.
   KJ_IF_SOME(writer, maybeTailStreamWriter) {
+    // TODO(felix): Used for debug logging, remove after a few days.
+    if (topLevelInvocationSpanContext == kj::none) {
+      LOG_NOSENTRY(WARNING, "tried to send log before onset event", trace->entrypoint, isJsRpc);
+    }
     // If message is too big on its own, truncate it.
     writer->report(context,
         {(tracing::Log(timestamp, logLevel,
@@ -220,7 +225,8 @@ void WorkerTracer::addSpan(CompleteSpan&& span) {
     // TODO(o11y): Provide correct nested spans
     // TODO(o11y): Propagate span context when context entropy is not available for RPC-based worker
     // invocations as indicated by isTrigger
-    auto& topLevelContext = KJ_ASSERT_NONNULL(topLevelInvocationSpanContext, span);
+    auto& topLevelContext =
+        KJ_ASSERT_NONNULL(topLevelInvocationSpanContext, span, trace->entrypoint, isJsRpc);
     tracing::InvocationSpanContext context = [&]() {
       if (topLevelContext.isTrigger()) {
         return topLevelContext.clone();
@@ -419,6 +425,12 @@ void WorkerTracer::setOutcome(EventOutcome outcome, kj::Duration cpuTime, kj::Du
   // fixed size.
 }
 
+void WorkerTracer::recordTimestamp(kj::Date timestamp) {
+  if (completeTime == kj::UNIX_EPOCH) {
+    completeTime = timestamp;
+  }
+}
+
 void WorkerTracer::setFetchResponseInfo(tracing::FetchResponseInfo&& info) {
   // Match the behavior of setEventInfo(). Any resolution of the TODO comments
   // in setEventInfo() that are related to this check while probably also affect
@@ -434,6 +446,7 @@ void WorkerTracer::setFetchResponseInfo(tracing::FetchResponseInfo&& info) {
 }
 
 void WorkerTracer::setUserRequestSpan(SpanParent&& span) {
+  KJ_ASSERT(span.isObserved(), "span argument must be observed");
   KJ_ASSERT(!userRequestSpan.isObserved(), "setUserRequestSpan can only be called once");
   userRequestSpan = kj::mv(span);
 }
@@ -446,4 +459,8 @@ SpanParent WorkerTracer::getUserRequestSpan() {
   return userRequestSpan.addRef();
 }
 
+void BaseTracer::setIsJsRpc() {
+  isJsRpc = true;
+}
+
 }  // namespace workerd

src/workerd/io/tracer.h

@@ -128,17 +128,15 @@ class BaseTracer: public kj::Refcounted {
 
   // Report time as seen from the incoming Request when the request is complete, since it will not
   // be available afterwards.
-  void recordTimestamp(kj::Date timestamp) {
-    if (completeTime == kj::UNIX_EPOCH) {
-      completeTime = timestamp;
-    }
-  }
+  virtual void recordTimestamp(kj::Date timestamp) = 0;
 
   virtual SpanParent getUserRequestSpan() = 0;
 
-  // Time to be reported for the outcome event time. This will be set before the outcome is
-  // dispatched.
-  kj::Date completeTime = kj::UNIX_EPOCH;
+  // TODO(felix): Used for debug logging, remove after a few days.
+  void setIsJsRpc();
+
+  // Indicates that we're reporting from a JsRpc customEvent.
+  bool isJsRpc = false;
 };
 
 // Records a worker stage's trace information into a Trace object.  When all references to the
@@ -172,6 +170,8 @@ class WorkerTracer: public BaseTracer {
       tracing::EventInfo&& info) override;
   void setFetchResponseInfo(tracing::FetchResponseInfo&& info) override;
   void setOutcome(EventOutcome outcome, kj::Duration cpuTime, kj::Duration wallTime) override;
+  virtual void recordTimestamp(kj::Date timestamp) override;
+
   SpanParent getUserRequestSpan() override;
   // Allow setting the user request span after the tracer has been created so its observer can
   // reference the tracer. This can only be set once.
@@ -198,5 +198,9 @@ class WorkerTracer: public BaseTracer {
   kj::Maybe<kj::Rc<PipelineTracer>> parentPipeline;
 
   kj::Maybe<kj::Own<tracing::TailStreamWriter>> maybeTailStreamWriter;
+
+  // Time to be reported for the outcome event time. This will be set before the outcome is
+  // dispatched.
+  kj::Date completeTime = kj::UNIX_EPOCH;
 };
 }  // namespace workerd

src/workerd/io/worker.c++

@@ -235,7 +235,6 @@ void addExceptionToTrace(jsg::Lock& js,
     }
   }
 
-  // TODO(someday): Limit size of exception content?
   tracer.addException(ioContext.getInvocationSpanContext(), timestamp, kj::mv(name),
       kj::mv(message), kj::mv(stack));
 }