diff options
author | Henrik Edin <henrik.edin@mongodb.com> | 2020-03-02 14:52:46 -0500 |
---|---|---|
committer | Evergreen Agent <no-reply@evergreen.mongodb.com> | 2020-03-03 18:14:05 +0000 |
commit | 2803adc3ba76f87101d493cb940df4e0f53c7879 (patch) | |
tree | 73d5e0dbcf26bcff51fecc469b5e31d01c918585 /src/mongo/logv2 | |
parent | a68774045ce42d55e82236408bd9cf004c54d12a (diff) | |
download | mongo-2803adc3ba76f87101d493cb940df4e0f53c7879.tar.gz |
SERVER-46520 Add mechanism to emit uassert as part of a logv2 log statement
Diffstat (limited to 'src/mongo/logv2')
-rw-r--r-- | src/mongo/logv2/README.md | 15 | ||||
-rw-r--r-- | src/mongo/logv2/attributes.cpp | 5 | ||||
-rw-r--r-- | src/mongo/logv2/attributes.h | 1 | ||||
-rw-r--r-- | src/mongo/logv2/bson_formatter.cpp | 17 | ||||
-rw-r--r-- | src/mongo/logv2/bson_formatter.h | 3 | ||||
-rw-r--r-- | src/mongo/logv2/log_detail.cpp | 8 | ||||
-rw-r--r-- | src/mongo/logv2/log_domain_global.cpp | 23 | ||||
-rw-r--r-- | src/mongo/logv2/log_manager.cpp | 5 | ||||
-rw-r--r-- | src/mongo/logv2/log_options.h | 15 | ||||
-rw-r--r-- | src/mongo/logv2/log_source.h | 8 | ||||
-rw-r--r-- | src/mongo/logv2/log_test_v2.cpp | 43 | ||||
-rw-r--r-- | src/mongo/logv2/plain_formatter.cpp | 19 | ||||
-rw-r--r-- | src/mongo/logv2/plain_formatter.h | 1 | ||||
-rw-r--r-- | src/mongo/logv2/uassert_sink.h | 55 |
14 files changed, 199 insertions, 19 deletions
diff --git a/src/mongo/logv2/README.md b/src/mongo/logv2/README.md index 4f695d49742..a5578c83b0a 100644 --- a/src/mongo/logv2/README.md +++ b/src/mongo/logv2/README.md @@ -277,6 +277,21 @@ Text | JSON/BSON ---- | --------- `(200 ns, 400 ns)` | `"samples": [{"durationNanos": 200}, {"durationNanos": 400}]` +# Additional features + +## Combining uassert with log statement + +Code that emits a high severity log statement may also need to emit a `uassert` after the log. There is the `UserAssertAfterLog` helper that allows you to re-use the log statement to do the formatting required for the `uassert`. The reason string will be a plain text formatted log (replacement fields filled in format-string). + +##### Examples +``` +LOGV2_ERROR_OPTIONS(1050, {UserAssertAfterLog(ErrorCodes::DataCorruptionDetected)}, "Data corruption detected for {recordId}, "recordId"_attr=RecordId(123456)); +``` +Would emit an `uassert` after performing the log that is equivalent to: +``` +uasserted(ErrorCodes::DataCorruptionDetected, "Data corruption detected for RecordId(123456)"); +``` + # Output formats Desired log output format is set to mongod, mongos and the mongo shell using the `-logFormat` option. Available values are `text` and `json`. Currently text formatting is default. diff --git a/src/mongo/logv2/attributes.cpp b/src/mongo/logv2/attributes.cpp index f767f3ae94c..c53c030a988 100644 --- a/src/mongo/logv2/attributes.cpp +++ b/src/mongo/logv2/attributes.cpp @@ -83,6 +83,11 @@ const boost::log::attribute_name& truncation() { return attr; } +const boost::log::attribute_name& userassert() { + static const boost::log::attribute_name attr("userassert"); + return attr; +} + } // namespace attributes } // namespace logv2 } // namespace mongo diff --git a/src/mongo/logv2/attributes.h b/src/mongo/logv2/attributes.h index f39f24a95cd..8118faaaf0f 100644 --- a/src/mongo/logv2/attributes.h +++ b/src/mongo/logv2/attributes.h @@ -46,6 +46,7 @@ const boost::log::attribute_name& id(); const boost::log::attribute_name& message(); const boost::log::attribute_name& attributes(); const boost::log::attribute_name& truncation(); +const boost::log::attribute_name& userassert(); } // namespace attributes } // namespace logv2 diff --git a/src/mongo/logv2/bson_formatter.cpp b/src/mongo/logv2/bson_formatter.cpp index 88222e6a9d6..116f537273a 100644 --- a/src/mongo/logv2/bson_formatter.cpp +++ b/src/mongo/logv2/bson_formatter.cpp @@ -112,14 +112,12 @@ private: }; } // namespace -void BSONFormatter::operator()(boost::log::record_view const& rec, - boost::log::formatting_ostream& strm) const { +void BSONFormatter::operator()(boost::log::record_view const& rec, BSONObjBuilder& builder) const { using boost::log::extract; // Build a JSON object for the user attributes. const auto& attrs = extract<TypeErasedAttributeStorage>(attributes::attributes(), rec).get(); - BSONObjBuilder builder; builder.append(constants::kTimestampFieldName, extract<Date_t>(attributes::timeStamp(), rec).get()); builder.append(constants::kSeverityFieldName, @@ -140,10 +138,21 @@ void BSONFormatter::operator()(boost::log::record_view const& rec, if (tags != LogTag::kNone) { builder.append(constants::kTagsFieldName, tags.toBSONArray()); } +} - BSONObj obj = builder.obj(); +void BSONFormatter::operator()(boost::log::record_view const& rec, + boost::log::formatting_ostream& strm) const { + BSONObjBuilder builder; + operator()(rec, builder); + BSONObj obj = builder.done(); strm.write(obj.objdata(), obj.objsize()); } +BSONObj BSONFormatter::operator()(boost::log::record_view const& rec) const { + BSONObjBuilder builder; + operator()(rec, builder); + return builder.obj(); +} + } // namespace logv2 } // namespace mongo diff --git a/src/mongo/logv2/bson_formatter.h b/src/mongo/logv2/bson_formatter.h index 0e9479d65b8..61053b1f15f 100644 --- a/src/mongo/logv2/bson_formatter.h +++ b/src/mongo/logv2/bson_formatter.h @@ -32,6 +32,7 @@ #include <boost/log/core/record_view.hpp> #include <boost/log/utility/formatting_ostream_fwd.hpp> +#include "mongo/bson/bsonobjbuilder.h" #include "mongo/logv2/constants.h" namespace mongo { @@ -41,7 +42,9 @@ class BSONFormatter { public: BSONFormatter(const AtomicWord<int32_t>* maxAttributeSizeKB = nullptr) {} + void operator()(boost::log::record_view const& rec, BSONObjBuilder& builder) const; void operator()(boost::log::record_view const& rec, boost::log::formatting_ostream& strm) const; + BSONObj operator()(boost::log::record_view const& rec) const; }; } // namespace logv2 diff --git a/src/mongo/logv2/log_detail.cpp b/src/mongo/logv2/log_detail.cpp index 4668ff2339f..71bc1fb9b5d 100644 --- a/src/mongo/logv2/log_detail.cpp +++ b/src/mongo/logv2/log_detail.cpp @@ -49,8 +49,12 @@ void doLogImpl(int32_t id, TypeErasedAttributeStorage const& attrs) { dassert(options.component() != LogComponent::kNumLogComponents); auto& source = options.domain().internal().source(); - auto record = - source.open_record(id, severity, options.component(), options.tags(), options.truncation()); + auto record = source.open_record(id, + severity, + options.component(), + options.tags(), + options.truncation(), + options.uassertErrorCode()); if (record) { record.attribute_values().insert( attributes::message(), diff --git a/src/mongo/logv2/log_domain_global.cpp b/src/mongo/logv2/log_domain_global.cpp index 327c046da42..236f389f5ee 100644 --- a/src/mongo/logv2/log_domain_global.cpp +++ b/src/mongo/logv2/log_domain_global.cpp @@ -40,6 +40,7 @@ #include "mongo/logv2/shared_access_fstream.h" #include "mongo/logv2/tagged_severity_filter.h" #include "mongo/logv2/text_formatter.h" +#include "mongo/logv2/uassert_sink.h" #include <boost/core/null_deleter.hpp> #include <boost/filesystem/operations.hpp> @@ -54,13 +55,20 @@ void LogDomainGlobal::ConfigurationOptions::makeDisabled() { } struct LogDomainGlobal::Impl { - typedef CompositeBackend<boost::log::sinks::text_ostream_backend, RamLogSink, RamLogSink> + typedef CompositeBackend<boost::log::sinks::text_ostream_backend, + RamLogSink, + RamLogSink, + UserAssertSink> ConsoleBackend; #ifndef _WIN32 - typedef CompositeBackend<boost::log::sinks::syslog_backend, RamLogSink, RamLogSink> + typedef CompositeBackend<boost::log::sinks::syslog_backend, + RamLogSink, + RamLogSink, + UserAssertSink> SyslogBackend; #endif - typedef CompositeBackend<FileRotateSink, RamLogSink, RamLogSink> RotatableFileBackend; + typedef CompositeBackend<FileRotateSink, RamLogSink, RamLogSink, UserAssertSink> + RotatableFileBackend; Impl(LogDomainGlobal& parent); Status configure(LogDomainGlobal::ConfigurationOptions const& options); @@ -87,7 +95,8 @@ LogDomainGlobal::Impl::Impl(LogDomainGlobal& parent) : _parent(parent) { auto console = boost::make_shared<ConsoleBackend>( boost::make_shared<boost::log::sinks::text_ostream_backend>(), boost::make_shared<RamLogSink>(RamLog::get("global")), - boost::make_shared<RamLogSink>(RamLog::get("startupWarnings"))); + boost::make_shared<RamLogSink>(RamLog::get("startupWarnings")), + boost::make_shared<UserAssertSink>()); console->lockedBackend<0>()->add_stream( boost::shared_ptr<std::ostream>(&Console::out(), boost::null_deleter())); @@ -117,7 +126,8 @@ Status LogDomainGlobal::Impl::configure(LogDomainGlobal::ConfigurationOptions co boost::log::sinks::syslog::make_facility(options.syslogFacility), boost::log::keywords::use_impl = boost::log::sinks::syslog::native), boost::make_shared<RamLogSink>(RamLog::get("global")), - boost::make_shared<RamLogSink>(RamLog::get("startupWarnings"))); + boost::make_shared<RamLogSink>(RamLog::get("startupWarnings")), + boost::make_shared<UserAssertSink>()); boost::log::sinks::syslog::custom_severity_mapping<LogSeverity> mapping( attributes::severity()); @@ -158,7 +168,8 @@ Status LogDomainGlobal::Impl::configure(LogDomainGlobal::ConfigurationOptions co auto backend = boost::make_shared<RotatableFileBackend>( boost::make_shared<FileRotateSink>(), boost::make_shared<RamLogSink>(RamLog::get("global")), - boost::make_shared<RamLogSink>(RamLog::get("startupWarnings"))); + boost::make_shared<RamLogSink>(RamLog::get("startupWarnings")), + boost::make_shared<UserAssertSink>()); Status ret = backend->lockedBackend<0>()->addFile( options.filePath, options.fileOpenMode == ConfigurationOptions::OpenMode::kAppend ? true : false); diff --git a/src/mongo/logv2/log_manager.cpp b/src/mongo/logv2/log_manager.cpp index b5fc193ace3..d4710dc4977 100644 --- a/src/mongo/logv2/log_manager.cpp +++ b/src/mongo/logv2/log_manager.cpp @@ -58,13 +58,18 @@ LogManager::LogManager() { ++depth; // Try and log that we failed to log if (depth == 1) { + std::exception_ptr ex = nullptr; try { throw; + } catch (const DBException&) { + ex = std::current_exception(); } catch (...) { LOGV2(4638200, "Exception during log, message not written to stream", "exception"_attr = exceptionToStatus()); } + if (ex) + std::rethrow_exception(ex); } // Logging exceptions are fatal in debug builds. Guard ourselves from additional logging diff --git a/src/mongo/logv2/log_options.h b/src/mongo/logv2/log_options.h index fdd41307b43..d03a7bf274b 100644 --- a/src/mongo/logv2/log_options.h +++ b/src/mongo/logv2/log_options.h @@ -37,6 +37,13 @@ namespace mongo { namespace logv2 { +class UserAssertAfterLog { +public: + explicit UserAssertAfterLog(ErrorCodes::Error code) : errorCode(code) {} + + ErrorCodes::Error errorCode; +}; + class LogOptions { public: static LogOptions ensureValidComponent(LogOptions options, LogComponent component) { @@ -54,6 +61,9 @@ public: LogOptions(LogTruncation truncation) : _truncation(truncation) {} + LogOptions(UserAssertAfterLog uassertAfterLog) + : _userAssertErrorCode(uassertAfterLog.errorCode) {} + LogOptions(LogTag tags, LogTruncation truncation) : _tags(tags), _truncation(truncation) {} LogOptions(LogComponent component, LogDomain* domain, LogTag tags) @@ -78,11 +88,16 @@ public: return _truncation; } + ErrorCodes::Error uassertErrorCode() const { + return _userAssertErrorCode; + } + private: LogDomain* _domain = &LogManager::global().getGlobalDomain(); LogTag _tags; LogComponent _component = LogComponent::kAutomaticDetermination; LogTruncation _truncation = constants::kDefaultTruncation; + ErrorCodes::Error _userAssertErrorCode = ErrorCodes::OK; }; } // namespace logv2 diff --git a/src/mongo/logv2/log_source.h b/src/mongo/logv2/log_source.h index 99269bcdba2..7e389bd4548 100644 --- a/src/mongo/logv2/log_source.h +++ b/src/mongo/logv2/log_source.h @@ -63,12 +63,14 @@ public: _component(LogComponent::kDefault), _tags(LogTag::kNone), _truncation(constants::kDefaultTruncation), + _uassertErrorCode(ErrorCodes::OK), _id(-1) { add_attribute_unlocked(attributes::domain(), _domain); add_attribute_unlocked(attributes::severity(), _severity); add_attribute_unlocked(attributes::component(), _component); add_attribute_unlocked(attributes::tags(), _tags); add_attribute_unlocked(attributes::truncation(), _truncation); + add_attribute_unlocked(attributes::userassert(), _uassertErrorCode); add_attribute_unlocked(attributes::id(), _id); add_attribute_unlocked(attributes::timeStamp(), boost::log::attributes::make_function([]() { return Date_t::now(); @@ -85,13 +87,15 @@ public: LogSeverity severity, LogComponent component, LogTag tags, - LogTruncation truncation) { + LogTruncation truncation, + ErrorCodes::Error userassertErrorCode) { // Perform a quick check first if (this->core()->get_logging_enabled()) { _severity.set(severity); _component.set(component); _tags.set(tags); _truncation.set(truncation); + _uassertErrorCode.set(userassertErrorCode); _id.set(id); return Base::open_record_unlocked(); } else @@ -104,6 +108,7 @@ public: _component.set(LogComponent::kDefault); _tags.set(LogTag::kNone); _truncation.set(constants::kDefaultTruncation); + _uassertErrorCode.set(ErrorCodes::OK); _id.set(-1); } @@ -113,6 +118,7 @@ private: boost::log::attributes::mutable_constant<LogComponent> _component; boost::log::attributes::mutable_constant<LogTag> _tags; boost::log::attributes::mutable_constant<LogTruncation> _truncation; + boost::log::attributes::mutable_constant<ErrorCodes::Error> _uassertErrorCode; boost::log::attributes::mutable_constant<int32_t> _id; }; diff --git a/src/mongo/logv2/log_test_v2.cpp b/src/mongo/logv2/log_test_v2.cpp index f0ac7e3218f..0bda9fcc28d 100644 --- a/src/mongo/logv2/log_test_v2.cpp +++ b/src/mongo/logv2/log_test_v2.cpp @@ -44,6 +44,7 @@ #include "mongo/bson/oid.h" #include "mongo/logv2/bson_formatter.h" #include "mongo/logv2/component_settings_filter.h" +#include "mongo/logv2/composite_backend.h" #include "mongo/logv2/constants.h" #include "mongo/logv2/json_formatter.h" #include "mongo/logv2/log.h" @@ -52,6 +53,7 @@ #include "mongo/logv2/plain_formatter.h" #include "mongo/logv2/ramlog_sink.h" #include "mongo/logv2/text_formatter.h" +#include "mongo/logv2/uassert_sink.h" #include "mongo/platform/decimal128.h" #include "mongo/stdx/thread.h" #include "mongo/unittest/temp_dir.h" @@ -1515,6 +1517,47 @@ TEST_F(LogTestV2, FileLogging) { ASSERT(before_rotation == after_rotation); } +TEST_F(LogTestV2, UserAssert) { + std::vector<std::string> lines; + + using backend_t = CompositeBackend<LogCaptureBackend, UserAssertSink>; + + auto sink = boost::make_shared<boost::log::sinks::synchronous_sink<backend_t>>( + boost::make_shared<backend_t>(boost::make_shared<LogCaptureBackend>(lines), + boost::make_shared<UserAssertSink>())); + + sink->set_filter(ComponentSettingsFilter(LogManager::global().getGlobalDomain(), + LogManager::global().getGlobalSettings())); + sink->set_formatter(PlainFormatter()); + attach(sink); + + bool gotUassert = false; + try { + LOGV2_OPTIONS(4652000, {UserAssertAfterLog(ErrorCodes::BadValue)}, "uasserting log"); + } catch (const DBException& ex) { + ASSERT_EQUALS(ex.code(), ErrorCodes::BadValue); + ASSERT_EQUALS(ex.reason(), "uasserting log"); + ASSERT_EQUALS(lines.back(), ex.reason()); + gotUassert = true; + } + ASSERT(gotUassert); + + + bool gotUassertWithReplacementFields = false; + try { + LOGV2_OPTIONS(4652001, + {UserAssertAfterLog(ErrorCodes::BadValue)}, + "uasserting log {name}", + "name"_attr = 1); + } catch (const DBException& ex) { + ASSERT_EQUALS(ex.code(), ErrorCodes::BadValue); + ASSERT_EQUALS(ex.reason(), "uasserting log 1"); + ASSERT_EQUALS(lines.back(), ex.reason()); + gotUassertWithReplacementFields = true; + } + ASSERT(gotUassertWithReplacementFields); +} + } // namespace } // namespace logv2 } // namespace mongo diff --git a/src/mongo/logv2/plain_formatter.cpp b/src/mongo/logv2/plain_formatter.cpp index 8fd8d635fda..00edef93491 100644 --- a/src/mongo/logv2/plain_formatter.cpp +++ b/src/mongo/logv2/plain_formatter.cpp @@ -135,7 +135,7 @@ private: } // namespace void PlainFormatter::operator()(boost::log::record_view const& rec, - boost::log::formatting_ostream& strm) const { + fmt::memory_buffer& buffer) const { using namespace boost::log; StringData message = extract<StringData>(attributes::message(), rec).get(); @@ -144,7 +144,6 @@ void PlainFormatter::operator()(boost::log::record_view const& rec, TextValueExtractor extractor; extractor.args.reserve(attrs.size()); attrs.apply(extractor); - fmt::memory_buffer buffer; fmt::vformat_to( buffer, to_string_view(message), @@ -157,10 +156,18 @@ void PlainFormatter::operator()(boost::log::record_view const& rec, else attributeMaxSize = constants::kDefaultMaxAttributeOutputSizeKB * 1024; } - StringData dataToWrite(buffer.data(), std::min(attributeMaxSize, buffer.size())); - if (dataToWrite.endsWith("\n"_sd)) - dataToWrite = StringData(dataToWrite.rawData(), dataToWrite.size() - 1); - strm.write(dataToWrite.rawData(), dataToWrite.size()); + + buffer.resize(std::min(attributeMaxSize, buffer.size())); + if (StringData sd(buffer.data(), buffer.size()); sd.endsWith("\n"_sd)) + buffer.resize(buffer.size() - 1); +} + +void PlainFormatter::operator()(boost::log::record_view const& rec, + boost::log::formatting_ostream& strm) const { + using namespace boost::log; + fmt::memory_buffer buffer; + operator()(rec, buffer); + strm.write(buffer.data(), buffer.size()); } } // namespace mongo::logv2 diff --git a/src/mongo/logv2/plain_formatter.h b/src/mongo/logv2/plain_formatter.h index 6860c2dda10..bc74dd0a810 100644 --- a/src/mongo/logv2/plain_formatter.h +++ b/src/mongo/logv2/plain_formatter.h @@ -43,6 +43,7 @@ public: PlainFormatter(const AtomicWord<int32_t>* maxAttributeSizeKB = nullptr) : _maxAttributeSizeKB(maxAttributeSizeKB) {} + void operator()(boost::log::record_view const& rec, fmt::memory_buffer& buffer) const; void operator()(boost::log::record_view const& rec, boost::log::formatting_ostream& strm) const; private: diff --git a/src/mongo/logv2/uassert_sink.h b/src/mongo/logv2/uassert_sink.h new file mode 100644 index 00000000000..61aeb67625b --- /dev/null +++ b/src/mongo/logv2/uassert_sink.h @@ -0,0 +1,55 @@ +/** + * Copyright (C) 2020-present MongoDB, Inc. + * + * This program is free software: you can redistribute it and/or modify + * it under the terms of the Server Side Public License, version 1, + * as published by MongoDB, Inc. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * Server Side Public License for more details. + * + * You should have received a copy of the Server Side Public License + * along with this program. If not, see + * <http://www.mongodb.com/licensing/server-side-public-license>. + * + * As a special exception, the copyright holders give permission to link the + * code of portions of this program with the OpenSSL library under certain + * conditions as described in each individual source file and distribute + * linked combinations including the program with the OpenSSL library. You + * must comply with the Server Side Public License in all respects for + * all of the code used other than as permitted herein. If you modify file(s) + * with this exception, you may extend this exception to your version of the + * file(s), but you are not obligated to do so. If you do not wish to do so, + * delete this exception statement from your version. If you delete this + * exception statement from all source files in the program, then also delete + * it in the license file. + */ + +#pragma once + +#include <boost/log/attributes/attribute_value_set.hpp> +#include <boost/log/attributes/value_extraction.hpp> +#include <boost/log/core/record_view.hpp> +#include <boost/log/sinks.hpp> + +#include "mongo/logv2/bson_formatter.h" +#include "mongo/util/assert_util.h" + +namespace mongo::logv2 { +class UserAssertSink + : public boost::log::sinks:: + basic_formatted_sink_backend<char, boost::log::sinks::concurrent_feeding> { +public: + void consume(boost::log::record_view const& rec, string_type const& formatted_string) { + using boost::log::extract; + ErrorCodes::Error code = extract<ErrorCodes::Error>(attributes::userassert(), rec).get(); + if (code != ErrorCodes::OK) { + fmt::memory_buffer buffer; + PlainFormatter()(rec, buffer); + uasserted(code, StringData(buffer.data(), buffer.size())); + } + } +}; +} // namespace mongo::logv2 |