SERVER-36270: Add test combining backup cursors and manipulating the truncate after point.

5 files changed, 83 insertions, 64 deletions

diff --git a/jstests/libs/backup_utils.js b/jstests/libs/backup_utils.js
new file mode 100644
index 00000000000..fbf99193d8b
--- /dev/null
+++ b/jstests/libs/backup_utils.js
@@ -0,0 +1,67 @@
+function backupData(mongo, destinationDirectory) {
+    let backupCursor = openBackupCursor(mongo);
+    let metadata = copyCursorFiles(mongo, backupCursor, destinationDirectory);
+    backupCursor.close();
+    return metadata;
+}
+
+function openBackupCursor(mongo) {
+    // Opening a backup cursor can race with taking a checkpoint, resulting in a transient
+    // error. Retry until it succeeds.
+    while (true) {
+        try {
+            return mongo.getDB("admin").aggregate([{$backupCursor: {}}]);
+        } catch (exc) {
+            jsTestLog({"Failed to open a backup cursor, retrying.": exc});
+        }
+    }
+}
+
+function copyCursorFiles(mongo, backupCursor, destinationDirectory) {
+    resetDbpath(destinationDirectory);
+    mkdir(destinationDirectory + "/journal");
+
+    assert(backupCursor.hasNext());
+    let doc = backupCursor.next();
+    assert(doc.hasOwnProperty("metadata"));
+    let metadata = doc["metadata"];
+
+    while (backupCursor.hasNext()) {
+        let doc = backupCursor.next();
+        assert(doc.hasOwnProperty("filename"));
+        let dbgDoc = copyFileHelper(doc["filename"], metadata["dbpath"], destinationDirectory);
+        dbgDoc["msg"] = "File copy";
+        jsTestLog(dbgDoc);
+    }
+
+    jsTestLog({
+        msg: "Destination",
+        destination: destinationDirectory,
+        dbpath: ls(destinationDirectory),
+        journal: ls(destinationDirectory + "/journal")
+    });
+
+    return metadata;
+}
+
+function copyFileHelper(absoluteFilePath, sourceDbPath, destinationDirectory) {
+    // Ensure the dbpath ends with an OS appropriate slash.
+    let lastChar = sourceDbPath[sourceDbPath.length - 1];
+    if (lastChar !== '/' && lastChar !== '\\') {
+        if (_isWindows()) {
+            sourceDbPath += '\\';
+        } else {
+            sourceDbPath += '/';
+        }
+    }
+
+    // Ensure that the full path starts with the returned dbpath.
+    assert.eq(0, absoluteFilePath.indexOf(sourceDbPath));
+
+    // Grab the file path relative to the dbpath. Maintain that relation when copying
+    // to the `hiddenDbpath`.
+    let relativePath = absoluteFilePath.substr(sourceDbPath.length);
+    let destination = destinationDirectory + '/' + relativePath;
+    copyFile(absoluteFilePath, destination);
+    return {fileSource: absoluteFilePath, relativePath: relativePath, fileDestination: destination};
+}
diff --git a/jstests/noPassthrough/libs/backup_restore.js b/jstests/noPassthrough/libs/backup_restore.js
index 4641fcbb62d..2de982f6883 100644
--- a/jstests/noPassthrough/libs/backup_restore.js
+++ b/jstests/noPassthrough/libs/backup_restore.js
@@ -361,51 +361,14 @@ var BackupRestoreTest = function(options) {
             assert.gt(copiedFiles.length, 0, testName + ' no files copied');
             rst.start(secondary.nodeId, {}, true);
         } else if (options.backup == 'backupCursor') {
-            resetDbpath(hiddenDbpath);
-            mkdir(hiddenDbpath + '/journal');
-            jsTestLog("Copying start: " + tojson({
-                          source: dbpathSecondary,
-                          destination: hiddenDbpath,
-                          sourceFiles: ls(dbpathSecondary),
-                          journalFiles: ls(dbpathSecondary + '/journal')
-                      }));
-
-            let backupCursor = secondary.getDB('admin').aggregate([{$backupCursor: {}}]);
-            assert(backupCursor.hasNext());
-            let doc = backupCursor.next();
-            assert(doc.hasOwnProperty('metadata'));
-            jsTestLog("Metadata doc: " + tojson({doc: doc}));
-
-            // Grab the dbpath, ensure it ends with a slash. Note that while the `dbpath` inputs
-            // may be in windows or unix format, the FS helpers for listing a directory and
-            // copying files (etc..)  treat them equally.
-            let dbpath = doc['metadata']['dbpath'];
-            if (dbpath.lastIndexOf('/') + 1 != dbpath.length &&
-                dbpath.lastIndexOf('\\') + 1 != dbpath.length) {
-                dbpath += '/';
-            }
-
-            while (backupCursor.hasNext()) {
-                doc = backupCursor.next();
-
-                let fileToCopy = doc['filename'];
-                // Ensure that the full path starts with the returned dbpath.
-                assert.eq(0, fileToCopy.search(dbpath));
-
-                // Grab the file path relative to the dbpath. Maintain that relation when copying
-                // to the `hiddenDbpath`.
-                let relativePath = fileToCopy.substr(dbpath.length);
-                jsTestLog("File copy: " +
-                          tojson({fileToCopy: fileToCopy, relativePath: relativePath}));
-                copyFile(fileToCopy, hiddenDbpath + '/' + relativePath);
-            }
+            load("jstests/libs/backup_utils.js");
 
+            backupData(secondary, hiddenDbpath);
             copiedFiles = ls(hiddenDbpath);
             jsTestLog("Copying End: " + tojson({
                           destinationFiles: copiedFiles,
                           destinationJournal: ls(hiddenDbpath + '/journal')
                       }));
-            backupCursor.close();
             assert.gt(copiedFiles.length, 0, testName + ' no files copied');
         }
 
diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp b/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp
index 2aed5a1feff..8139572f643 100644
--- a/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp
+++ b/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp
@@ -303,9 +303,8 @@ public:
                     WT_SESSION* s = session->getSession();
                     invariantWTOK(s->checkpoint(s, "use_timestamp=true"));
 
-                    // Now that the checkpoint is durable, publish the previously recorded stable
-                    // timestamp and oplog needed to recover from it.
-                    _lastStableCheckpointTimestamp.store(stableTimestamp.asULL());
+                    // Now that the checkpoint is durable, publish the oplog needed to recover
+                    // from it.
                     _oplogNeededForCrashRecovery.store(oplogNeededForRollback.asULL());
                 }
             } catch (const WriteConflictException&) {
@@ -348,10 +347,6 @@ public:
         }
     }
 
-    std::uint64_t getLastStableCheckpointTimestamp() const {
-        return _lastStableCheckpointTimestamp.load();
-    }
-
     std::uint64_t getOplogNeededForCrashRecovery() const {
         return _oplogNeededForCrashRecovery.load();
     }
@@ -380,10 +375,6 @@ private:
 
     bool _hasTriggeredFirstStableCheckpoint = false;
 
-    // The earliest stable timestamp at which the last checkpoint could have been taken. The
-    // checkpoint might have used a newer stable timestamp if stable was updated concurrently with
-    // checkpointing.
-    AtomicWord<std::uint64_t> _lastStableCheckpointTimestamp;
     AtomicWord<std::uint64_t> _oplogNeededForCrashRecovery;
 };
 
@@ -1659,7 +1650,7 @@ boost::optional<Timestamp> WiredTigerKVEngine::getLastStableRecoveryTimestamp()
         return stable;
     }
 
-    const auto ret = _checkpointThread->getLastStableCheckpointTimestamp();
+    const auto ret = _getCheckpointTimestamp();
     if (ret) {
         return Timestamp(ret);
     }
@@ -1743,4 +1734,13 @@ Timestamp WiredTigerKVEngine::getInitialDataTimestamp() const {
     return Timestamp(_initialDataTimestamp.load());
 }
 
+std::uint64_t WiredTigerKVEngine::_getCheckpointTimestamp() const {
+    char buf[(2 * 8 /*bytes in hex*/) + 1 /*nul terminator*/];
+    invariantWTOK(_conn->query_timestamp(_conn, buf, "get=last_checkpoint"));
+
+    std::uint64_t tmp;
+    fassert(50963, parseNumberFromStringWithBase(buf, 16, &tmp));
+    return tmp;
+}
+
 }  // namespace mongo
diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.h b/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.h
index 6712bd35fc3..38ea22be720 100644
--- a/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.h
+++ b/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.h
@@ -393,6 +393,8 @@ private:
      */
     bool _canRecoverToStableTimestamp() const;
 
+    std::uint64_t _getCheckpointTimestamp() const;
+
     WT_CONNECTION* _conn;
     WiredTigerFileVersion _fileVersion;
     WiredTigerEventHandler _eventHandler;
diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_record_store.cpp b/src/mongo/db/storage/wiredtiger/wiredtiger_record_store.cpp
index 04bdd8d3636..25aa2b1aad0 100644
--- a/src/mongo/db/storage/wiredtiger/wiredtiger_record_store.cpp
+++ b/src/mongo/db/storage/wiredtiger/wiredtiger_record_store.cpp
@@ -1746,12 +1746,7 @@ void WiredTigerRecordStore::_increaseDataSize(OperationContext* opCtx, int64_t a
 void WiredTigerRecordStore::cappedTruncateAfter(OperationContext* opCtx,
                                                 RecordId end,
                                                 bool inclusive) {
-    // Only log messages at a lower level here for testing.
-    int logLevel = getTestCommandsEnabled() ? 0 : 2;
-
     std::unique_ptr<SeekableRecordCursor> cursor = getCursor(opCtx, true);
-    LOG(logLevel) << "Truncating capped collection '" << _ns
-                  << "' in WiredTiger record store, (inclusive=" << inclusive << ")";
 
     auto record = cursor->seekExact(end);
     massert(28807, str::stream() << "Failed to seek to the record located at " << end, record);
@@ -1772,7 +1767,6 @@ void WiredTigerRecordStore::cappedTruncateAfter(OperationContext* opCtx,
         // that is being deleted.
         record = cursor->next();
         if (!record) {
-            LOG(logLevel) << "No records to delete for truncation";
             return;  // No records to delete.
         }
         lastKeptId = end;
@@ -1789,8 +1783,6 @@ void WiredTigerRecordStore::cappedTruncateAfter(OperationContext* opCtx,
             }
             recordsRemoved++;
             bytesRemoved += record->data.size();
-            LOG(logLevel) << "Record id to delete for truncation of '" << _ns << "': " << record->id
-                          << " (" << Timestamp(record->id.repr()) << ")";
         } while ((record = cursor->next()));
     }
 
@@ -1802,10 +1794,6 @@ void WiredTigerRecordStore::cappedTruncateAfter(OperationContext* opCtx,
     WT_CURSOR* start = startwrap.get();
     setKey(start, firstRemovedId);
 
-    LOG(logLevel) << "Truncating collection '" << _ns << "' from " << firstRemovedId << " ("
-                  << Timestamp(firstRemovedId.repr()) << ")"
-                  << " to the end. Number of records to delete: " << recordsRemoved;
-
     WT_SESSION* session = WiredTigerRecoveryUnit::get(opCtx)->getSession()->getSession();
     invariantWTOK(session->truncate(session, nullptr, start, nullptr, nullptr));
 
@@ -1818,7 +1806,6 @@ void WiredTigerRecordStore::cappedTruncateAfter(OperationContext* opCtx,
         // Immediately rewind visibility to our truncation point, to prevent new
         // transactions from appearing.
         Timestamp truncTs(lastKeptId.repr());
-        LOG(logLevel) << "Rewinding oplog visibility point to " << truncTs << " after truncation.";
 
         if (!serverGlobalParams.enableMajorityReadConcern) {
             // If majority read concern is disabled, we must set the oldest timestamp along with the