SERVER-47869 Add debug logging mechanism to mongos cursor manager

There is a bug in the mongos cursor manager tracked by SERVER-27796 which has never been reproduced
in our testing environment but has been encountered by multiple customers. This change adds a small
diagnostic log to the mongos cursor manager which is dumped when a symptom of the bug is found.

2 files changed, 250 insertions, 8 deletions

diff --git a/src/mongo/s/query/cluster_cursor_manager.cpp b/src/mongo/s/query/cluster_cursor_manager.cpp
index b3bb3038eed..73ae523f978 100644
--- a/src/mongo/s/query/cluster_cursor_manager.cpp
+++ b/src/mongo/s/query/cluster_cursor_manager.cpp
@@ -148,7 +148,9 @@ void ClusterCursorManager::PinnedCursor::returnAndKillCursor() {
 }
 
 ClusterCursorManager::ClusterCursorManager(ClockSource* clockSource)
-    : _clockSource(clockSource), _pseudoRandom(SecureRandom().nextInt64()) {
+    : _clockSource(clockSource),
+      _randomSeed(SecureRandom().nextInt64()),
+      _pseudoRandom(_randomSeed) {
     invariant(_clockSource);
 }
 
@@ -176,6 +178,7 @@ StatusWith<CursorId> ClusterCursorManager::registerCursor(
     const auto now = _clockSource->now();
 
     stdx::unique_lock<Latch> lk(_mutex);
+    _log.push({LogEvent::Type::kRegisterAttempt, boost::none, now, nss});
 
     if (_inShutdown) {
         lk.unlock();
@@ -232,6 +235,7 @@ StatusWith<CursorId> ClusterCursorManager::registerCursor(
                                                       authenticatedUsers,
                                                       opCtx->getOperationKey()));
     invariant(emplaceResult.second);
+    _log.push({LogEvent::Type::kRegisterComplete, cursorId, now, nss});
 
     return cursorId;
 }
@@ -242,7 +246,10 @@ StatusWith<ClusterCursorManager::PinnedCursor> ClusterCursorManager::checkOutCur
     OperationContext* opCtx,
     AuthzCheckFn authChecker,
     AuthCheck checkSessionAuth) {
+    const auto now = _clockSource->now();
+
     stdx::lock_guard<Latch> lk(_mutex);
+    _log.push({LogEvent::Type::kCheckoutAttempt, cursorId, now, nss});
 
     if (_inShutdown) {
         return Status(ErrorCodes::ShutdownInProgress,
@@ -285,6 +292,8 @@ StatusWith<ClusterCursorManager::PinnedCursor> ClusterCursorManager::checkOutCur
         }
     }
     cursorGuard->reattachToOperationContext(opCtx);
+
+    _log.push({LogEvent::Type::kCheckoutComplete, cursorId, now, nss});
     return PinnedCursor(this, std::move(cursorGuard), nss, cursorId);
 }
 
@@ -303,6 +312,7 @@ void ClusterCursorManager::checkInCursor(std::unique_ptr<ClusterClientCursor> cu
     cursor->setLastUseDate(now);
 
     stdx::unique_lock<Latch> lk(_mutex);
+    _log.push({LogEvent::Type::kCheckInAttempt, cursorId, now, nss});
 
     CursorEntry* entry = _getEntry(lk, nss, cursorId);
     invariant(entry);
@@ -314,6 +324,7 @@ void ClusterCursorManager::checkInCursor(std::unique_ptr<ClusterClientCursor> cu
     entry->returnCursor(std::move(cursor));
 
     if (cursorState == CursorState::NotExhausted && !killPending) {
+        _log.push({LogEvent::Type::kCheckInCompleteCursorSaved, cursorId, now, nss});
         // The caller may need the cursor again.
         return;
     }
@@ -355,8 +366,11 @@ Status ClusterCursorManager::killCursor(OperationContext* opCtx,
                                         CursorId cursorId) {
     invariant(opCtx);
 
+    const auto now = _clockSource->now();
     stdx::unique_lock<Latch> lk(_mutex);
 
+    _log.push({LogEvent::Type::kKillCursorAttempt, cursorId, now, nss});
+
     CursorEntry* entry = _getEntry(lk, nss, cursorId);
     if (!entry) {
         return cursorNotFoundStatus(nss, cursorId);
@@ -393,6 +407,7 @@ void ClusterCursorManager::detachAndKillCursor(stdx::unique_lock<Latch> lk,
 
 std::size_t ClusterCursorManager::killMortalCursorsInactiveSince(OperationContext* opCtx,
                                                                  Date_t cutoff) {
+    const auto now = _clockSource->now();
     stdx::unique_lock<Latch> lk(_mutex);
 
     auto pred = [cutoff](CursorId cursorId, const CursorEntry& entry) -> bool {
@@ -410,24 +425,29 @@ std::size_t ClusterCursorManager::killMortalCursorsInactiveSince(OperationContex
         return res;
     };
 
-    return killCursorsSatisfying(std::move(lk), opCtx, std::move(pred));
+    return killCursorsSatisfying(std::move(lk), opCtx, std::move(pred), now);
 }
 
 void ClusterCursorManager::killAllCursors(OperationContext* opCtx) {
+    const auto now = _clockSource->now();
     stdx::unique_lock<Latch> lk(_mutex);
     auto pred = [](CursorId, const CursorEntry&) -> bool { return true; };
 
-    killCursorsSatisfying(std::move(lk), opCtx, std::move(pred));
+    killCursorsSatisfying(std::move(lk), opCtx, std::move(pred), now);
 }
 
 std::size_t ClusterCursorManager::killCursorsSatisfying(
     stdx::unique_lock<Latch> lk,
     OperationContext* opCtx,
-    std::function<bool(CursorId, const CursorEntry&)> pred) {
+    std::function<bool(CursorId, const CursorEntry&)> pred,
+    Date_t now) {
     invariant(opCtx);
     invariant(lk.owns_lock());
     std::size_t nKilled = 0;
 
+    _log.push(
+        {LogEvent::Type::kRemoveCursorsSatisfyingPredicateAttempt, boost::none, now, boost::none});
+
     std::vector<ClusterClientCursorGuard> cursorsToDestroy;
     auto nsContainerIt = _namespaceToContainerMap.begin();
     while (nsContainerIt != _namespaceToContainerMap.end()) {
@@ -451,6 +471,14 @@ std::size_t ClusterCursorManager::killCursorsSatisfying(
                 continue;
             }
 
+            _log.push({LogEvent::Type::kCursorMarkedForDeletionBySatisfyingPredicate,
+                       cursorId,
+                       // While we collected 'now' above, we ran caller-provided predicates which
+                       // may have been expensive. To avoid re-reading from the clock while the
+                       // lock is held, we do not provide a value for 'now' in this log entry.
+                       boost::none,
+                       nsContainerIt->first});
+
             cursorsToDestroy.push_back(entry.releaseCursor(opCtx));
 
             // Destroy the entry and set the iterator to the next element.
@@ -464,6 +492,14 @@ std::size_t ClusterCursorManager::killCursorsSatisfying(
         }
     }
 
+    _log.push({LogEvent::Type::kRemoveCursorsSatisfyingPredicateComplete,
+               boost::none,
+               // While we collected 'now' above, we ran caller-provided predicates which may have
+               // been expensive. To avoid re-reading from the clock while the lock is held, we do
+               // not provide a value for 'now' in this log entry.
+               boost::none,
+               boost::none});
+
     // Ensure cursors are killed outside the lock, as killing may require waiting for callbacks to
     // finish.
     lk.unlock();
@@ -687,8 +723,27 @@ auto ClusterCursorManager::eraseContainer(NssToCursorContainerMap::iterator it)
     // This was the last cursor remaining in the given namespace.  Erase all state associated
     // with this namespace.
     size_t numDeleted = _cursorIdPrefixToNamespaceMap.erase(container.containerPrefix);
-    invariant(numDeleted == 1);
+    if (numDeleted != 1) {
+        LOGV2_ERROR(
+            4786901,
+            "Error attempting to erase CursorEntryContainer for nss {nss} and containerPrefix"
+            "{prefix}. Could not find containerPrefix in map from cursor ID prefix to nss. "
+            "Expected 'numDeleted' to be 1, but got {actualNumDeleted}",
+            "Error attempting to erase CursorEntryContainer. Could not find containerPrefix in map "
+            "from cursor id prefix to namespace string.",
+            "nss"_attr = it->first,
+            "prefix"_attr = container.containerPrefix,
+            "actualNumDeleted"_attr = numDeleted);
+        logCursorManagerInfo();
+        MONGO_UNREACHABLE;
+    }
+    const auto nssRemoved = it->first;
     _namespaceToContainerMap.erase(it++);
+    _log.push({LogEvent::Type::kNamespaceEntryMapErased,
+               boost::none,
+               boost::none,
+               std::move(nssRemoved)});
+
     invariant(_namespaceToContainerMap.size() == _cursorIdPrefixToNamespaceMap.size());
     return it;
 }
@@ -697,7 +752,7 @@ StatusWith<ClusterClientCursorGuard> ClusterCursorManager::_detachCursor(WithLoc
                                                                          OperationContext* opCtx,
                                                                          const NamespaceString& nss,
                                                                          CursorId cursorId) {
-
+    _log.push({LogEvent::Type::kDetachAttempt, cursorId, boost::none, nss});
     CursorEntry* entry = _getEntry(lk, nss, cursorId);
     if (!entry) {
         return cursorNotFoundStatus(nss, cursorId);
@@ -720,7 +775,107 @@ StatusWith<ClusterClientCursorGuard> ClusterCursorManager::_detachCursor(WithLoc
         eraseContainer(nsToContainerIt);
     }
 
+    _log.push({LogEvent::Type::kDetachComplete, cursorId, boost::none, nss});
+
     return std::move(cursor);
 }
 
+void ClusterCursorManager::logCursorManagerInfo() const {
+    LOGV2_ERROR_OPTIONS(4786900,
+                        logv2::LogTruncation::Disabled,
+                        "Dumping cursor manager contents. "
+                        "NSS -> Container map: {nssToContainer} "
+                        "Cursor ID Prefix -> NSS map: {cursorIdToNss} "
+                        "Internal log: {internalLog}",
+                        "Dumping cursor manager contents.",
+                        "{nssToContainer}"_attr = dumpNssToContainerMap(),
+                        "{cursorIdToNss}"_attr = dumpCursorIdToNssMap(),
+                        "{internalLog}"_attr = dumpInternalLog());
+}
+
+std::string ClusterCursorManager::LogEvent::typeToString(ClusterCursorManager::LogEvent::Type t) {
+    const static stdx::unordered_map<LogEvent::Type, std::string> kMap = {
+        {Type::kRegisterAttempt, "registerAttempt"},
+        {Type::kRegisterComplete, "registerComplete"},
+        {Type::kCheckoutAttempt, "checkoutAttempt"},
+        {Type::kCheckoutComplete, "checkoutComplete"},
+        {Type::kCheckInAttempt, "checkInAttempt"},
+        {Type::kCheckInCompleteCursorSaved, "checkInCompleteCursorSaved"},
+        {Type::kDetachAttempt, "detachAttempt"},
+        {Type::kDetachComplete, "detachComplete"},
+        {Type::kNamespaceEntryMapErased, "namespaceEntryMapErased"},
+        {Type::kRemoveCursorsSatisfyingPredicateAttempt, "killCursorsSatisfyingPredicateAttempt"},
+        {Type::kRemoveCursorsSatisfyingPredicateComplete, "killCursorsSatisfyingPredicateComplete"},
+        {Type::kKillCursorAttempt, "killCursorAttempt"},
+    };
+
+    if (auto it = kMap.find(t); it != kMap.end()) {
+        return it->second;
+    }
+    return "unknown " + std::to_string(static_cast<int>(t));
+}
+
+BSONObj ClusterCursorManager::dumpNssToContainerMap() const {
+    BSONObjBuilder bob;
+    // Record an object for the NSS -> Container map.
+    {
+        BSONObjBuilder nssToContainer(bob.subobjStart("nssToContainer"));
+        for (auto&& [nss, cursorContainer] : _namespaceToContainerMap) {
+            BSONObjBuilder nssBob(nssToContainer.subobjStart(nss.toString()));
+            nssBob.appendIntOrLL("containerPrefix",
+                                 static_cast<int64_t>(cursorContainer.containerPrefix));
+            BSONArrayBuilder cursors(nssBob.subarrayStart("cursors"));
+            for (auto&& [cursorId, cursorEntry] : cursorContainer.entryMap) {
+                BSONObjBuilder cursorBob(cursors.subobjStart());
+                cursorBob.appendIntOrLL("id", cursorId);
+                cursorBob.append("lastActive", cursorEntry.getLastActive());
+            }
+        }
+    }
+    return bob.obj();
+}
+
+BSONObj ClusterCursorManager::dumpCursorIdToNssMap() const {
+    BSONObjBuilder bob;
+
+    // Record an array for the Cursor ID Prefix -> NSS map.
+    {
+        BSONArrayBuilder cursorIdPrefixToNss(bob.subarrayStart("cursorIdPrefixToNss"));
+        for (auto&& [cursorIdPrefix, nss] : _cursorIdPrefixToNamespaceMap) {
+            BSONObjBuilder bob(cursorIdPrefixToNss.subobjStart());
+            bob.appendIntOrLL("cursorIdPrefix", static_cast<int64_t>(cursorIdPrefix));
+            bob.append("nss", nss.toString());
+        }
+    }
+
+    return bob.obj();
+}
+
+BSONObj ClusterCursorManager::dumpInternalLog() const {
+    BSONObjBuilder bob;
+    // Dump the internal log maintained by the ClusterCursorManager.
+    {
+        BSONArrayBuilder logBuilder(bob.subarrayStart("log"));
+        size_t i = _log.start;
+        while (i != _log.end) {
+            BSONObjBuilder bob(logBuilder.subobjStart());
+            const auto& logEntry = _log.events[i];
+            if (logEntry.cursorId) {
+                bob.appendIntOrLL("cursorId", *logEntry.cursorId);
+            }
+            bob.append("type", LogEvent::typeToString(logEntry.type));
+
+            if (logEntry.time) {
+                bob.append("approxTime", *logEntry.time);
+            }
+
+            if (logEntry.nss) {
+                bob.append("nss", logEntry.nss->toString());
+            }
+
+            i = (i + 1) % _log.events.size();
+        }
+    }
+    return bob.obj();
+}
 }  // namespace mongo
diff --git a/src/mongo/s/query/cluster_cursor_manager.h b/src/mongo/s/query/cluster_cursor_manager.h
index 3dd8cd90ba4..0b1055e1b9c 100644
--- a/src/mongo/s/query/cluster_cursor_manager.h
+++ b/src/mongo/s/query/cluster_cursor_manager.h
@@ -392,6 +392,74 @@ private:
     using CursorEntryMap = stdx::unordered_map<CursorId, CursorEntry>;
     using NssToCursorContainerMap = stdx::unordered_map<NamespaceString, CursorEntryContainer>;
 
+    // Internal, fixed size log of events cursor manager. This has been added to help diagnose
+    // SERVER-27796.
+    struct LogEvent {
+        enum class Type {
+            kRegisterAttempt,   // Any attempt to create a cursor.
+            kRegisterComplete,  // A cursor actually being created.
+
+            // Checking out a cursor.
+            kCheckoutAttempt,
+            kCheckoutComplete,
+
+            // Caller attempts to check a cursor in. This event may be followed by a
+            // kCheckInCompleteCursorSaved, or by events which indicate the cursor is deleted.
+            kCheckInAttempt,
+
+            // Logged when the check-in is successful and the cursor is kept.
+            kCheckInCompleteCursorSaved,
+
+            // Detaching a cursor (and erasing associated namespace).
+            kDetachAttempt,
+            kDetachComplete,
+            kNamespaceEntryMapErased,
+
+            // These mark the beginning and end of the period where
+            // killCursorsSatisfyingPredicate() holds a lock.
+            kRemoveCursorsSatisfyingPredicateAttempt,
+            kRemoveCursorsSatisfyingPredicateComplete,
+
+            // Any call to killCursor().
+            kKillCursorAttempt,
+
+            // Represents each time killCursorsSatisfyingPredicate() detaches a cursor that it
+            // intends to destroy.
+            kCursorMarkedForDeletionBySatisfyingPredicate,
+
+            //
+            // NOTE: If you ever add to this enum be sure to update the typeToString() method
+            // below.
+            //
+        };
+
+        static std::string typeToString(Type);
+
+        Type type;
+
+        // boost::none for log entries that don't have an associated cursor ID.
+        boost::optional<CursorId> cursorId;
+
+        // Time is not always provided to avoid having to read the clock while the mutex is held.
+        boost::optional<Date_t> time;
+        boost::optional<NamespaceString> nss;
+    };
+
+    // Circular queue used to store the latest events that happened in the ClusterCursorManager.
+    struct CircularLogQueue {
+        std::vector<LogEvent> events{512};
+        size_t start = 0;
+        size_t end = 0;
+
+        void push(LogEvent&& e) {
+            events[end] = std::move(e);
+            end = (end + 1) % events.size();
+            if (end == start) {
+                start = (start + 1) % events.size();
+            }
+        }
+    };
+
     /**
      * Transfers ownership of the given pinned cursor back to the manager, and moves the cursor to
      * the 'idle' state.
@@ -444,13 +512,15 @@ private:
     void killOperationUsingCursor(WithLock, CursorEntry* entry);
 
     /**
-     * Kill the cursors satisfying the given predicate. Assumes that 'lk' is held upon entry.
+     * Kill the cursors satisfying the given predicate. Assumes that 'lk' is held upon entry. The
+     * 'now' parameter is only used for the internal logging mechansim.
      *
      * Returns the number of cursors killed.
      */
     std::size_t killCursorsSatisfying(stdx::unique_lock<Latch> lk,
                                       OperationContext* opCtx,
-                                      std::function<bool(CursorId, const CursorEntry&)> pred);
+                                      std::function<bool(CursorId, const CursorEntry&)> pred,
+                                      Date_t now);
 
     /**
      * CursorEntry is a moveable, non-copyable container for a single cursor.
@@ -606,6 +676,20 @@ private:
      */
     NssToCursorContainerMap::iterator eraseContainer(NssToCursorContainerMap::iterator it);
 
+    /**
+     * Functions which dump the state/history of the cursor manager into a BSONObj for debug
+     * purposes.
+     */
+    BSONObj dumpCursorIdToNssMap() const;
+    BSONObj dumpNssToContainerMap() const;
+    BSONObj dumpInternalLog() const;
+
+    /**
+     * Logs objects which summarize the current state of the cursor manager as well as its recent
+     * history.
+     */
+    void logCursorManagerInfo() const;
+
     // Clock source.  Used when the 'last active' time for a cursor needs to be set/updated.  May be
     // concurrently accessed by multiple threads.
     ClockSource* _clockSource;
@@ -616,6 +700,7 @@ private:
     bool _inShutdown{false};
 
     // Randomness source.  Used for cursor id generation.
+    const int64_t _randomSeed;
     PseudoRandom _pseudoRandom;
 
     // Map from cursor id prefix to associated namespace.  Exists only to provide namespace lookup
@@ -637,6 +722,8 @@ private:
     NssToCursorContainerMap _namespaceToContainerMap;
 
     size_t _cursorsTimedOut = 0;
+
+    CircularLogQueue _log;
 };
 
 }  // namespace mongo