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, 235 insertions, 8 deletions

diff --git a/src/mongo/s/query/cluster_cursor_manager.cpp b/src/mongo/s/query/cluster_cursor_manager.cpp
index 15ac5d3ef34..72ef8ce6635 100644
--- a/src/mongo/s/query/cluster_cursor_manager.cpp
+++ b/src/mongo/s/query/cluster_cursor_manager.cpp
@@ -243,7 +243,8 @@ boost::optional<TxnNumber> ClusterCursorManager::PinnedCursor::getTxnNumber() co
 
 ClusterCursorManager::ClusterCursorManager(ClockSource* clockSource)
     : _clockSource(clockSource),
-      _pseudoRandom(std::unique_ptr<SecureRandom>(SecureRandom::create())->nextInt64()) {
+      _randomSeed(std::unique_ptr<SecureRandom>(SecureRandom::create())->nextInt64()),
+      _pseudoRandom(_randomSeed) {
     invariant(_clockSource);
 }
 
@@ -271,6 +272,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();
@@ -323,6 +325,7 @@ StatusWith<CursorId> ClusterCursorManager::registerCursor(
         cursorId,
         CursorEntry(std::move(cursor), cursorType, cursorLifetime, now, authenticatedUsers));
     invariant(emplaceResult.second);
+    _log.push({LogEvent::Type::kRegisterComplete, cursorId, now, nss});
 
     return cursorId;
 }
@@ -333,7 +336,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,
@@ -379,6 +385,7 @@ StatusWith<ClusterCursorManager::PinnedCursor> ClusterCursorManager::checkOutCur
         }
     }
     cursor->reattachToOperationContext(opCtx);
+    _log.push({LogEvent::Type::kCheckoutComplete, cursorId, now, nss});
     return PinnedCursor(this, std::move(cursor), nss, cursorId);
 }
 
@@ -397,6 +404,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);
@@ -408,6 +416,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;
     }
@@ -449,8 +458,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);
@@ -488,6 +500,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 {
@@ -502,24 +515,28 @@ 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<std::unique_ptr<ClusterClientCursor>> cursorsToDestroy;
     auto nsContainerIt = _namespaceToContainerMap.begin();
     while (nsContainerIt != _namespaceToContainerMap.end()) {
@@ -544,6 +561,13 @@ std::size_t ClusterCursorManager::killCursorsSatisfying(
             }
 
             cursorsToDestroy.push_back(entry.releaseCursor(nullptr));
+            _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});
 
             // Destroy the entry and set the iterator to the next element.
             entryMap.erase(cursorIdEntryIt++);
@@ -556,6 +580,13 @@ 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});
     // Call kill() outside of the lock, as it may require waiting for callbacks to finish.
     lk.unlock();
 
@@ -750,15 +781,30 @@ 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) {
+        LOG(0).setIsTruncatable(false)
+            << "Error attempting to erase CursorEntryContainer for nss " << it->first
+            << " and containerPrefix " << container.containerPrefix
+            << ". Could not find containerPrefix in map from cursor ID prefix to nss. Expected "
+               "'numDeleted' to be 1, but got "
+            << 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;
 }
 
 StatusWith<std::unique_ptr<ClusterClientCursor>> ClusterCursorManager::_detachCursor(
     WithLock lk, NamespaceString const& nss, CursorId cursorId) {
-
+    _log.push({LogEvent::Type::kDetachAttempt, cursorId, boost::none, nss});
     CursorEntry* entry = _getEntry(lk, nss, cursorId);
     if (!entry) {
         return cursorNotFoundStatus(nss, cursorId);
@@ -781,7 +827,101 @@ StatusWith<std::unique_ptr<ClusterClientCursor>> ClusterCursorManager::_detachCu
         eraseContainer(nsToContainerIt);
     }
 
+    _log.push({LogEvent::Type::kDetachComplete, cursorId, boost::none, nss});
+
     return std::move(cursor);
 }
 
+void ClusterCursorManager::logCursorManagerInfo() const {
+    LOG(0).setIsTruncatable(false) << "Dumping cursor manager contents."
+                                   << " NSS -> Container map:  " << dumpNssToContainerMap()
+                                   << " Cursor ID Prefix -> NSS map: " << dumpCursorIdToNssMap()
+                                   << " Internal log: " << dumpInternalLog();
+}
+
+std::string ClusterCursorManager::LogEvent::typeToString(ClusterCursorManager::LogEvent::Type t) {
+    static const 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 e2d58bcfb1a..84652ad5c22 100644
--- a/src/mongo/s/query/cluster_cursor_manager.h
+++ b/src/mongo/s/query/cluster_cursor_manager.h
@@ -489,6 +489,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.
@@ -540,13 +608,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.
@@ -690,6 +760,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;
@@ -700,6 +784,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
@@ -721,6 +806,8 @@ private:
     NssToCursorContainerMap _namespaceToContainerMap;
 
     size_t _cursorsTimedOut = 0;
+
+    CircularLogQueue _log;
 };
 
 }  // namespace mongo