[o11y] Add more debug logging for missing/delayed Onset event

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/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();
@@ -453,4 +459,8 @@ SpanParent WorkerTracer::getUserRequestSpan() {
   return userRequestSpan.addRef();
 }
 
+void BaseTracer::setIsJsRpc() {
+  isJsRpc = true;
+}
+
 }  // namespace workerd

src/workerd/io/tracer.h

@@ -131,6 +131,12 @@ class BaseTracer: public kj::Refcounted {
   virtual void recordTimestamp(kj::Date timestamp) = 0;
 
   virtual SpanParent getUserRequestSpan() = 0;
+
+  // 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