diff --git a/include/xrpl/basics/Log.h b/include/xrpl/basics/Log.h index 6638da7bee..5ba31f89f0 100644 --- a/include/xrpl/basics/Log.h +++ b/include/xrpl/basics/Log.h @@ -156,9 +156,10 @@ private: private: std::unique_ptr m_stream; boost::filesystem::path m_path; + std::mutex mutable fileMutex_; }; - std::mutex mutable mutex_; + std::mutex mutable sinkSetMutex_; std::map< std::string, std::unique_ptr, @@ -205,7 +206,7 @@ public: write( beast::severities::Severity level, std::string const& partition, - std::string const& text, + std::string text, bool console); std::string @@ -243,7 +244,7 @@ public: static void format( std::string& output, - std::string const& message, + std::string message, beast::severities::Severity severity, std::string const& partition); diff --git a/include/xrpl/beast/utility/Journal.h b/include/xrpl/beast/utility/Journal.h index d2d9ae0d57..f54b57815e 100644 --- a/include/xrpl/beast/utility/Journal.h +++ b/include/xrpl/beast/utility/Journal.h @@ -144,8 +144,8 @@ public: void setModuleName(std::string const& name); - [[nodiscard]] static JsonLogAttributes - combine(AttributeFields const& a, AttributeFields const& b); + void + combine(AttributeFields const& from); AttributeFields& contextValues() @@ -172,22 +172,37 @@ public: friend class Journal; }; - struct JsonLogContext + class JsonLogContext { - std::source_location location = {}; - rapidjson::Value messageParams; - rapidjson::MemoryPoolAllocator<> allocator; + rapidjson::Value attributes_; + rapidjson::MemoryPoolAllocator<> allocator_; + public: JsonLogContext() = default; - void - reset(std::source_location location_) noexcept + rapidjson::MemoryPoolAllocator<>& + allocator() { - location = location_; - messageParams = rapidjson::Value{}; - messageParams.SetObject(); - allocator.Clear(); + return allocator_; } + + rapidjson::Value& + messageParams() + { + return attributes_["Params"]; + } + + rapidjson::Value& + attributes() + { + return attributes_; + } + + void + reset( + std::source_location location, + severities::Severity severity, + std::optional const& attributes) noexcept; }; private: @@ -204,14 +219,13 @@ private: // Invariant: m_sink always points to a valid Sink Sink* m_sink = nullptr; - static void - initMessageContext(std::source_location location); + void + initMessageContext( + std::source_location location, + severities::Severity severity) const; static std::string - formatLog( - std::string const& message, - severities::Severity severity, - std::optional const& attributes = std::nullopt); + formatLog(std::string const& message); public: //-------------------------------------------------------------------------- @@ -304,25 +318,16 @@ public: { public: ScopedStream(ScopedStream const& other) - : ScopedStream(other.m_attributes, other.m_sink, other.m_level) + : ScopedStream(other.m_sink, other.m_level) { } - ScopedStream( - std::optional attributes, - Sink& sink, - Severity level); + ScopedStream(Sink& sink, Severity level); template - ScopedStream( - std::optional attributes, - Stream const& stream, - T const& t); + ScopedStream(Stream const& stream, T const& t); - ScopedStream( - std::optional attributes, - Stream const& stream, - std::ostream& manip(std::ostream&)); + ScopedStream(Stream const& stream, std::ostream& manip(std::ostream&)); ScopedStream& operator=(ScopedStream const&) = delete; @@ -343,7 +348,6 @@ public: operator<<(T const& t) const; private: - std::optional m_attributes; Sink& m_sink; Severity const m_level; std::ostringstream mutable m_ostream; @@ -378,11 +382,7 @@ public: Constructor is inlined so checking active() very inexpensive. */ - Stream( - std::optional attributes, - Sink& sink, - Severity level) - : m_attributes(std::move(attributes)), m_sink(sink), m_level(level) + Stream(Sink& sink, Severity level) : m_sink(sink), m_level(level) { XRPL_ASSERT( m_level < severities::kDisabled, @@ -390,8 +390,7 @@ public: } /** Construct or copy another Stream. */ - Stream(Stream const& other) - : Stream(other.m_attributes, other.m_sink, other.m_level) + Stream(Stream const& other) : Stream(other.m_sink, other.m_level) { } @@ -438,7 +437,6 @@ public: /** @} */ private: - std::optional m_attributes; Sink& m_sink; Severity m_level; }; @@ -467,9 +465,8 @@ public: if (other.m_attributes.has_value()) { if (m_attributes.has_value()) - m_attributes = JsonLogAttributes::combine( - other.m_attributes->contextValues_, - m_attributes->contextValues_); + m_attributes->combine( + other.m_attributes->contextValues_); else m_attributes = other.m_attributes; } @@ -516,9 +513,11 @@ public: /** Returns a stream for this sink, with the specified severity level. */ Stream - stream(Severity level) const + stream(Severity level, std::source_location location = std::source_location::current()) const { - return Stream(m_attributes, *m_sink, level); + if (m_jsonLogsEnabled) + initMessageContext(location, level); + return Stream(*m_sink, level); } /** Returns `true` if any message would be logged at this severity level. @@ -537,24 +536,24 @@ public: trace(std::source_location location = std::source_location::current()) const { if (m_jsonLogsEnabled) - initMessageContext(location); - return {m_attributes, *m_sink, severities::kTrace}; + initMessageContext(location, severities::kTrace); + return {*m_sink, severities::kTrace}; } Stream debug(std::source_location location = std::source_location::current()) const { if (m_jsonLogsEnabled) - initMessageContext(location); - return {m_attributes, *m_sink, severities::kDebug}; + initMessageContext(location, severities::kDebug); + return {*m_sink, severities::kDebug}; } Stream info(std::source_location location = std::source_location::current()) const { if (m_jsonLogsEnabled) - initMessageContext(location); - return {m_attributes, *m_sink, severities::kInfo}; + initMessageContext(location, severities::kInfo); + return {*m_sink, severities::kInfo}; } Stream @@ -563,24 +562,24 @@ public: char const* a = "a"; rapidjson::Value v{a, 1}; if (m_jsonLogsEnabled) - initMessageContext(location); - return {m_attributes, *m_sink, severities::kWarning}; + initMessageContext(location, severities::kWarning); + return {*m_sink, severities::kWarning}; } Stream error(std::source_location location = std::source_location::current()) const { if (m_jsonLogsEnabled) - initMessageContext(location); - return {m_attributes, *m_sink, severities::kError}; + initMessageContext(location, severities::kError); + return {*m_sink, severities::kError}; } Stream fatal(std::source_location location = std::source_location::current()) const { if (m_jsonLogsEnabled) - initMessageContext(location); - return {m_attributes, *m_sink, severities::kFatal}; + initMessageContext(location, severities::kFatal); + return {*m_sink, severities::kFatal}; } /** @} */ @@ -599,8 +598,7 @@ public: { globalLogAttributes_ = JsonLogAttributes{}; } - globalLogAttributes_ = JsonLogAttributes::combine( - globalLogAttributes_->contextValues(), + globalLogAttributes_->combine( globalLogAttributes.contextValues()); } }; @@ -617,11 +615,8 @@ static_assert(std::is_nothrow_destructible::value == true, ""); //------------------------------------------------------------------------------ template -Journal::ScopedStream::ScopedStream( - std::optional attributes, - Stream const& stream, - T const& t) - : ScopedStream(std::move(attributes), stream.sink(), stream.level()) +Journal::ScopedStream::ScopedStream(Stream const& stream, T const& t) + : ScopedStream(stream.sink(), stream.level()) { m_ostream << t; } @@ -640,7 +635,7 @@ template Journal::ScopedStream Journal::Stream::operator<<(T const& t) const { - return {m_attributes, *this, t}; + return {*this, t}; } namespace detail { @@ -766,6 +761,7 @@ setJsonValue( } } + object.RemoveMember(name); object.AddMember( rapidjson::StringRef(name), std::move(jsonValue), allocator); } @@ -778,8 +774,8 @@ operator<<(std::ostream& os, LogParameter const& param) if (!beast::Journal::m_jsonLogsEnabled) return os; detail::setJsonValue( - beast::Journal::currentJsonLogContext_.messageParams, - beast::Journal::currentJsonLogContext_.allocator, + beast::Journal::currentJsonLogContext_.messageParams(), + beast::Journal::currentJsonLogContext_.allocator(), param.name_, param.value_, &os); @@ -793,8 +789,8 @@ operator<<(std::ostream& os, LogField const& param) if (!beast::Journal::m_jsonLogsEnabled) return os; detail::setJsonValue( - beast::Journal::currentJsonLogContext_.messageParams, - beast::Journal::currentJsonLogContext_.allocator, + beast::Journal::currentJsonLogContext_.messageParams(), + beast::Journal::currentJsonLogContext_.allocator(), param.name_, param.value_, nullptr); diff --git a/src/libxrpl/basics/Log.cpp b/src/libxrpl/basics/Log.cpp index 0ddd56f17d..a87d9bb315 100644 --- a/src/libxrpl/basics/Log.cpp +++ b/src/libxrpl/basics/Log.cpp @@ -88,9 +88,13 @@ Logs::File::open(boost::filesystem::path const& path) if (stream->good()) { + std::lock_guard lock(fileMutex_); m_path = path; m_stream = std::move(stream); + size_t const bufsize = 256 * 1024; + static char buf[bufsize]; + m_stream->rdbuf()->pubsetbuf(buf, bufsize); wasOpened = true; } @@ -109,12 +113,14 @@ Logs::File::closeAndReopen() void Logs::File::close() { + std::lock_guard lock(fileMutex_); m_stream = nullptr; } void Logs::File::write(char const* text) { + std::lock_guard lock(fileMutex_); if (m_stream != nullptr) (*m_stream) << text; } @@ -122,10 +128,10 @@ Logs::File::write(char const* text) void Logs::File::writeln(char const* text) { + std::lock_guard lock(fileMutex_); if (m_stream != nullptr) { - (*m_stream) << text; - (*m_stream) << std::endl; + (*m_stream) << text << '\n'; } } @@ -145,7 +151,7 @@ Logs::open(boost::filesystem::path const& pathToLogFile) beast::Journal::Sink& Logs::get(std::string const& name) { - std::lock_guard lock(mutex_); + std::lock_guard lock(sinkSetMutex_); auto const result = sinks_.emplace(name, makeSink(name, thresh_)); return *result.first->second; } @@ -173,7 +179,7 @@ Logs::threshold() const void Logs::threshold(beast::severities::Severity thresh) { - std::lock_guard lock(mutex_); + std::lock_guard lock(sinkSetMutex_); thresh_ = thresh; for (auto& sink : sinks_) sink.second->threshold(thresh); @@ -183,7 +189,7 @@ std::vector> Logs::partition_severities() const { std::vector> list; - std::lock_guard lock(mutex_); + std::lock_guard lock(sinkSetMutex_); list.reserve(sinks_.size()); for (auto const& [name, sink] : sinks_) list.emplace_back(name, toString(fromSeverity(sink->threshold()))); @@ -194,12 +200,11 @@ void Logs::write( beast::severities::Severity level, std::string const& partition, - std::string const& text, + std::string text, bool console) { std::string s; - format(s, text, level, partition); - std::lock_guard lock(mutex_); + format(s, std::move(text), level, partition); file_.writeln(s); if (!silent_) std::cerr << s << '\n'; @@ -211,7 +216,6 @@ Logs::write( std::string Logs::rotate() { - std::lock_guard lock(mutex_); bool const wasOpened = file_.closeAndReopen(); if (wasOpened) return "The log file was closed and reopened."; @@ -328,15 +332,15 @@ Logs::fromString(std::string const& s) void Logs::format( std::string& output, - std::string const& message, + std::string message, beast::severities::Severity severity, std::string const& partition) { - output.reserve(message.size() + partition.size() + 100); - + output = std::move(message); if (!beast::Journal::isStructuredJournalEnabled()) { - output = to_string(std::chrono::system_clock::now()); + output.reserve(message.size() + partition.size() + 100); + output += to_string(std::chrono::system_clock::now()); output += " "; if (!partition.empty()) @@ -369,8 +373,6 @@ Logs::format( } } - output += message; - // Limit the maximum length of the output if (output.size() > maximumMessageCharacters) { diff --git a/src/libxrpl/beast/utility/beast_Journal.cpp b/src/libxrpl/beast/utility/beast_Journal.cpp index a710e7754c..04e286b8db 100644 --- a/src/libxrpl/beast/utility/beast_Journal.cpp +++ b/src/libxrpl/beast/utility/beast_Journal.cpp @@ -154,135 +154,136 @@ Journal::JsonLogAttributes::setModuleName(std::string const& name) allocator_); } -Journal::JsonLogAttributes +void Journal::JsonLogAttributes::combine( - AttributeFields const& a, - AttributeFields const& b) + AttributeFields const& from) { - JsonLogAttributes result; - - result.contextValues_.CopyFrom(a, result.allocator_); - - for (auto& member : b.GetObject()) + for (auto& member : from.GetObject()) { - auto val = rapidjson::Value{member.value, result.allocator_}; - if (result.contextValues_.HasMember(member.name)) - { - result.contextValues_[member.name] = std::move(val); - } - else - { - result.contextValues_.AddMember( - rapidjson::Value{member.name, result.allocator_}, - std::move(val), - result.allocator_); - } - } + contextValues_.RemoveMember(member.name); - return result; + contextValues_.AddMember( + rapidjson::Value{member.name, allocator_}, + rapidjson::Value{member.value, allocator_}, + allocator_); + } } void -Journal::initMessageContext(std::source_location location) +Journal::JsonLogContext::reset( + std::source_location location, + severities::Severity severity, + std::optional const& attributes) noexcept { - currentJsonLogContext_.reset(location); + struct ThreadIdStringInitializer + { + std::string value; + ThreadIdStringInitializer() + { + std::stringstream threadIdStream; + threadIdStream << std::this_thread::get_id(); + value = threadIdStream.str(); + } + }; + thread_local ThreadIdStringInitializer threadId; + + attributes_.SetObject(); + if (globalLogAttributes_.has_value()) + { + attributes_.CopyFrom(globalLogAttributes_->contextValues(), allocator_); + if (attributes.has_value()) + { + for (auto const& [key, value] : + attributes->contextValues().GetObject()) + { + attributes_.RemoveMember(key); + + rapidjson::Value jsonValue; + jsonValue.CopyFrom(value, allocator_); + + attributes_.AddMember( + rapidjson::Value{key, allocator_}, + rapidjson::Value{value, allocator_}, + allocator_); + } + } + } + else if (attributes.has_value()) + { + attributes_.CopyFrom(attributes->contextValues(), allocator_); + } + + attributes_.RemoveMember("Function"); + attributes_.AddMember( + rapidjson::StringRef("Function"), + rapidjson::Value{location.function_name(), allocator_}, + allocator_); + + attributes_.RemoveMember("File"); + attributes_.AddMember( + rapidjson::StringRef("File"), + rapidjson::Value{location.file_name(), allocator_}, + allocator_); + + attributes_.RemoveMember("Line"); + attributes_.AddMember( + rapidjson::StringRef("Line"), + location.line(), + allocator_); + attributes_.RemoveMember("ThreadId"); + attributes_.AddMember( + rapidjson::StringRef("ThreadId"), + rapidjson::Value{threadId.value.c_str(), allocator_}, + allocator_); + attributes_.RemoveMember("Params"); + attributes_.AddMember( + rapidjson::StringRef("Params"), + rapidjson::Value{rapidjson::kObjectType}, + allocator_); + auto severityStr = to_string(severity); + attributes_.RemoveMember("Level"); + attributes_.AddMember( + rapidjson::StringRef("Level"), + rapidjson::Value{severityStr.c_str(), allocator_}, + allocator_); + attributes_.RemoveMember("Time"); + attributes_.AddMember( + rapidjson::StringRef("Time"), + std::chrono::duration_cast( + std::chrono::system_clock::now().time_since_epoch()) + .count(), + allocator_); +} + +void +Journal::initMessageContext( + std::source_location location, + severities::Severity severity) const +{ + currentJsonLogContext_.reset(location, severity, m_attributes); } std::string -Journal::formatLog( - std::string const& message, - severities::Severity severity, - std::optional const& attributes) +Journal::formatLog(std::string const& message) { if (!m_jsonLogsEnabled) { return message; } - rapidjson::Document doc{¤tJsonLogContext_.allocator}; - rapidjson::Value logContext; - logContext.SetObject(); + auto& attributes = currentJsonLogContext_.attributes(); - logContext.AddMember( - rapidjson::StringRef("Function"), - rapidjson::StringRef(currentJsonLogContext_.location.function_name()), - currentJsonLogContext_.allocator); - - logContext.AddMember( - rapidjson::StringRef("File"), - rapidjson::StringRef(currentJsonLogContext_.location.file_name()), - currentJsonLogContext_.allocator); - - logContext.AddMember( - rapidjson::StringRef("Line"), - currentJsonLogContext_.location.line(), - currentJsonLogContext_.allocator); - std::stringstream threadIdStream; - threadIdStream << std::this_thread::get_id(); - auto threadIdStr = threadIdStream.str(); - logContext.AddMember( - rapidjson::StringRef("ThreadId"), - rapidjson::StringRef(threadIdStr.c_str()), - currentJsonLogContext_.allocator); - logContext.AddMember( - rapidjson::StringRef("Params"), - std::move(currentJsonLogContext_.messageParams), - currentJsonLogContext_.allocator); - currentJsonLogContext_.messageParams = rapidjson::Value{}; - currentJsonLogContext_.messageParams.SetObject(); - auto severityStr = to_string(severity); - logContext.AddMember( - rapidjson::StringRef("Level"), - rapidjson::StringRef(severityStr.c_str()), - currentJsonLogContext_.allocator); - logContext.AddMember( + attributes.RemoveMember("Message"); + attributes.AddMember( rapidjson::StringRef("Message"), - rapidjson::StringRef(message.c_str()), - currentJsonLogContext_.allocator); - logContext.AddMember( - rapidjson::StringRef("Time"), - std::chrono::duration_cast( - std::chrono::system_clock::now().time_since_epoch()) - .count(), - currentJsonLogContext_.allocator); - - if (attributes.has_value()) - { - for (auto const& [key, value] : attributes->contextValues().GetObject()) - { - if (logContext.HasMember(key)) - continue; - rapidjson::Value jsonValue; - jsonValue.CopyFrom(value, currentJsonLogContext_.allocator); - - logContext.AddMember( - rapidjson::Value{key, currentJsonLogContext_.allocator}, - std::move(jsonValue), - currentJsonLogContext_.allocator); - } - } - - if (globalLogAttributes_) - { - for (auto const& [key, value] : - globalLogAttributes_->contextValues().GetObject()) - { - if (logContext.HasMember(key)) - continue; - rapidjson::Value jsonValue; - jsonValue.CopyFrom(value, currentJsonLogContext_.allocator); - - logContext.AddMember( - rapidjson::Value{key, currentJsonLogContext_.allocator}, - std::move(jsonValue), - currentJsonLogContext_.allocator); - } - } + rapidjson::Value{rapidjson::StringRef(message.c_str()), currentJsonLogContext_.allocator()}, + currentJsonLogContext_.allocator() + ); rapidjson::StringBuffer buffer; rapidjson::Writer writer(buffer); - logContext.Accept(writer); + attributes.Accept(writer); return {buffer.GetString()}; } @@ -345,21 +346,17 @@ Journal::Sink::threshold(Severity thresh) //------------------------------------------------------------------------------ -Journal::ScopedStream::ScopedStream( - std::optional attributes, - Sink& sink, - Severity level) - : m_attributes(std::move(attributes)), m_sink(sink), m_level(level) +Journal::ScopedStream::ScopedStream(Sink& sink, Severity level) + : m_sink(sink), m_level(level) { // Modifiers applied from all ctors m_ostream << std::boolalpha << std::showbase; } Journal::ScopedStream::ScopedStream( - std::optional attributes, Stream const& stream, std::ostream& manip(std::ostream&)) - : ScopedStream(std::move(attributes), stream.sink(), stream.level()) + : ScopedStream(stream.sink(), stream.level()) { m_ostream << manip; } @@ -370,9 +367,9 @@ Journal::ScopedStream::~ScopedStream() if (!s.empty()) { if (s == "\n") - m_sink.write(m_level, formatLog("", m_level, m_attributes)); + m_sink.write(m_level, formatLog("")); else - m_sink.write(m_level, formatLog(s, m_level, m_attributes)); + m_sink.write(m_level, formatLog(s)); } } @@ -387,7 +384,7 @@ Journal::ScopedStream::operator<<(std::ostream& manip(std::ostream&)) const Journal::ScopedStream Journal::Stream::operator<<(std::ostream& manip(std::ostream&)) const { - return {m_attributes, *this, manip}; + return {*this, manip}; } } // namespace beast