SERVER-46058 Redaction of BSONObj results in BSONObj and not a string.

8 files changed, 88 insertions, 29 deletions

diff --git a/src/mongo/bson/bsonobj.cpp b/src/mongo/bson/bsonobj.cpp
index 5ed88c978aa..994cbde6070 100644
--- a/src/mongo/bson/bsonobj.cpp
+++ b/src/mongo/bson/bsonobj.cpp
@@ -28,6 +28,7 @@
  */
 
 #define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kDefault
+#define MONGO_LOGV2_DEFAULT_COMPONENT ::mongo::logv2::LogComponent::kDefault
 
 #include "mongo/db/jsobj.h"
 
@@ -38,6 +39,7 @@
 #include "mongo/bson/generator_extended_relaxed_2_0_0.h"
 #include "mongo/bson/generator_legacy_strict.h"
 #include "mongo/db/json.h"
+#include "mongo/logv2/log.h"
 #include "mongo/util/allocator.h"
 #include "mongo/util/hex.h"
 #include "mongo/util/log.h"
@@ -111,14 +113,7 @@ BSONObj BSONObj::copy() const {
     // those assumptions, and preserving any currently observed behavior does not form an argument
     // against the later application of such optimizations.
     int size = objsize();
-    if (!isOwned() && (size < kMinBSONLength || size > BufferMaxSize)) {
-        // Only for unowned objects, the size is validated in the constructor, so it is an error for
-        // the size to ever be invalid. This means that the unowned memory we are reading has
-        // changed, and we must exit immediately to avoid further undefined behavior.
-        severe() << "BSONObj::copy() - size " << size
-                 << " of unowned BSONObj is invalid and differs from previously validated size.";
-        fassertFailed(31322);
-    }
+    _validateUnownedSize(size);
     auto storage = SharedBuffer::allocate(size);
 
     // If the call to objsize() changes between this call and the previous one, this indicates that
@@ -143,6 +138,42 @@ BSONObj BSONObj::getOwned(const BSONObj& obj) {
     return obj.getOwned();
 }
 
+BSONObj BSONObj::redact() const {
+    _validateUnownedSize(objsize());
+
+    // Helper to get an "internal function" to be able to do recursion
+    struct redactor {
+        void operator()(BSONObjBuilder& builder, const BSONObj& obj) {
+            for (BSONElement e : obj) {
+                if (e.type() == Object || e.type() == Array) {
+                    BSONObjBuilder subBuilder = builder.subobjStart(e.fieldNameStringData());
+                    operator()(subBuilder, e.Obj());
+                    subBuilder.done();
+                } else {
+                    builder.append(e.fieldNameStringData(), "###"_sd);
+                }
+            }
+        }
+    };
+
+    BSONObjBuilder builder;
+    redactor()(builder, *this);
+    return builder.obj();
+}
+
+void BSONObj::_validateUnownedSize(int size) const {
+    // Only for unowned objects, the size is validated in the constructor, so it is an error for
+    // the size to ever be invalid. This means that the unowned memory we are reading has
+    // changed, and we must exit immediately to avoid further undefined behavior.
+    if (!isOwned() && (size < kMinBSONLength || size > BufferMaxSize)) {
+        LOGV2_FATAL(51772,
+                    "BSONObj::_validateUnownedSize() - size {size} of unowned BSONObj is invalid "
+                    "and differs from previously validated size.",
+                    "size"_attr = size);
+        fassertFailed(31322);
+    }
+}
+
 template <typename Generator>
 BSONObj BSONObj::_jsonStringGenerator(const Generator& g,
                                       int pretty,
diff --git a/src/mongo/bson/bsonobj.h b/src/mongo/bson/bsonobj.h
index 6df5e45ce57..fbdb1c7f791 100644
--- a/src/mongo/bson/bsonobj.h
+++ b/src/mongo/bson/bsonobj.h
@@ -249,6 +249,9 @@ public:
     /** @return a new full (and owned) copy of the object. */
     BSONObj copy() const;
 
+    /** @return a new full (and owned) redacted copy of the object. */
+    BSONObj redact() const;
+
     /** Readable representation of a BSON object in an extended JSON-style notation.
         This is an abbreviated representation which might be used for logging.
     */
@@ -624,6 +627,8 @@ private:
             _assertInvalid(Traits::MaxSize);
     }
 
+    void _validateUnownedSize(int size) const;
+
     const char* _objdata;
     ConstSharedBuffer _ownedBuffer;
 };
diff --git a/src/mongo/db/commands.cpp b/src/mongo/db/commands.cpp
index 9f7fb5991b3..fbcf69dc8c2 100644
--- a/src/mongo/db/commands.cpp
+++ b/src/mongo/db/commands.cpp
@@ -694,7 +694,7 @@ public:
 
 private:
     void run(OperationContext* opCtx, rpc::ReplyBuilderInterface* result) override {
-        opCtx->lockState()->setDebugInfo(redact(_request->body));
+        opCtx->lockState()->setDebugInfo(redact(_request->body).toString());
         bool ok = _command->runWithReplyBuilder(opCtx, _dbName, _request->body, result);
         if (!ok) {
             BSONObjBuilder bob = result->getBodyBuilder();
diff --git a/src/mongo/db/repl/oplog.cpp b/src/mongo/db/repl/oplog.cpp
index bbd877e2a00..90062ebd3d0 100644
--- a/src/mongo/db/repl/oplog.cpp
+++ b/src/mongo/db/repl/oplog.cpp
@@ -28,6 +28,7 @@
  */
 
 #define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kReplication
+#define MONGO_LOGV2_DEFAULT_COMPONENT ::mongo::logv2::LogComponent::kReplication
 
 #include "mongo/platform/basic.h"
 
@@ -89,6 +90,7 @@
 #include "mongo/db/storage/storage_options.h"
 #include "mongo/db/transaction_participant.h"
 #include "mongo/db/views/view_catalog.h"
+#include "mongo/logv2/log.h"
 #include "mongo/platform/random.h"
 #include "mongo/rpc/get_status_from_command_result.h"
 #include "mongo/scripting/engine.h"
@@ -1452,9 +1454,12 @@ Status applyCommand_inlock(OperationContext* opCtx,
                 opCtx->recoveryUnit()->abandonSnapshot();
                 opCtx->checkForInterrupt();
 
-                LOG(1)
-                    << "Acceptable error during oplog application: background operation in progress for DB '{}' from oplog entry {}"_format(
-                           nss.db(), redact(entry.toBSON()));
+                LOGV2_DEBUG(51774,
+                            1,
+                            "Acceptable error during oplog application: background operation in "
+                            "progress for DB '{db}' from oplog entry {entry}",
+                            "db"_attr = nss.db(),
+                            "entry"_attr = redact(entry.toBSON()));
                 break;
             }
             case ErrorCodes::BackgroundOperationInProgressForNamespace: {
@@ -1478,9 +1483,12 @@ Status applyCommand_inlock(OperationContext* opCtx,
                 opCtx->recoveryUnit()->abandonSnapshot();
                 opCtx->checkForInterrupt();
 
-                LOG(1)
-                    << "Acceptable error during oplog application: background operation in progress for ns '{}' from oplog entry {}"_format(
-                           ns, redact(entry.toBSON()));
+                LOGV2_DEBUG(51775,
+                            1,
+                            "Acceptable error during oplog application: background operation in "
+                            "progress for ns '{ns}' from oplog entry {entry}",
+                            "ns"_attr = ns,
+                            "entry"_attr = redact(entry.toBSON()));
                 break;
             }
             default: {
@@ -1490,9 +1498,13 @@ Status applyCommand_inlock(OperationContext* opCtx,
                     return status;
                 }
 
-                LOG(1)
-                    << "Acceptable error during oplog application on db '{}' with status '{}' from oplog entry {}"_format(
-                           nss.db(), status.toString(), redact(entry.toBSON()));
+                LOGV2_DEBUG(51776,
+                            1,
+                            "Acceptable error during oplog application on db '{db}' with status "
+                            "'{status}' from oplog entry {entry}",
+                            "db"_attr = nss.db(),
+                            "status"_attr = status,
+                            "entry"_attr = redact(entry.toBSON()));
             }
             // fallthrough
             case ErrorCodes::OK:
diff --git a/src/mongo/db/service_entry_point_common.cpp b/src/mongo/db/service_entry_point_common.cpp
index 621aebf5f77..413a113e782 100644
--- a/src/mongo/db/service_entry_point_common.cpp
+++ b/src/mongo/db/service_entry_point_common.cpp
@@ -28,6 +28,7 @@
  */
 
 #define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kCommand
+#define MONGO_LOGV2_DEFAULT_COMPONENT ::mongo::logv2::LogComponent::kCommand
 
 #include "mongo/platform/basic.h"
 
@@ -82,6 +83,7 @@
 #include "mongo/db/stats/top.h"
 #include "mongo/db/transaction_participant.h"
 #include "mongo/db/transaction_validation.h"
+#include "mongo/logv2/log.h"
 #include "mongo/rpc/factory.h"
 #include "mongo/rpc/get_status_from_command_result.h"
 #include "mongo/rpc/message.h"
@@ -127,11 +129,20 @@ void generateLegacyQueryErrorResponse(const AssertionException& exception,
                                       Message* response) {
     curop->debug().errInfo = exception.toStatus();
 
-    log(LogComponent::kQuery) << "assertion " << exception.toString() << " ns:" << queryMessage.ns
-                              << " query:"
-                              << (queryMessage.query.valid(BSONVersion::kLatest)
-                                      ? redact(queryMessage.query)
-                                      : "query object is corrupt");
+    if (queryMessage.query.valid(BSONVersion::kLatest))
+        LOGV2_OPTIONS(51777,
+                      {logv2::LogComponent::kQuery},
+                      "assertion {exception} ns: {ns} query: {query}",
+                      "exception"_attr = exception,
+                      "ns"_attr = queryMessage.ns,
+                      "query"_attr = redact(queryMessage.query));
+    else
+        LOGV2_OPTIONS(51778,
+                      {logv2::LogComponent::kQuery},
+                      "assertion {exception} ns: {ns} query object is corrupt",
+                      "exception"_attr = exception,
+                      "ns"_attr = queryMessage.ns);
+
     if (queryMessage.ntoskip || queryMessage.ntoreturn) {
         log(LogComponent::kQuery) << " ntoskip:" << queryMessage.ntoskip
                                   << " ntoreturn:" << queryMessage.ntoreturn;
diff --git a/src/mongo/logger/redaction.cpp b/src/mongo/logger/redaction.cpp
index b0ee1aff716..5cf9c1b3ae7 100644
--- a/src/mongo/logger/redaction.cpp
+++ b/src/mongo/logger/redaction.cpp
@@ -46,12 +46,12 @@ constexpr auto kRedactionDefaultMask = "###"_sd;
 
 }  // namespace
 
-std::string redact(const BSONObj& objectToRedact) {
+BSONObj redact(const BSONObj& objectToRedact) {
     if (!logger::globalLogDomain()->shouldRedactLogs()) {
-        return objectToRedact.toString(false);
+        return objectToRedact;
     }
 
-    return objectToRedact.toString(true);
+    return objectToRedact.redact();
 }
 
 StringData redact(StringData stringToRedact) {
diff --git a/src/mongo/logger/redaction.h b/src/mongo/logger/redaction.h
index 85430e382e6..c1c67997ec1 100644
--- a/src/mongo/logger/redaction.h
+++ b/src/mongo/logger/redaction.h
@@ -56,7 +56,7 @@ class DBException;
  *  In 'redact' mode replace all values with '###' and keep keys intact.
  *  In normal mode return objectToRedact.toString().
  */
-std::string redact(const BSONObj& objectToRedact);
+BSONObj redact(const BSONObj& objectToRedact);
 
 /**
  *  In 'redact mode return '###'.
diff --git a/src/mongo/logger/redaction_test.cpp b/src/mongo/logger/redaction_test.cpp
index 1c763d5ebb2..eb5902ec816 100644
--- a/src/mongo/logger/redaction_test.cpp
+++ b/src/mongo/logger/redaction_test.cpp
@@ -95,12 +95,12 @@ TEST(RedactExceptionTest, BasicException) {
 TEST(RedactBSONTest, NoRedact) {
     logger::globalLogDomain()->setShouldRedactLogs(false);
     BSONObj obj = BSON("a" << 1);
-    ASSERT_EQ(redact(obj), obj.toString());
+    ASSERT_BSONOBJ_EQ(redact(obj), obj);
 }
 
 void testBSONCases(std::initializer_list<BSONStringPair> testCases) {
     for (auto m : testCases) {
-        ASSERT_EQ(redact(m.first), m.second);
+        ASSERT_EQ(redact(m.first).toString(), m.second);
     }
 }