From 4f89424851dd11003c1abf647e5ac56538fb150d Mon Sep 17 00:00:00 2001 From: James M Snell Date: Fri, 20 Sep 2024 12:06:08 -0700 Subject: [PATCH] Attempt to log the stack where cross-request promises are being resolved --- src/workerd/io/worker.c++ | 29 +++++++++++++++++++++++++++++ 1 file changed, 29 insertions(+) diff --git a/src/workerd/io/worker.c++ b/src/workerd/io/worker.c++ index 98c2ae019c4..6214482dfc1 100644 --- a/src/workerd/io/worker.c++ +++ b/src/workerd/io/worker.c++ @@ -1194,6 +1194,35 @@ Worker::Isolate::Isolate(kj::Own apiParam, v8::Local argument)> callback) -> v8::Maybe { try { auto& js = jsg::Lock::from(isolate); + + { + // TODO(soon): Hopefully this logging is temporary. We want to get an idea + // of where the cross request promises are being resolved just in general. + // To do so we need to try to capture a stack. We do so by creating an error + // object and logging it. + v8::HandleScope handleScope(isolate); + auto err = + v8::Exception::Error(js.str("Cross Request Promise Resolve"_kj)).As(); + jsg::check(err->Set(js.v8Context(), js.str("name"_kj), js.str("Warning"_kj))); + auto stack = jsg::check(err->Get(js.v8Context(), js.str("stack"_kj))); + // Let's only log if there's actually a useful stack in the log. + auto msg = kj::str("NOSENTRY ", stack); + // This check is meant to prevent spamming the logs with messages that do + // not actually provide any useful information. + if (msg != "NOSENTRY Warning: Cross Request Promise Resolve") { + KJ_LOG(WARNING, kj::str("NOSENTRY ", stack)); + } else { + // If we get here, it means we don't have a useful JS stack trace. + // Either the stack trace limit was set to zero for some reason or + // this resolve/reject originated from inside the runtime where a + // JS stack trace is not available. Let's emit the warning with a + // C++ stack instead. + // TODO(review): Is this worthwhile? Does it give us enough useful signal? + LOG_PERIODICALLY(WARNING, "NOSENTRY Warning: Cross Request Promise Resolve\n", + kj::getStackTrace()); + } + } + // The promise tag is generally opaque except for right here. The tag // wraps an instanceof kj::Own, which wraps an atomically // refcounted pointer to the DeleteQueue for the correct isolate.