Skip to content

Commit aa162ad

Browse files
committed
[o11y] Log a useful warning when reporting span without current IncomingRequest
This should help us understand which spans are affected.
1 parent 77f0338 commit aa162ad

File tree

2 files changed

+30
-1
lines changed

2 files changed

+30
-1
lines changed

src/workerd/io/io-context.h

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -401,6 +401,13 @@ class IoContext final: public kj::Refcounted, private kj::TaskSet::ErrorHandler
401401
// True if this is the IoContext for the current thread (same as `hasCurrent() && tcx == current()`).
402402
bool isCurrent();
403403

404+
// Check if a current request is available. Used to provide better diagnostics when this is
405+
// unexpectedly absent when reporting a user span.
406+
// TODO(cleanup): This is a hack, remove after addressing the underlying issue.
407+
bool hasCurrentIncomingRequest() {
408+
return !incomingRequests.empty();
409+
}
410+
404411
// Like requireCurrent() but throws a JS error if this IoContext is not the current.
405412
void requireCurrentOrThrowJs();
406413

src/workerd/io/tracer.c++

Lines changed: 23 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -465,7 +465,29 @@ void BaseTracer::adjustSpanTime(CompleteSpan& span) {
465465
// missing topLevelInvocationSpanContext right after).
466466
if (weakIoContext != kj::none) {
467467
auto& weakIoCtx = KJ_ASSERT_NONNULL(weakIoContext);
468-
weakIoCtx->runIfAlive([&span](IoContext& context) { span.endTime = context.now(); });
468+
weakIoCtx->runIfAlive([this, &span](IoContext& context) {
469+
if (context.hasCurrentIncomingRequest()) {
470+
span.endTime = context.now();
471+
} else {
472+
// We have an IOContext, but there's no current IncomingRequest. Always log a warning here,
473+
// this should not be happening. Still report completeTime as a useful timestamp if
474+
// available.
475+
bool hasCompleteTime = false;
476+
if (completeTime != kj::UNIX_EPOCH) {
477+
span.endTime = completeTime;
478+
hasCompleteTime = true;
479+
} else {
480+
span.endTime = span.startTime;
481+
}
482+
if (isPredictableModeForTest()) {
483+
KJ_FAIL_ASSERT(
484+
"reported span without current request", span.operationName, hasCompleteTime);
485+
} else {
486+
KJ_LOG(WARNING, "reported span without current request", span.operationName,
487+
hasCompleteTime);
488+
}
489+
}
490+
});
469491
if (!weakIoCtx->isValid()) {
470492
// This can happen if we start a customEvent from this event and cancel it after this IoContext
471493
// gets destroyed. In that case we no longer have an IoContext available and can't get the

0 commit comments

Comments
 (0)