diff options
Diffstat (limited to 'src/mongo/logv2')
| -rw-r--r-- | src/mongo/logv2/log_capture_backend.h | 37 | ||||
| -rw-r--r-- | src/mongo/logv2/log_component.h | 1 | ||||
| -rw-r--r-- | src/mongo/logv2/logv2_test.cpp | 287 | ||||
| -rw-r--r-- | src/mongo/logv2/redaction.cpp | 6 | ||||
| -rw-r--r-- | src/mongo/logv2/redaction_test.cpp | 95 |
5 files changed, 278 insertions, 148 deletions
diff --git a/src/mongo/logv2/log_capture_backend.h b/src/mongo/logv2/log_capture_backend.h index 701ec62a9d4..4078934fb4c 100644 --- a/src/mongo/logv2/log_capture_backend.h +++ b/src/mongo/logv2/log_capture_backend.h @@ -37,31 +37,44 @@ #include <string> #include <vector> +#include "mongo/platform/atomic_word.h" + namespace mongo::logv2 { + +/* + * LogLineListener is a wrapper class used in the LogCaptureBackend that defines what to do with + * log lines upon consumption. + */ +class LogLineListener { +public: + virtual ~LogLineListener() = default; + virtual void accept(const std::string& line) = 0; +}; + class LogCaptureBackend : public boost::log::sinks:: - basic_formatted_sink_backend<char, boost::log::sinks::synchronized_feeding> { + basic_formatted_sink_backend<char, boost::log::sinks::concurrent_feeding> { public: - LogCaptureBackend(std::vector<std::string>& lines, bool stripEol) - : _stripEol(stripEol), _logLines(lines) {} + LogCaptureBackend(std::unique_ptr<LogLineListener> logListener, bool stripEol) + : _logListener{std::move(logListener)}, _stripEol(stripEol) {} - static boost::shared_ptr<boost::log::sinks::synchronous_sink<LogCaptureBackend>> create( - std::vector<std::string>& lines, bool stripEol) { - return boost::make_shared<boost::log::sinks::synchronous_sink<LogCaptureBackend>>( - boost::make_shared<LogCaptureBackend>(lines, stripEol)); + static boost::shared_ptr<boost::log::sinks::unlocked_sink<LogCaptureBackend>> create( + std::unique_ptr<LogLineListener> logListener, bool stripEol) { + return boost::make_shared<boost::log::sinks::unlocked_sink<LogCaptureBackend>>( + boost::make_shared<LogCaptureBackend>(std::move(logListener), stripEol)); } void consume(boost::log::record_view const& rec, string_type const& formatted_string) { - if (_stripEol && !formatted_string.empty() && + if (_stripEol.load() && !formatted_string.empty() && formatted_string[formatted_string.size() - 1] == '\n') { - _logLines.push_back(formatted_string.substr(0, formatted_string.size() - 1)); + _logListener->accept(formatted_string.substr(0, formatted_string.size() - 1)); } else { - _logLines.push_back(formatted_string); + _logListener->accept(formatted_string); } } private: - bool _stripEol; - std::vector<std::string>& _logLines; + std::unique_ptr<LogLineListener> _logListener; + AtomicWord<bool> _stripEol; }; } // namespace mongo::logv2 diff --git a/src/mongo/logv2/log_component.h b/src/mongo/logv2/log_component.h index 2b1985756b9..90aced1c07a 100644 --- a/src/mongo/logv2/log_component.h +++ b/src/mongo/logv2/log_component.h @@ -61,6 +61,7 @@ namespace mongo::logv2 { X(kNetwork, , "network" , "NETWORK" , kDefault) \ X(kProcessHealth, , "processHealth" , "HEALTH" , kDefault) \ X(kQuery, , "query" , "QUERY" , kDefault) \ + X(kQueryStats, , "queryStats" , "QRYSTATS", kDefault) \ X(kReplication, , "replication" , "REPL" , kDefault) \ X(kReplicationElection, , "election" , "ELECTION", kReplication) \ X(kReplicationHeartbeats, , "heartbeats" , "REPL_HB" , kReplication) \ diff --git a/src/mongo/logv2/logv2_test.cpp b/src/mongo/logv2/logv2_test.cpp index 2477d27033b..899440b4fba 100644 --- a/src/mongo/logv2/logv2_test.cpp +++ b/src/mongo/logv2/logv2_test.cpp @@ -64,6 +64,7 @@ #include "mongo/unittest/death_test.h" #include "mongo/unittest/temp_dir.h" #include "mongo/unittest/unittest.h" +#include "mongo/util/shared_buffer.h" #include "mongo/util/str_escape.h" #include "mongo/util/string_map.h" #include "mongo/util/uuid.h" @@ -192,10 +193,21 @@ void applyDefaultFilterToSink(SinkPtr&& sink) { sink->set_filter(ComponentSettingsFilter(mgr().getGlobalDomain(), mgr().getGlobalSettings())); } +class Listener : public logv2::LogLineListener { +public: + explicit Listener(synchronized_value<std::vector<std::string>>* sv) : _sv(sv) {} + void accept(const std::string& line) override { + (***_sv).push_back(line); + } + +private: + synchronized_value<std::vector<std::string>>* _sv; +}; + class LogDuringInitShutdownTester { public: LogDuringInitShutdownTester() { - auto sink = LogCaptureBackend::create(lines, true); + auto sink = LogCaptureBackend::create(std::make_unique<Listener>(&syncedLines), true); applyDefaultFilterToSink(sink); // We have to leave this sink installed as it is not allowed to install sinks during // shutdown. Add a filter so it is only used during this test. @@ -205,15 +217,15 @@ public: ScopeGuard enabledGuard([this] { enabled = false; }); LOGV2(20001, "log during init"); - ASSERT_EQUALS(lines.back(), "log during init"); + ASSERT_EQUALS((**syncedLines).back(), "log during init"); } ~LogDuringInitShutdownTester() { enabled = true; LOGV2(4600800, "log during shutdown"); - ASSERT_EQUALS(lines.back(), "log during shutdown"); + ASSERT_EQUALS((**syncedLines).back(), "log during shutdown"); } - std::vector<std::string> lines; + synchronized_value<std::vector<std::string>> syncedLines; bool enabled = true; }; @@ -225,28 +237,30 @@ public: public: LineCapture() = delete; LineCapture(bool stripEol) - : _lines{std::make_unique<std::vector<std::string>>()}, - _sink{LogCaptureBackend::create(*_lines, stripEol)} {} - auto& lines() { - return *_lines; + : _syncedLines{synchronized_value<std::vector<std::string>>()}, + _sink{ + LogCaptureBackend::create(std::make_unique<Listener>(&_syncedLines), stripEol)} {} + auto lines() { + return **_syncedLines; } auto& sink() { return _sink; } - const std::string& back() const { - ASSERT_GT(_lines->size(), 0); - return _lines->back(); + std::string back() const { + auto logLinesLockGuard = *_syncedLines; + ASSERT_GT(logLinesLockGuard->size(), 0); + return logLinesLockGuard->back(); } void clear() { - return _lines->clear(); + return (**_syncedLines).clear(); } size_t size() const { - return _lines->size(); + return (**_syncedLines).size(); } private: - std::unique_ptr<std::vector<std::string>> _lines; - boost::shared_ptr<boost::log::sinks::synchronous_sink<LogCaptureBackend>> _sink; + synchronized_value<std::vector<std::string>> _syncedLines; + boost::shared_ptr<boost::log::sinks::unlocked_sink<LogCaptureBackend>> _sink; }; LogV2Test() { @@ -287,9 +301,9 @@ public: } template <typename Fmt> - LineCapture makeLineCapture(Fmt&& formatter, bool stripEol = true) { - LineCapture ret(stripEol); - auto& s = ret.sink(); + std::unique_ptr<LineCapture> makeLineCapture(Fmt&& formatter, bool stripEol = true) { + auto ret = std::make_unique<LineCapture>(stripEol); + auto& s = ret->sink(); applyDefaultFilterToSink(s); s->set_formatter(std::forward<Fmt>(formatter)); attachSink(s); @@ -307,60 +321,60 @@ TEST_F(LogV2Test, Basic) { fmt::memory_buffer buffer; LOGV2(20002, "test"); - ASSERT_EQUALS(lines.back(), "test"); + ASSERT_EQUALS(lines->back(), "test"); LOGV2_DEBUG(20063, -2, "test debug"); - ASSERT_EQUALS(lines.back(), "test debug"); + ASSERT_EQUALS(lines->back(), "test debug"); LOGV2(20003, "test {name}", "name"_attr = 1); - ASSERT_EQUALS(lines.back(), "test 1"); + ASSERT_EQUALS(lines->back(), "test 1"); LOGV2(20004, "test {name:d}", "name"_attr = 2); - ASSERT_EQUALS(lines.back(), "test 2"); + ASSERT_EQUALS(lines->back(), "test 2"); LOGV2(20005, "test {name}", "name"_attr = "char*"); - ASSERT_EQUALS(lines.back(), "test char*"); + ASSERT_EQUALS(lines->back(), "test char*"); LOGV2(20006, "test {name}", "name"_attr = std::string("std::string")); - ASSERT_EQUALS(lines.back(), "test std::string"); + ASSERT_EQUALS(lines->back(), "test std::string"); LOGV2(20007, "test {name}", "name"_attr = "StringData"_sd); - ASSERT_EQUALS(lines.back(), "test StringData"); + ASSERT_EQUALS(lines->back(), "test StringData"); LOGV2_OPTIONS(20064, {LogTag::kStartupWarnings}, "test"); - ASSERT_EQUALS(lines.back(), "test"); + ASSERT_EQUALS(lines->back(), "test"); TypeWithBSON t(1.0, 2.0); LOGV2(20008, "{name} custom formatting", "name"_attr = t); - ASSERT_EQUALS(lines.back(), t.toString() + " custom formatting"); + ASSERT_EQUALS(lines->back(), t.toString() + " custom formatting"); TypeWithoutBSON t2(1.0, 2.0); LOGV2(20009, "{name} custom formatting, no bson", "name"_attr = t2); - ASSERT_EQUALS(lines.back(), t.toString() + " custom formatting, no bson"); + ASSERT_EQUALS(lines->back(), t.toString() + " custom formatting, no bson"); TypeWithOnlyStringSerialize t3(1.0, 2.0); LOGV2(20010, "{name}", "name"_attr = t3); buffer.clear(); t3.serialize(buffer); - ASSERT_EQUALS(lines.back(), fmt::to_string(buffer)); + ASSERT_EQUALS(lines->back(), fmt::to_string(buffer)); // Serialize should be preferred when both are available TypeWithBothStringFormatters t4; LOGV2(20011, "{name}", "name"_attr = t4); buffer.clear(); t4.serialize(buffer); - ASSERT_EQUALS(lines.back(), fmt::to_string(buffer)); + ASSERT_EQUALS(lines->back(), fmt::to_string(buffer)); // Message string is selected when using API that also take a format string LOGV2(20084, "fmtstr {name}", "msgstr", "name"_attr = 1); - ASSERT_EQUALS(lines.back(), "msgstr"); + ASSERT_EQUALS(lines->back(), "msgstr"); // Test that logging exceptions does not propagate out to user code in release builds if (!kDebugBuild) { LOGV2(4638203, "mismatch {name}", "not_name"_attr = 1); - ASSERT(StringData(lines.back()).startsWith("Exception during log"_sd)); + ASSERT(StringData(lines->back()).startsWith("Exception during log"_sd)); } -} +} // namespace namespace bl_sinks = boost::log::sinks; // Sink backend which will grab a mutex, then immediately segfault. @@ -414,7 +428,7 @@ public: template <typename T> void validateJSON(T expected) { namespace pt = boost::property_tree; - std::istringstream json_stream(json.back()); + std::istringstream json_stream(json->back()); pt::ptree ptree; pt::json_parser::read_json(json_stream, ptree); ASSERT_EQUALS(ptree.get<std::string>(std::string(kTenantFieldName)), tenant.toString()); @@ -422,15 +436,20 @@ public: } auto lastBSONElement() { - ASSERT_EQUALS(BSONObj(bson.back().data()).getField(kTenantFieldName).str(), - tenant.toString()); - return BSONObj(bson.back().data()).getField(kAttributesFieldName).Obj().getField("name"_sd); + auto str = bson->back(); + buf.realloc(str.size()); + str.copy(buf.get(), str.size()); + BSONObj obj(buf); + + ASSERT_EQUALS(obj.getField(kTenantFieldName).str(), tenant.toString()); + return obj.getField(kAttributesFieldName).Obj().getField("name"_sd); } TenantId tenant = TenantId(OID::gen()); - LineCapture text = makeLineCapture(PlainFormatter()); - LineCapture json = makeLineCapture(JSONFormatter()); - LineCapture bson = makeLineCapture(BSONFormatter()); + std::unique_ptr<LineCapture> text = makeLineCapture(PlainFormatter()); + std::unique_ptr<LineCapture> json = makeLineCapture(JSONFormatter()); + std::unique_ptr<LineCapture> bson = makeLineCapture(BSONFormatter()); + SharedBuffer buf; }; TEST_F(LogV2TypesTest, Numeric) { @@ -438,9 +457,9 @@ TEST_F(LogV2TypesTest, Numeric) { using T = decltype(dummy); auto test = [&](auto value) { - text.clear(); + text->clear(); LOGV2(20012, "{name}", "name"_attr = value); - ASSERT_EQUALS(text.back(), fmt::format("{}", value)); + ASSERT_EQUALS(text->back(), fmt::format("{}", value)); validateJSON(value); // TODO: We should have been able to use std::make_signed here but it is broken on @@ -471,10 +490,10 @@ TEST_F(LogV2TypesTest, Numeric) { using T = decltype(dummy); auto test = [&](auto value) { - text.clear(); + text->clear(); LOGV2(20013, "{name}", "name"_attr = value); // Floats are formatted as double - ASSERT_EQUALS(text.back(), fmt::format("{}", static_cast<double>(value))); + ASSERT_EQUALS(text->back(), fmt::format("{}", static_cast<double>(value))); validateJSON(value); ASSERT_EQUALS(lastBSONElement().Number(), value); }; @@ -493,13 +512,13 @@ TEST_F(LogV2TypesTest, Numeric) { bool b = true; LOGV2(20014, "bool {name}", "name"_attr = b); - ASSERT_EQUALS(text.back(), "bool true"); + ASSERT_EQUALS(text->back(), "bool true"); validateJSON(b); ASSERT(lastBSONElement().Bool() == b); char c = 1; LOGV2(20015, "char {name}", "name"_attr = c); - ASSERT_EQUALS(text.back(), "char 1"); + ASSERT_EQUALS(text->back(), "char 1"); validateJSON(static_cast<uint8_t>(c)); // cast to prevent property_tree ASCII parse. ASSERT(lastBSONElement().Number() == c); @@ -526,19 +545,19 @@ TEST_F(LogV2TypesTest, Enums) { enum UnscopedEnum { UnscopedEntry }; LOGV2(20076, "{name}", "name"_attr = UnscopedEntry); auto expectedUnscoped = static_cast<std::underlying_type_t<UnscopedEnum>>(UnscopedEntry); - ASSERT_EQUALS(text.back(), std::to_string(expectedUnscoped)); + ASSERT_EQUALS(text->back(), std::to_string(expectedUnscoped)); validateJSON(expectedUnscoped); ASSERT_EQUALS(lastBSONElement().Number(), expectedUnscoped); enum class ScopedEnum { Entry = -1 }; LOGV2(20077, "{name}", "name"_attr = ScopedEnum::Entry); auto expectedScoped = static_cast<std::underlying_type_t<ScopedEnum>>(ScopedEnum::Entry); - ASSERT_EQUALS(text.back(), std::to_string(expectedScoped)); + ASSERT_EQUALS(text->back(), std::to_string(expectedScoped)); validateJSON(expectedScoped); ASSERT_EQUALS(lastBSONElement().Number(), expectedScoped); LOGV2(20078, "{name}", "name"_attr = UnscopedEntryWithToString); - ASSERT_EQUALS(text.back(), toString(UnscopedEntryWithToString)); + ASSERT_EQUALS(text->back(), toString(UnscopedEntryWithToString)); validateJSON(toString(UnscopedEntryWithToString)); ASSERT_EQUALS(lastBSONElement().String(), toString(UnscopedEntryWithToString)); } @@ -546,32 +565,32 @@ TEST_F(LogV2TypesTest, Enums) { TEST_F(LogV2TypesTest, Stringlike) { const char* c_str = "a c string"; LOGV2(20016, "c string {name}", "name"_attr = c_str); - ASSERT_EQUALS(text.back(), "c string a c string"); + ASSERT_EQUALS(text->back(), "c string a c string"); validateJSON(std::string(c_str)); ASSERT_EQUALS(lastBSONElement().String(), c_str); char* c_str2 = const_cast<char*>("non-const"); LOGV2(20017, "c string {name}", "name"_attr = c_str2); - ASSERT_EQUALS(text.back(), "c string non-const"); + ASSERT_EQUALS(text->back(), "c string non-const"); validateJSON(std::string(c_str2)); ASSERT_EQUALS(lastBSONElement().String(), c_str2); std::string str = "a std::string"; LOGV2(20018, "std::string {name}", "name"_attr = str); - ASSERT_EQUALS(text.back(), "std::string a std::string"); + ASSERT_EQUALS(text->back(), "std::string a std::string"); validateJSON(str); ASSERT_EQUALS(lastBSONElement().String(), str); StringData str_data = "a StringData"_sd; LOGV2(20019, "StringData {name}", "name"_attr = str_data); - ASSERT_EQUALS(text.back(), "StringData a StringData"); + ASSERT_EQUALS(text->back(), "StringData a StringData"); validateJSON(str_data.toString()); ASSERT_EQUALS(lastBSONElement().String(), str_data); { std::string_view s = "a std::string_view"; LOGV2(4329200, "std::string_view {name}", "name"_attr = s); - ASSERT_EQUALS(text.back(), "std::string_view a std::string_view"); + ASSERT_EQUALS(text->back(), "std::string_view a std::string_view"); validateJSON(std::string{s}); ASSERT_EQUALS(lastBSONElement().String(), s); } @@ -585,9 +604,9 @@ TEST_F(LogV2TypesTest, BSONObj) { .append("str"_sd, "a StringData"_sd) .obj(); LOGV2(20020, "bson {name}", "name"_attr = bsonObj); - ASSERT(text.back() == + ASSERT(text->back() == std::string("bson ") + bsonObj.jsonString(JsonStringFormat::ExtendedRelaxedV2_0_0)); - ASSERT(mongo::fromjson(json.back()) + ASSERT(mongo::fromjson(json->back()) .getField(kAttributesFieldName) .Obj() .getField("name") @@ -600,9 +619,9 @@ TEST_F(LogV2TypesTest, BSONArray) { BSONArray bsonArr = BSONArrayBuilder().append("first"_sd).append("second"_sd).append("third"_sd).arr(); LOGV2(20021, "{name}", "name"_attr = bsonArr); - ASSERT_EQUALS(text.back(), + ASSERT_EQUALS(text->back(), bsonArr.jsonString(JsonStringFormat::ExtendedRelaxedV2_0_0, 0, true)); - ASSERT(mongo::fromjson(json.back()) + ASSERT(mongo::fromjson(json->back()) .getField(kAttributesFieldName) .Obj() .getField("name") @@ -619,8 +638,8 @@ TEST_F(LogV2TypesTest, BSONElement) { .append("str"_sd, "a StringData"_sd) .obj(); LOGV2(20022, "bson element {name}", "name"_attr = bsonObj.getField("int32"_sd)); - ASSERT(text.back() == std::string("bson element ") + bsonObj.getField("int32"_sd).toString()); - ASSERT(mongo::fromjson(json.back()) + ASSERT(text->back() == std::string("bson element ") + bsonObj.getField("int32"_sd).toString()); + ASSERT(mongo::fromjson(json->back()) .getField(kAttributesFieldName) .Obj() .getField("name"_sd) @@ -637,8 +656,8 @@ TEST_F(LogV2TypesTest, DateT) { setDateFormatIsLocalTimezone(localTimezone); Date_t date = Date_t::now(); LOGV2(20023, "Date_t {name}", "name"_attr = date); - ASSERT_EQUALS(text.back(), std::string("Date_t ") + date.toString()); - ASSERT_EQUALS(mongo::fromjson(json.back()) + ASSERT_EQUALS(text->back(), std::string("Date_t ") + date.toString()); + ASSERT_EQUALS(mongo::fromjson(json->back()) .getField(kAttributesFieldName) .Obj() .getField("name") @@ -652,8 +671,8 @@ TEST_F(LogV2TypesTest, DateT) { TEST_F(LogV2TypesTest, Decimal128) { LOGV2(20024, "Decimal128 {name}", "name"_attr = Decimal128::kPi); - ASSERT_EQUALS(text.back(), std::string("Decimal128 ") + Decimal128::kPi.toString()); - ASSERT(mongo::fromjson(json.back()) + ASSERT_EQUALS(text->back(), std::string("Decimal128 ") + Decimal128::kPi.toString()); + ASSERT(mongo::fromjson(json->back()) .getField(kAttributesFieldName) .Obj() .getField("name") @@ -665,9 +684,9 @@ TEST_F(LogV2TypesTest, Decimal128) { TEST_F(LogV2TypesTest, OID) { OID oid = OID::gen(); LOGV2(20025, "OID {name}", "name"_attr = oid); - ASSERT_EQUALS(text.back(), std::string("OID ") + oid.toString()); + ASSERT_EQUALS(text->back(), std::string("OID ") + oid.toString()); ASSERT_EQUALS( - mongo::fromjson(json.back()).getField(kAttributesFieldName).Obj().getField("name").OID(), + mongo::fromjson(json->back()).getField(kAttributesFieldName).Obj().getField("name").OID(), oid); ASSERT_EQUALS(lastBSONElement().OID(), oid); } @@ -675,8 +694,8 @@ TEST_F(LogV2TypesTest, OID) { TEST_F(LogV2TypesTest, Timestamp) { Timestamp ts = Timestamp::max(); LOGV2(20026, "Timestamp {name}", "name"_attr = ts); - ASSERT_EQUALS(text.back(), std::string("Timestamp ") + ts.toString()); - ASSERT_EQUALS(mongo::fromjson(json.back()) + ASSERT_EQUALS(text->back(), std::string("Timestamp ") + ts.toString()); + ASSERT_EQUALS(mongo::fromjson(json->back()) .getField(kAttributesFieldName) .Obj() .getField("name") @@ -688,8 +707,8 @@ TEST_F(LogV2TypesTest, Timestamp) { TEST_F(LogV2TypesTest, UUID) { UUID uuid = UUID::gen(); LOGV2(20027, "UUID {name}", "name"_attr = uuid); - ASSERT_EQUALS(text.back(), std::string("UUID ") + uuid.toString()); - ASSERT_EQUALS(UUID::parse(mongo::fromjson(json.back()) + ASSERT_EQUALS(text->back(), std::string("UUID ") + uuid.toString()); + ASSERT_EQUALS(UUID::parse(mongo::fromjson(json->back()) .getField(kAttributesFieldName) .Obj() .getField("name") @@ -700,10 +719,10 @@ TEST_F(LogV2TypesTest, UUID) { TEST_F(LogV2TypesTest, BoostOptional) { LOGV2(20028, "boost::optional empty {name}", "name"_attr = boost::optional<bool>()); - ASSERT_EQUALS(text.back(), + ASSERT_EQUALS(text->back(), std::string("boost::optional empty ") + constants::kNullOptionalString.toString()); - ASSERT(mongo::fromjson(json.back()) + ASSERT(mongo::fromjson(json->back()) .getField(kAttributesFieldName) .Obj() .getField("name") @@ -711,18 +730,18 @@ TEST_F(LogV2TypesTest, BoostOptional) { ASSERT(lastBSONElement().isNull()); LOGV2(20029, "boost::optional<bool> {name}", "name"_attr = boost::optional<bool>(true)); - ASSERT_EQUALS(text.back(), std::string("boost::optional<bool> true")); + ASSERT_EQUALS(text->back(), std::string("boost::optional<bool> true")); ASSERT_EQUALS( - mongo::fromjson(json.back()).getField(kAttributesFieldName).Obj().getField("name").Bool(), + mongo::fromjson(json->back()).getField(kAttributesFieldName).Obj().getField("name").Bool(), true); ASSERT_EQUALS(lastBSONElement().Bool(), true); LOGV2(20030, "boost::optional<boost::optional<bool>> {name}", "name"_attr = boost::optional<boost::optional<bool>>(boost::optional<bool>(true))); - ASSERT_EQUALS(text.back(), std::string("boost::optional<boost::optional<bool>> true")); + ASSERT_EQUALS(text->back(), std::string("boost::optional<boost::optional<bool>> true")); ASSERT_EQUALS( - mongo::fromjson(json.back()).getField(kAttributesFieldName).Obj().getField("name").Bool(), + mongo::fromjson(json->back()).getField(kAttributesFieldName).Obj().getField("name").Bool(), true); ASSERT_EQUALS(lastBSONElement().Bool(), true); @@ -730,8 +749,9 @@ TEST_F(LogV2TypesTest, BoostOptional) { LOGV2(20031, "boost::optional<TypeWithBSON> {name}", "name"_attr = boost::optional<TypeWithBSON>(withBSON)); - ASSERT_EQUALS(text.back(), std::string("boost::optional<TypeWithBSON> ") + withBSON.toString()); - ASSERT(mongo::fromjson(json.back()) + ASSERT_EQUALS(text->back(), + std::string("boost::optional<TypeWithBSON> ") + withBSON.toString()); + ASSERT(mongo::fromjson(json->back()) .getField(kAttributesFieldName) .Obj() .getField("name") @@ -743,25 +763,28 @@ TEST_F(LogV2TypesTest, BoostOptional) { LOGV2(20032, "boost::optional<TypeWithBSON> {name}", "name"_attr = boost::optional<TypeWithoutBSON>(withoutBSON)); - ASSERT_EQUALS(text.back(), + ASSERT_EQUALS(text->back(), std::string("boost::optional<TypeWithBSON> ") + withoutBSON.toString()); - ASSERT_EQUALS( - mongo::fromjson(json.back()).getField(kAttributesFieldName).Obj().getField("name").String(), - withoutBSON.toString()); + ASSERT_EQUALS(mongo::fromjson(json->back()) + .getField(kAttributesFieldName) + .Obj() + .getField("name") + .String(), + withoutBSON.toString()); ASSERT_EQUALS(lastBSONElement().String(), withoutBSON.toString()); } TEST_F(LogV2TypesTest, Duration) { Milliseconds ms{12345}; LOGV2(20033, "Duration {name}", "name"_attr = ms); - ASSERT_EQUALS(text.back(), std::string("Duration ") + ms.toString()); - ASSERT_EQUALS(mongo::fromjson(json.back()) + ASSERT_EQUALS(text->back(), std::string("Duration ") + ms.toString()); + ASSERT_EQUALS(mongo::fromjson(json->back()) .getField(kAttributesFieldName) .Obj() .getField("name" + ms.mongoUnitSuffix()) .Int(), ms.count()); - ASSERT_EQUALS(BSONObj(bson.back().data()) + ASSERT_EQUALS(BSONObj(bson->back().data()) .getField(kAttributesFieldName) .Obj() .getField("name" + ms.mongoUnitSuffix()) @@ -773,31 +796,31 @@ TEST_F(LogV2Test, TextFormat) { auto lines = makeLineCapture(TextFormatter()); LOGV2_OPTIONS(20065, {LogTag::kNone}, "warning"); - ASSERT(lines.back().rfind("** WARNING: warning") == std::string::npos); + ASSERT(lines->back().rfind("** WARNING: warning") == std::string::npos); LOGV2_OPTIONS(20066, {LogTag::kStartupWarnings}, "warning"); - ASSERT(lines.back().rfind("** WARNING: warning") != std::string::npos); + ASSERT(lines->back().rfind("** WARNING: warning") != std::string::npos); LOGV2_OPTIONS(20067, {static_cast<LogTag::Value>(LogTag::kStartupWarnings | LogTag::kPlainShell)}, "warning"); - ASSERT(lines.back().rfind("** WARNING: warning") != std::string::npos); + ASSERT(lines->back().rfind("** WARNING: warning") != std::string::npos); TypeWithBSON t(1.0, 2.0); LOGV2(20034, "{name} custom formatting", "name"_attr = t); - ASSERT(lines.back().rfind(t.toString() + " custom formatting") != std::string::npos); + ASSERT(lines->back().rfind(t.toString() + " custom formatting") != std::string::npos); LOGV2(20035, "{name} bson", "name"_attr = t.toBSON()); - ASSERT(lines.back().rfind(t.toBSON().jsonString(JsonStringFormat::ExtendedRelaxedV2_0_0) + - " bson") != std::string::npos); + ASSERT(lines->back().rfind(t.toBSON().jsonString(JsonStringFormat::ExtendedRelaxedV2_0_0) + + " bson") != std::string::npos); TypeWithoutBSON t2(1.0, 2.0); LOGV2(20036, "{name} custom formatting, no bson", "name"_attr = t2); - ASSERT(lines.back().rfind(t.toString() + " custom formatting, no bson") != std::string::npos); + ASSERT(lines->back().rfind(t.toString() + " custom formatting, no bson") != std::string::npos); TypeWithNonMemberFormatting t3; LOGV2(20079, "{name}", "name"_attr = t3); - ASSERT(lines.back().rfind(toString(t3)) != std::string::npos); + ASSERT(lines->back().rfind(toString(t3)) != std::string::npos); } std::string hello() { @@ -812,12 +835,12 @@ public: template <typename F> void validate(F validator) { - validator(mongo::fromjson(lines.back())); - validator(BSONObj(linesBson.back().data())); + validator(mongo::fromjson(lines->back())); + validator(BSONObj(linesBson->back().data())); } - LineCapture lines = makeLineCapture(JSONFormatter()); - LineCapture linesBson = makeLineCapture(BSONFormatter()); + std::unique_ptr<LineCapture> lines = makeLineCapture(JSONFormatter()); + std::unique_ptr<LineCapture> linesBson = makeLineCapture(BSONFormatter()); }; TEST_F(LogV2JsonBsonTest, Root) { @@ -1162,8 +1185,8 @@ public: /** Ensure json and bson modes both pass. */ template <typename F> void validate(F validator) { - validator(mongo::fromjson(json.back())); - validator(BSONObj(bson.back().data())); + validator(mongo::fromjson(json->back())); + validator(BSONObj(bson->back().data())); } }; @@ -1171,7 +1194,7 @@ public: TEST_F(LogV2ContainerTest, StandardSequential) { std::vector<std::string> vectorStrings = {"str1", "str2", "str3"}; LOGV2(20047, "{name}", "name"_attr = vectorStrings); - ASSERT_EQUALS(text.back(), textJoin(vectorStrings, [](auto&& s) { return s; })); + ASSERT_EQUALS(text->back(), textJoin(vectorStrings, [](auto&& s) { return s; })); validate([&vectorStrings](const BSONObj& obj) { std::vector<BSONElement> jsonVector = obj.getField(kAttributesFieldName).Obj().getField("name").Array(); @@ -1207,7 +1230,7 @@ TEST_F(LogV2ContainerTest, CustomFormatting) { std::list<TypeWithBSON> listCustom = { TypeWithBSON(0.0, 1.0), TypeWithBSON(2.0, 3.0), TypeWithBSON(4.0, 5.0)}; LOGV2(20048, "{name}", "name"_attr = listCustom); - ASSERT_EQUALS(text.back(), textJoin(listCustom, [](auto&& x) { return x.toString(); })); + ASSERT_EQUALS(text->back(), textJoin(listCustom, [](auto&& x) { return x.toString(); })); validate([&listCustom](const BSONObj& obj) { std::vector<BSONElement> jsonVector = obj.getField(kAttributesFieldName).Obj().getField("name").Array(); @@ -1223,7 +1246,7 @@ TEST_F(LogV2ContainerTest, CustomFormatting) { TEST_F(LogV2ContainerTest, OptionalsAsElements) { std::forward_list<boost::optional<bool>> listOptionalBool = {true, boost::none, false}; LOGV2(20049, "{name}", "name"_attr = listOptionalBool); - ASSERT_EQUALS(text.back(), textJoin(listOptionalBool, [](const auto& item) -> std::string { + ASSERT_EQUALS(text->back(), textJoin(listOptionalBool, [](const auto& item) -> std::string { if (!item) return constants::kNullOptionalString.toString(); if (*item) @@ -1250,7 +1273,7 @@ TEST_F(LogV2ContainerTest, OptionalsAsElements) { TEST_F(LogV2ContainerTest, Nested) { std::array<std::deque<int>, 4> arrayOfDeques = {{{0, 1}, {2, 3}, {4, 5}, {6, 7}}}; LOGV2(20050, "{name}", "name"_attr = arrayOfDeques); - ASSERT_EQUALS(text.back(), textJoin(arrayOfDeques, [](auto&& outer) { + ASSERT_EQUALS(text->back(), textJoin(arrayOfDeques, [](auto&& outer) { return textJoin(outer, [](auto&& v) { return fmt::format("{}", v); }); })); validate([&arrayOfDeques](const BSONObj& obj) { @@ -1276,7 +1299,7 @@ TEST_F(LogV2ContainerTest, Associative) { // Associative containers are also supported std::map<std::string, std::string> mapStrStr = {{"key1", "val1"}, {"key2", "val2"}}; LOGV2(20051, "{name}", "name"_attr = mapStrStr); - ASSERT_EQUALS(text.back(), textJoin(mapStrStr, [](const auto& item) { + ASSERT_EQUALS(text->back(), textJoin(mapStrStr, [](const auto& item) { return fmt::format("{}: {}", item.first, item.second); })); validate([&mapStrStr](const BSONObj& obj) { @@ -1295,7 +1318,7 @@ TEST_F(LogV2ContainerTest, AssociativeWithOptionalSequential) { {"key2", boost::optional<std::vector<int>>{boost::none}}}; LOGV2(20052, "{name}", "name"_attr = mapOptionalVector); - ASSERT_EQUALS(text.back(), textJoin(mapOptionalVector, [](auto&& item) { + ASSERT_EQUALS(text->back(), textJoin(mapOptionalVector, [](auto&& item) { std::string r = item.first + ": "; if (item.second) { r += textJoin(*item.second, [](int v) { return fmt::format("{}", v); }); @@ -1416,7 +1439,7 @@ TEST_F(LogV2Test, Unicode) { }; auto getLastMongo = [&]() { - return mongo::fromjson(lines.back()) + return mongo::fromjson(lines->back()) .getField(constants::kAttributesFieldName) .Obj() .getField("name") @@ -1426,7 +1449,7 @@ TEST_F(LogV2Test, Unicode) { auto getLastPtree = [&]() { namespace pt = boost::property_tree; - std::istringstream json_stream(lines.back()); + std::istringstream json_stream(lines->back()); pt::ptree ptree; pt::json_parser::read_json(json_stream, ptree); return ptree.get<std::string>(std::string(constants::kAttributesFieldName) + ".name"); @@ -1482,7 +1505,7 @@ TEST_F(LogV2Test, JsonTruncation) { // Attributes coming after the truncated one should be written ASSERT(obj.getField(constants::kAttributesFieldName).Obj().getField("attr2").Bool()); }; - validateTruncation(mongo::fromjson(lines.back())); + validateTruncation(mongo::fromjson(lines->back())); LOGV2_OPTIONS(20086, {LogTruncation::Disabled}, "{name}", "name"_attr = builder.done()); auto validateTruncationDisabled = [&](const BSONObj& obj) { @@ -1501,7 +1524,7 @@ TEST_F(LogV2Test, JsonTruncation) { ASSERT(!obj.hasField(constants::kTruncatedFieldName)); ASSERT(!obj.hasField(constants::kTruncatedSizeFieldName)); }; - validateTruncationDisabled(mongo::fromjson(lines.back())); + validateTruncationDisabled(mongo::fromjson(lines->back())); BSONArrayBuilder arrBuilder; // Fields will use more than one byte each so this will truncate at some point @@ -1526,7 +1549,7 @@ TEST_F(LogV2Test, JsonTruncation) { obj.getField(constants::kTruncatedSizeFieldName).Obj().getField("name"_sd).Int(), arrToLog.objsize()); }; - validateArrayTruncation(mongo::fromjson(lines.back())); + validateArrayTruncation(mongo::fromjson(lines->back())); } TEST_F(LogV2Test, StringTruncation) { @@ -1562,7 +1585,7 @@ TEST_F(LogV2Test, StringTruncation) { for (const auto& [input, suffix, note] : tests) { LOGV2(6694001, "name", "name"_attr = input); - BSONObj obj = fromjson(lines.back()); + BSONObj obj = fromjson(lines->back()); auto str = obj[constants::kAttributesFieldName]["name"].checkAndGetStringData(); std::string context = "Failed test: " + note; @@ -1609,9 +1632,9 @@ TEST_F(LogV2Test, Threads) { thread.join(); } - ASSERT(linesPlain.size() == threads.size() * kNumPerThread); - ASSERT(linesText.size() == threads.size() * kNumPerThread); - ASSERT(linesJson.size() == threads.size() * kNumPerThread); + ASSERT(linesPlain->size() == threads.size() * kNumPerThread); + ASSERT(linesText->size() == threads.size() * kNumPerThread); + ASSERT(linesJson->size() == threads.size() * kNumPerThread); } TEST_F(LogV2Test, Ramlog) { @@ -1625,7 +1648,7 @@ TEST_F(LogV2Test, Ramlog) { auto verifyRamLog = [&] { RamLog::LineIterator iter(ramlog); - for (const auto& s : lines.lines()) { + for (const auto& s : lines->lines()) { const auto next = iter.next(); if (s != next) { std::cout << "\n\n\n********************** s='" << s << "', next='" << next @@ -1748,8 +1771,8 @@ TEST_F(LogV2Test, MultipleDomains) { } }; LogDomain other_domain(std::make_unique<OtherDomain>()); - std::vector<std::string> other_lines; - auto other_sink = LogCaptureBackend::create(other_lines, true); + synchronized_value<std::vector<std::string>> other_lines; + auto other_sink = LogCaptureBackend::create(std::make_unique<Listener>(&other_lines), true); other_sink->set_filter(ComponentSettingsFilter(other_domain, mgr().getGlobalSettings())); other_sink->set_formatter(PlainFormatter()); attachSink(other_sink); @@ -1757,12 +1780,13 @@ TEST_F(LogV2Test, MultipleDomains) { auto global_lines = makeLineCapture(PlainFormatter()); LOGV2_OPTIONS(20070, {&other_domain}, "test"); - ASSERT(global_lines.lines().empty()); - ASSERT(other_lines.back() == "test"); + auto logLinesLockGuard = *other_lines; + ASSERT(global_lines->lines().empty()); + ASSERT(logLinesLockGuard->back() == "test"); LOGV2(20060, "global domain log"); - ASSERT(global_lines.back() == "global domain log"); - ASSERT(other_lines.back() == "test"); + ASSERT(global_lines->back() == "global domain log"); + ASSERT(logLinesLockGuard->back() == "test"); } TEST_F(LogV2Test, FileLogging) { @@ -1814,9 +1838,10 @@ TEST_F(LogV2Test, FileLogging) { } TEST_F(LogV2Test, UserAssert) { - std::vector<std::string> lines; + synchronized_value<std::vector<std::string>> syncedLines; auto sink = wrapInSynchronousSink(wrapInCompositeBackend( - boost::make_shared<LogCaptureBackend>(lines, true), boost::make_shared<UserAssertSink>())); + boost::make_shared<LogCaptureBackend>(std::make_unique<Listener>(&syncedLines), true), + boost::make_shared<UserAssertSink>())); applyDefaultFilterToSink(sink); sink->set_formatter(PlainFormatter()); attachSink(sink); @@ -1826,31 +1851,31 @@ TEST_F(LogV2Test, UserAssert) { ASSERT_THROWS_WITH_CHECK( LOGV2_OPTIONS(4652000, {UserAssertAfterLog(ErrorCodes::BadValue)}, "uasserting log"), DBException, - [&lines](const DBException& ex) { + [&syncedLines](const DBException& ex) { ASSERT_EQUALS(ex.code(), ErrorCodes::BadValue); ASSERT_EQUALS(ex.reason(), "uasserting log"); - ASSERT_EQUALS(lines.front(), ex.reason()); + ASSERT_EQUALS((**syncedLines).front(), ex.reason()); }); - lines.clear(); + (**syncedLines).clear(); ASSERT_THROWS_WITH_CHECK(LOGV2_OPTIONS(4652001, {UserAssertAfterLog(ErrorCodes::BadValue)}, "uasserting log {name}", "name"_attr = 1), DBException, - [&lines](const DBException& ex) { + [&syncedLines](const DBException& ex) { ASSERT_EQUALS(ex.code(), ErrorCodes::BadValue); ASSERT_EQUALS(ex.reason(), "uasserting log 1"); - ASSERT_EQUALS(lines.front(), ex.reason()); + ASSERT_EQUALS((**syncedLines).front(), ex.reason()); }); - lines.clear(); + (**syncedLines).clear(); ASSERT_THROWS_WITH_CHECK(LOGV2_OPTIONS(4716000, {UserAssertAfterLog()}, "uasserting log"), DBException, - [&lines](const DBException& ex) { + [&syncedLines](const DBException& ex) { ASSERT_EQUALS(ex.code(), 4716000); ASSERT_EQUALS(ex.reason(), "uasserting log"); - ASSERT_EQUALS(lines.front(), ex.reason()); + ASSERT_EQUALS((**syncedLines).front(), ex.reason()); }); } diff --git a/src/mongo/logv2/redaction.cpp b/src/mongo/logv2/redaction.cpp index 0b143ba39ae..29536660722 100644 --- a/src/mongo/logv2/redaction.cpp +++ b/src/mongo/logv2/redaction.cpp @@ -50,12 +50,12 @@ constexpr auto kRedactionDefaultMask = "###"_sd; BSONObj redact(const BSONObj& objectToRedact) { if (!logv2::shouldRedactLogs()) { if (!logv2::shouldRedactBinDataEncrypt()) { - return objectToRedact; + return objectToRedact.redact(BSONObj::RedactLevel::sensitiveOnly); } - return objectToRedact.redact(true /* onlyEncryptedFields */); + return objectToRedact.redact(BSONObj::RedactLevel::encryptedAndSensitive); } - return objectToRedact.redact(false /* onlyEncryptedFields */); + return objectToRedact.redact(BSONObj::RedactLevel::all); } StringData redact(StringData stringToRedact) { diff --git a/src/mongo/logv2/redaction_test.cpp b/src/mongo/logv2/redaction_test.cpp index dda840a4681..ca61f7ec295 100644 --- a/src/mongo/logv2/redaction_test.cpp +++ b/src/mongo/logv2/redaction_test.cpp @@ -34,6 +34,7 @@ #include "mongo/base/error_extra_info.h" #include "mongo/bson/bsonobjbuilder.h" #include "mongo/bson/bsontypes.h" +#include "mongo/bson/json.h" #include "mongo/db/jsobj.h" #include "mongo/logv2/log_util.h" #include "mongo/unittest/unittest.h" @@ -140,8 +141,6 @@ TEST(RedactEncryptedStringTest, BasicStrings) { } BSONObj obj = builder.done(); - std::cout << "This is obj: " << obj.toString() << std::endl; - auto redactedStr = R"({ type6: "###", string: "string", nestedobj: { subobj: "###" } })"; ASSERT_EQ(redact(obj).toString(), redactedStr); @@ -149,6 +148,98 @@ TEST(RedactEncryptedStringTest, BasicStrings) { ASSERT_EQ(redact(obj).toString(), obj.toString()); } +TEST(RedactSensitiveStringTest, BasicStrings) { + BSONObjBuilder builder{}; + builder.appendBinData("type8", sizeof(zero), BinDataType::Sensitive, zero); + builder.append("string", "string"); + { + BSONObjBuilder sub(builder.subobjStart("nestedobj")); + sub.appendBinData("subobj", sizeof(zero), BinDataType::Sensitive, zero); + } + const BSONObj obj = builder.done(); + + { + logv2::setShouldRedactBinDataEncrypt(true); + logv2::setShouldRedactLogs(true); + + // Fully-redacted logs should just redact everything + const auto redactedStr = R"({ type8: "###", string: "###", nestedobj: { subobj: "###" } })"; + ASSERT_EQ(redact(obj).toString(), redactedStr); + } + + { + const auto redactedStr = + R"({ type8: "###", string: "string", nestedobj: { subobj: "###" } })"; + // The setting for redacting logs shouldn't affect sensitive BinData. + logv2::setShouldRedactLogs(false); + ASSERT_EQ(redact(obj).toString(), redactedStr); + + // The setting for redacting encrypted BinData shouldn't affect sensitive BinData, either. + logv2::setShouldRedactBinDataEncrypt(false); + ASSERT_EQ(redact(obj).toString(), redactedStr); + } +} + +TEST(RedactSensitiveStringTest, NestedStrings) { + // The setting for redacting logs shouldn't affect sensitive BinData. + logv2::setShouldRedactBinDataEncrypt(false); + // The setting for redacting encrypted BinData shouldn't affect sensitive BinData, either. + logv2::setShouldRedactLogs(false); + + BSONObjBuilder builder{}; + + // Test for [ "###", { ...: "###" }, ... ] shape cases. + { + auto subarray = BSONObjBuilder(builder.subarrayStart("subarray")); + subarray.appendBinData("0", sizeof(zero), BinDataType::Sensitive, zero); + + for (auto nSubobjs = 0; nSubobjs < 3; ++nSubobjs) { + BSONObjBuilder(subarray.subobjStart("subobj")) + .appendBinData("type8", sizeof(zero), BinDataType::Sensitive, zero); + } + } + + // Test for { ...: "###", ...: [ "###", ... ] } shape cases. + { + auto subobj = BSONObjBuilder(builder.subobjStart("subobj")); + subobj.appendBinData("type8", sizeof(zero), BinDataType::Sensitive, zero); + + auto subarray = BSONObjBuilder(subobj.subarrayStart("subarray")); + for (auto nSubobjs = 0; nSubobjs < 3; ++nSubobjs) { + subarray.appendBinData("0", sizeof(zero), BinDataType::Sensitive, zero); + } + } + + // Test for [ [ [ "###", ... ] ] ] shape cases. + { + auto subarray1 = BSONObjBuilder(builder.subarrayStart("subarrays")); + auto subarray2 = BSONObjBuilder(subarray1.subarrayStart("subarray")); + auto subarray3 = BSONObjBuilder(subarray2.subarrayStart("subarray")); + for (auto nSubobjs = 0; nSubobjs < 3; ++nSubobjs) { + subarray3.appendBinData("0", sizeof(zero), BinDataType::Sensitive, zero); + } + } + + // Test for { ...: { ...: { ...: "###" } } } shape cases. + { + auto subobj1 = BSONObjBuilder(builder.subobjStart("subobjs")); + auto subobj2 = BSONObjBuilder(subobj1.subobjStart("subobj")); + auto subobj3 = BSONObjBuilder(subobj2.subobjStart("subobj")); + subobj3.appendBinData("type8", sizeof(zero), BinDataType::Sensitive, zero); + } + + const BSONObj obj = builder.done(); + + // Type 8 values should all be redacted. + const BSONObj expected = fromjson(R"({ + subarray: [ "###", { type8: "###" }, { type8: "###" }, { type8: "###" } ], + subobj: { type8: "###", subarray: [ "###", "###", "###" ] }, + subarrays: [ [ [ "###", "###", "###" ] ] ], + subobjs: { subobj: { subobj: { type8: "###" } } } + })"); + ASSERT_EQ(redact(obj).toString(), expected.toString()); +} + void testBSONCases(std::vector<BSONStringPair>& testCases) { for (auto m : testCases) { ASSERT_EQ(redact(m.first).toString(), m.second); |
