add extra logging for makeTimeoutPromise

This log adds context on what the output gate was locked on.

Author: Frederik-Baetens

src/workerd/io/actor-cache.c++

@@ -215,7 +215,7 @@ void ActorCache::requireNotTerminal() {
       // we don't let the worker return stale state. This isn't strictly necessary but it does
       // mirror previous behavior wherein we would use disabled storage via `flushImpl()` and break
       // the output gate.
-      ensureFlushScheduled({});
+      ensureFlushScheduled({}, "requireNotTerminal intentionally breaking output gate"_kjc);
     }
 
     kj::throwFatalException(kj::cp(e));
@@ -249,7 +249,7 @@ void ActorCache::evictOrOomIfNeeded(Lock& lock) {
       // that returns a promise which we'd then have to put somewhere so that we don't immediately
       // cancel it. Instead, we can ensure that a flush has been scheduled. `flushImpl()`, when
       // called, will throw an exception which breaks the gate.
-      ensureFlushScheduled(WriteOptions());
+      ensureFlushScheduled(WriteOptions(), "evictOrOomIfNeeded intentionally breaking output gate"_kjc);
     }
 
     kj::throwFatalException(kj::mv(exception));
@@ -1853,7 +1853,7 @@ kj::Maybe<kj::Promise<void>> ActorCache::setAlarm(kj::Maybe<kj::Date> newAlarmTi
     options.noCache
   };
 
-  ensureFlushScheduled(options);
+  ensureFlushScheduled(options, "setAlarm flush"_kjc);
 
   return getBackpressure();
 }
@@ -1990,7 +1990,7 @@ ActorCache::DeleteAllResults ActorCache::deleteAll(WriteOptions options) {
         .deletedDirty = kj::mv(deletedDirty),
         .countFulfiller = kj::mv(paf.fulfiller)
       };
-      ensureFlushScheduled(options);
+      ensureFlushScheduled(options, "deleteAll flush"_kjc);
     } else {
       // A previous deleteAll() was scheduled and hasn't been committed yet. This means that we
       // can actually coalesce the two, and there's no need to commit any writes that happened
@@ -2108,10 +2108,10 @@ void ActorCache::putImpl(Lock& lock, kj::Own<Entry> newEntry,
     addToDirtyList(*slot);
   }
 
-  ensureFlushScheduled(options);
+  ensureFlushScheduled(options, "putImpl flush"_kjc);
 }
 
-void ActorCache::ensureFlushScheduled(const WriteOptions& options) {
+void ActorCache::ensureFlushScheduled(const WriteOptions& options, kj::LiteralStringConst operationInfo) {
   if (lru.options.neverFlush) {
     // Skip all flushes. Used for preview sessions where data is strictly kept in memory.
 
@@ -2156,19 +2156,19 @@ void ActorCache::ensureFlushScheduled(const WriteOptions& options) {
     if (options.allowUnconfirmed) {
       // Don't apply output gate. But, if an exception is thrown, we still want to break the gate,
       // so arrange for that.
-      flushPromise = flushPromise.catch_([this](kj::Exception&& e) {
-        return gate.lockWhile(kj::Promise<void>(kj::mv(e)));
+      flushPromise = flushPromise.catch_([this, opInfo = kj::mv(operationInfo)](kj::Exception&& e) {
+        return gate.lockWhile(kj::Promise<void>(kj::mv(e)), kj::mv(opInfo));
       });
     } else {
-      flushPromise = gate.lockWhile(kj::mv(flushPromise));
+      flushPromise = gate.lockWhile(kj::mv(flushPromise), kj::mv(operationInfo));
       flushScheduledWithOutputGate = true;
     }
 
     lastFlush = flushPromise.fork();
   } else if (!flushScheduledWithOutputGate && !options.allowUnconfirmed) {
     // The flush has already been scheduled without the output gate, but we want to upgrade it to
     // use the output gate now.
-    lastFlush = gate.lockWhile(lastFlush.addBranch()).fork();
+    lastFlush = gate.lockWhile(lastFlush.addBranch(), kj::mv(operationInfo)).fork();
     flushScheduledWithOutputGate = true;
   }
 }

src/workerd/io/actor-cache.h

@@ -310,7 +310,7 @@ class ActorCache final: public ActorCacheInterface {
       auto p = reinterpret_cast<ActorCache*>(pointer);
       KJ_IF_SOME(d, p->currentAlarmTime.tryGet<DeferredAlarmDelete>()) {
         d.status = DeferredAlarmDelete::Status::READY;
-        p->ensureFlushScheduled(WriteOptions { .noCache = d.noCache });
+        p->ensureFlushScheduled(WriteOptions { .noCache = d.noCache }, "alarm disposer"_kjc);
       }
     }
   };
@@ -702,7 +702,7 @@ class ActorCache final: public ActorCacheInterface {
   kj::Promise<kj::Maybe<Value>> getImpl(kj::Own<Entry> entry, ReadOptions options);
 
   // Ensure that we will flush dirty entries soon.
-  void ensureFlushScheduled(const WriteOptions& options);
+  void ensureFlushScheduled(const WriteOptions& options, kj::LiteralStringConst operationInfo);
 
   // Schedule a read RPC. The given function will be invoked and provided with an
   // ActorStorage::Operations::Client on which the read operation should be performed. The function

src/workerd/io/actor-sqlite.c++

@@ -107,7 +107,7 @@ kj::Maybe<kj::Promise<void>> ActorSqlite::ExplicitTxn::commit() {
     // We committed the root transaction, so it's time to signal any replication layer and lock
     // the output gate in the meantime.
     actorSqlite.commitTasks.add(
-        actorSqlite.outputGate.lockWhile(actorSqlite.commitCallback()));
+        actorSqlite.outputGate.lockWhile(actorSqlite.commitCallback(), "explicit txn commit"_kjc));
   }
 
   // No backpressure for SQLite.
@@ -158,7 +158,7 @@ void ActorSqlite::onWrite() {
       { auto drop = kj::mv(txn); }
 
       return commitCallback();
-    })));
+    }), "committing write"_kjc));
   }
 }
 

src/workerd/io/io-gate.h

@@ -225,7 +225,8 @@ class OutputGate {
     // Optionally make a promise which should be exclusiveJoin()ed with the lock promise to
     // implement a timeout. The returned promise should be something that throws an exception
     // after some timeout has expired.
-    virtual kj::Promise<void> makeTimeoutPromise() { return kj::NEVER_DONE; }
+    // The passed operationInfo will be logged separately to provide extra information.
+    virtual kj::Promise<void> makeTimeoutPromise(kj::LiteralStringConst operationInfo) { return kj::NEVER_DONE; }
 
     // Optionally track metrics. In practice these are implemented by MetricsCollector::Actor, but
     // we don't want to depend on that class from here.
@@ -245,7 +246,7 @@ class OutputGate {
   // If `promise` rejects, the exception will propagate to all future `wait()`s. If the returned
   // promise is canceled before completion, all future `wait()`s will also throw.
   template <typename T>
-  kj::Promise<T> lockWhile(kj::Promise<T> promise);
+  kj::Promise<T> lockWhile(kj::Promise<T> promise, kj::LiteralStringConst operationInfo);
 
   // Wait until all preceding locks are released. The wait will not be affected by any future
   // call to `lockWhile()`.
@@ -277,13 +278,13 @@ class OutputGate {
 // inline implementation details
 
 template <typename T>
-kj::Promise<T> OutputGate::lockWhile(kj::Promise<T> promise) {
+kj::Promise<T> OutputGate::lockWhile(kj::Promise<T> promise, kj::LiteralStringConst operationInfo) {
   auto fulfiller = lock();
 
   if constexpr (std::is_void_v<T>) {
-    promise = promise.exclusiveJoin(hooks.makeTimeoutPromise());
+    promise = promise.exclusiveJoin(hooks.makeTimeoutPromise(operationInfo));
   } else {
-    promise = promise.exclusiveJoin(hooks.makeTimeoutPromise()
+    promise = promise.exclusiveJoin(hooks.makeTimeoutPromise(operationInfo)
         .then([]() -> T { KJ_UNREACHABLE; }));
   }
 

src/workerd/io/worker.c++

@@ -2951,12 +2951,13 @@ struct Worker::Actor::Impl {
     void inputGateWaiterRemoved() override { metrics.inputGateWaiterRemoved(); }
     // Implements InputGate::Hooks.
 
-    kj::Promise<void> makeTimeoutPromise() override {
+    kj::Promise<void> makeTimeoutPromise(kj::LiteralStringConst operationInfo) override {
       // This really only protects against total hangs. Lowering the timeout drastically is risky,
       // since low timeouts can spuriously fire when under heavy CPU load, failing requests that
       // would otherwise succeed.
       auto timeout = 30 * kj::SECONDS;
       co_await timerChannel.afterLimitTimeout(timeout);
+      KJ_LOG(ERROR, "Durable Object storage operation exceeded timeout", operationInfo);
       kj::throwFatalException(KJ_EXCEPTION(FAILED,
             "broken.outputGateBroken; jsg.Error: Durable Object storage operation exceeded "
             "timeout which caused object to be reset."));