diff --git a/include/xrpl/basics/Log.h b/include/xrpl/basics/Log.h index 833907eb9c8..f48a5cf8e5d 100644 --- a/include/xrpl/basics/Log.h +++ b/include/xrpl/basics/Log.h @@ -30,6 +30,7 @@ #include #include #include +#include #include namespace ripple { @@ -130,27 +131,14 @@ class Logs Does nothing if there is no associated system file. */ void - write(char const* text); + write(std::string_view text); /** write to the log file and append an end of line marker. Does nothing if there is no associated system file. */ void - writeln(char const* text); + writeln(std::string_view text); - /** Write to the log file using std::string. */ - /** @{ */ - void - write(std::string const& str) - { - write(str.c_str()); - } - - void - writeln(std::string const& str) - { - writeln(str.c_str()); - } /** @} */ private: @@ -186,6 +174,14 @@ class Logs beast::Journal::Sink& operator[](std::string const& name); + template + beast::Journal + journal(std::string const& name, AttributesFactory&& factory) + { + return beast::Journal{ + get(name), name, std::forward(factory)}; + } + beast::Journal journal(std::string const& name); @@ -237,30 +233,34 @@ class Logs static LogSeverity fromString(std::string const& s); -private: - enum { - // Maximum line length for log messages. - // If the message exceeds this length it will be truncated with elipses. - maximumMessageCharacters = 12 * 1024 - }; - static void format( std::string& output, std::string const& message, beast::severities::Severity severity, std::string const& partition); + +private: + enum { + // Maximum line length for log messages. + // If the message exceeds this length it will be truncated with elipses. + maximumMessageCharacters = 12 * 1024 + }; }; // Wraps a Journal::Stream to skip evaluation of // expensive argument lists if the stream is not active. #ifndef JLOG -#define JLOG(x) \ - if (!x) \ - { \ - } \ - else \ - x +#define JLOG_JOIN_(a, b) a##b +#define JLOG_JOIN(a, b) JLOG_JOIN_(a, b) +#define JLOG_UNIQUE(base) JLOG_JOIN(base, __LINE__) // line-based unique name + +#define JLOG(x) \ + if (auto JLOG_UNIQUE(stream) = (x); !JLOG_UNIQUE(stream)) \ + { \ + } \ + else \ + std::move(JLOG_UNIQUE(stream)) #endif #ifndef CLOG diff --git a/include/xrpl/beast/utility/Journal.h b/include/xrpl/beast/utility/Journal.h index 91ddf33d271..9da59fd0b2b 100644 --- a/include/xrpl/beast/utility/Journal.h +++ b/include/xrpl/beast/utility/Journal.h @@ -22,10 +22,266 @@ #include +#include +#include +#include +#include +#include +#include +#include #include +#include +#include +#include + +namespace ripple::log { +template +class LogParameter +{ +public: + template + LogParameter(char const* name, TArg&& value) + : name_(name), value_(std::forward(value)) + { + } + +private: + char const* name_; + T value_; + + template + friend std::ostream& + operator<<(std::ostream& os, LogParameter const&); +}; + +template +class LogField +{ +public: + template + LogField(char const* name, TArg&& value) + : name_(name), value_(std::forward(value)) + { + } + +private: + char const* name_; + T value_; + + template + friend std::ostream& + operator<<(std::ostream& os, LogField const&); +}; + +template +std::ostream& +operator<<(std::ostream& os, LogField const& param); + +template +std::ostream& +operator<<(std::ostream& os, LogParameter const& param); +} // namespace ripple::log namespace beast { +namespace detail { + +class SimpleJsonWriter +{ +public: + explicit SimpleJsonWriter(std::string* buffer) : buffer_(buffer) + { + } + + SimpleJsonWriter() = default; + + SimpleJsonWriter(SimpleJsonWriter const& other) = default; + SimpleJsonWriter& + operator=(SimpleJsonWriter const& other) = default; + + std::string& + buffer() + { + return *buffer_; + } + + void + startObject() const + { + buffer_->push_back('{'); + } + void + endObject() const + { + using namespace std::string_view_literals; + if (buffer_->back() == ',') + buffer_->pop_back(); + buffer_->append("},"sv); + } + void + writeKey(std::string_view key) const + { + writeString(key); + buffer_->back() = ':'; + } + void + startArray() const + { + buffer_->push_back('['); + } + void + endArray() const + { + using namespace std::string_view_literals; + if (buffer_->back() == ',') + buffer_->pop_back(); + buffer_->append("],"sv); + } + void + writeString(std::string_view str) const + { + using namespace std::string_view_literals; + buffer_->push_back('"'); + escape(str, *buffer_); + buffer_->append("\","sv); + } + std::string_view + writeInt(std::int32_t val) const + { + return pushNumber(val, *buffer_); + } + std::string_view + writeInt(std::int64_t val) const + { + return pushNumber(val, *buffer_); + } + std::string_view + writeUInt(std::uint32_t val) const + { + return pushNumber(val, *buffer_); + } + std::string_view + writeUInt(std::uint64_t val) const + { + return pushNumber(val, *buffer_); + } + std::string_view + writeDouble(double val) const + { + return pushNumber(val, *buffer_); + } + std::string_view + writeBool(bool val) const + { + using namespace std::string_view_literals; + auto str = val ? "true,"sv : "false,"sv; + buffer_->append(str); + return str; + } + void + writeNull() const + { + using namespace std::string_view_literals; + buffer_->append("null,"sv); + } + void + writeRaw(std::string_view str) const + { + buffer_->append(str); + } + + void + finish() + { + buffer_->pop_back(); + } + +private: + template + static std::string_view + pushNumber(T val, std::string& str) + { + thread_local char buffer[128]; + auto result = std::to_chars(std::begin(buffer), std::end(buffer), val); + auto ptr = result.ptr; + *ptr = ','; + auto len = ptr - std::begin(buffer); + str.append(buffer, len + 1); + return {buffer, static_cast(len)}; + } + + static void + escape(std::string_view str, std::string& buffer) + { + static constexpr char HEX[] = "0123456789ABCDEF"; + + char const* p = str.data(); + char const* end = p + str.size(); + char const* chunk = p; + + while (p < end) + { + auto c = static_cast(*p); + + // JSON requires escaping for <0x20 and the two specials below. + bool needsEscape = (c < 0x20) || (c == '"') || (c == '\\'); + + if (!needsEscape) + { + ++p; + continue; + } + + // Flush the preceding safe run in one go. + if (chunk != p) + buffer.append(chunk, p - chunk); + + switch (c) + { + case '"': + buffer.append("\\\"", 2); + break; + case '\\': + buffer.append("\\\\", 2); + break; + case '\b': + buffer.append("\\b", 2); + break; + case '\f': + buffer.append("\\f", 2); + break; + case '\n': + buffer.append("\\n", 2); + break; + case '\r': + buffer.append("\\r", 2); + break; + case '\t': + buffer.append("\\t", 2); + break; + default: { + // Other C0 controls -> \u00XX (JSON compliant) + char buf[6]{ + '\\', 'u', '0', '0', HEX[(c >> 4) & 0xF], HEX[c & 0xF]}; + buffer.append(buf, 6); + break; + } + } + + ++p; + chunk = p; + } + + // Flush trailing safe run + if (chunk != p) + buffer.append(chunk, p - chunk); + } + + std::string* buffer_ = nullptr; +}; + +} // namespace detail + /** A namespace for easy access to logging severity values. */ namespace severities { /** Severity level / threshold of a Journal message. */ @@ -42,6 +298,9 @@ enum Severity { kDisabled, kNone = kDisabled }; + +std::string_view +to_string(Severity severity); } // namespace severities /** A generic endpoint for log messages. @@ -59,18 +318,114 @@ enum Severity { class Journal { public: + template + friend std::ostream& + ripple::log::operator<<( + std::ostream& os, + ripple::log::LogField const& param); + + template + friend std::ostream& + ripple::log::operator<<( + std::ostream& os, + ripple::log::LogParameter const& param); + class Sink; + class JsonLogContext + { + std::string messageBuffer_; + detail::SimpleJsonWriter jsonWriter_; + bool hasMessageParams_ = false; + std::size_t messageOffset_ = 0; + + public: + JsonLogContext() : jsonWriter_(&messageBuffer_) + { + messageBuffer_.reserve(4 * 1024); + } + + std::string& + messageBuffer() + { + return messageBuffer_; + } + + void + startMessageParams() + { + if (!hasMessageParams_) + { + writer().writeKey("Dt"); + writer().startObject(); + hasMessageParams_ = true; + } + } + + void + endMessageParams() + { + if (hasMessageParams_) + { + writer().endObject(); + } + } + + detail::SimpleJsonWriter& + writer() + { + return jsonWriter_; + } + + void + reuseJson(); + + void + finish(); + + void + start( + std::source_location location, + severities::Severity severity, + std::string_view moduleName, + std::string_view journalAttributes) noexcept; + }; + private: // Severity level / threshold of a Journal message. using Severity = severities::Severity; + std::string name_; + std::string attributes_; + static std::string globalLogAttributes_; + static std::shared_mutex globalLogAttributesMutex_; + static bool jsonLogsEnabled_; + + static thread_local JsonLogContext currentJsonLogContext_; + // Invariant: m_sink always points to a valid Sink - Sink* m_sink; + Sink* m_sink = nullptr; + + void + initMessageContext( + std::source_location location, + severities::Severity severity) const; + + static std::string& + formatLog(std::string const& message); public: //-------------------------------------------------------------------------- + static void + enableStructuredJournal(); + + static void + disableStructuredJournal(); + + static bool + isStructuredJournalEnabled(); + /** Abstraction for the underlying message destination. */ class Sink { @@ -261,11 +616,32 @@ class Journal /** Output stream support. */ /** @{ */ ScopedStream - operator<<(std::ostream& manip(std::ostream&)) const; + operator<<(std::ostream& manip(std::ostream&)) const&& + { + return {*this, manip}; + } template ScopedStream - operator<<(T const& t) const; + operator<<(T const& t) const&& + { + return {*this, t}; + } + + ScopedStream + operator<<(std::ostream& manip(std::ostream&)) const& + { + currentJsonLogContext_.reuseJson(); + return {*this, manip}; + } + + template + ScopedStream + operator<<(T const& t) const& + { + currentJsonLogContext_.reuseJson(); + return {*this, t}; + } /** @} */ private: @@ -287,9 +663,71 @@ class Journal /** Journal has no default constructor. */ Journal() = delete; + Journal(Journal const& other) + : name_(other.name_) + , attributes_(other.attributes_) + , m_sink(other.m_sink) + { + } + + template + Journal(Journal const& other, TAttributesFactory&& attributesFactory) + : name_(other.name_), m_sink(other.m_sink) + { + std::string buffer{other.attributes_}; + detail::SimpleJsonWriter writer{&buffer}; + if (other.attributes_.empty() && jsonLogsEnabled_) + { + writer.startObject(); + } + attributesFactory(writer); + attributes_ = std::move(buffer); + } + + /** Create a journal that writes to the specified sink. */ + explicit Journal(Sink& sink, std::string const& name = {}) + : name_(name), m_sink(&sink) + { + } + /** Create a journal that writes to the specified sink. */ - explicit Journal(Sink& sink) : m_sink(&sink) + template + explicit Journal( + Sink& sink, + std::string const& name, + TAttributesFactory&& attributesFactory) + : name_(name), m_sink(&sink) { + std::string buffer; + buffer.reserve(128); + detail::SimpleJsonWriter writer{&buffer}; + if (jsonLogsEnabled_) + { + writer.startObject(); + } + attributesFactory(writer); + attributes_ = std::move(buffer); + } + + Journal& + operator=(Journal const& other) + { + if (&other == this) + return *this; // LCOV_EXCL_LINE + + m_sink = other.m_sink; + name_ = other.name_; + attributes_ = other.attributes_; + return *this; + } + + Journal& + operator=(Journal&& other) noexcept + { + m_sink = other.m_sink; + name_ = std::move(other.name_); + attributes_ = std::move(other.attributes_); + return *this; } /** Returns the Sink associated with this Journal. */ @@ -301,8 +739,11 @@ class Journal /** 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 { + initMessageContext(location, level); return Stream(*m_sink, level); } @@ -319,41 +760,69 @@ class Journal /** Severity stream access functions. */ /** @{ */ Stream - trace() const + trace(std::source_location location = std::source_location::current()) const { + initMessageContext(location, severities::kTrace); return {*m_sink, severities::kTrace}; } Stream - debug() const + debug(std::source_location location = std::source_location::current()) const { + initMessageContext(location, severities::kDebug); return {*m_sink, severities::kDebug}; } Stream - info() const + info(std::source_location location = std::source_location::current()) const { + initMessageContext(location, severities::kInfo); return {*m_sink, severities::kInfo}; } Stream - warn() const + warn(std::source_location location = std::source_location::current()) const { + initMessageContext(location, severities::kWarning); return {*m_sink, severities::kWarning}; } Stream - error() const + error(std::source_location location = std::source_location::current()) const { + initMessageContext(location, severities::kError); return {*m_sink, severities::kError}; } Stream - fatal() const + fatal(std::source_location location = std::source_location::current()) const { + initMessageContext(location, severities::kFatal); return {*m_sink, severities::kFatal}; } /** @} */ + + static void + resetGlobalAttributes() + { + std::unique_lock lock(globalLogAttributesMutex_); + globalLogAttributes_.clear(); + } + + template + static void + addGlobalAttributes(TAttributesFactory&& factory) + { + std::unique_lock lock(globalLogAttributesMutex_); + globalLogAttributes_.reserve(1024); + auto isEmpty = globalLogAttributes_.empty(); + detail::SimpleJsonWriter writer{&globalLogAttributes_}; + if (isEmpty && jsonLogsEnabled_) + { + writer.startObject(); + } + factory(writer); + } }; #ifndef __INTELLISENSE__ @@ -368,7 +837,7 @@ static_assert(std::is_nothrow_destructible::value == true, ""); //------------------------------------------------------------------------------ template -Journal::ScopedStream::ScopedStream(Journal::Stream const& stream, T const& t) +Journal::ScopedStream::ScopedStream(Stream const& stream, T const& t) : ScopedStream(stream.sink(), stream.level()) { m_ostream << t; @@ -384,13 +853,6 @@ Journal::ScopedStream::operator<<(T const& t) const //------------------------------------------------------------------------------ -template -Journal::ScopedStream -Journal::Stream::operator<<(T const& t) const -{ - return ScopedStream(*this, t); -} - namespace detail { template > @@ -460,4 +922,244 @@ using logwstream = basic_logstream; } // namespace beast +namespace ripple::log { + +namespace detail { + +template +concept ToCharsFormattable = requires(T val) { + { + to_chars(std::declval(), std::declval(), val) + } -> std::convertible_to; +}; + +template +concept StreamFormattable = requires(T val) { + { + std::declval() << val + } -> std::convertible_to; +}; + +template +void +setTextValue( + beast::detail::SimpleJsonWriter& writer, + char const* name, + T&& value) +{ + using ValueType = std::decay_t; + writer.buffer() += name; + writer.buffer() += ": "; + if constexpr ( + std::is_same_v || + std::is_same_v || + std::is_same_v || + std::is_same_v) + { + writer.buffer() += value; + } + else + { + std::ostringstream oss; + oss << value; + writer.buffer() += value; + ; + } + writer.buffer() += " "; +} + +template +void +setJsonValue( + beast::detail::SimpleJsonWriter& writer, + char const* name, + T&& value, + std::ostream* outStream) +{ + using ValueType = std::decay_t; + writer.writeKey(name); + if constexpr (std::is_same_v) + { + auto sv = writer.writeBool(value); + if (outStream) + { + outStream->write(sv.data(), sv.size()); + } + } + else if constexpr (std::is_integral_v) + { + std::string_view sv; + if constexpr (std::is_signed_v) + { + if constexpr (sizeof(ValueType) > 4) + { + sv = writer.writeInt(static_cast(value)); + } + else + { + sv = writer.writeInt(static_cast(value)); + } + } + else + { + if constexpr (sizeof(ValueType) > 4) + { + sv = writer.writeUInt(static_cast(value)); + } + else + { + sv = writer.writeUInt(static_cast(value)); + } + } + if (outStream) + { + outStream->write(sv.data(), sv.size()); + } + } + else if constexpr (std::is_floating_point_v) + { + auto sv = writer.writeDouble(value); + + if (outStream) + { + outStream->write(sv.data(), sv.size()); + } + } + else if constexpr ( + std::is_same_v || + std::is_same_v) + { + writer.writeString(value); + if (outStream) + { + outStream->write(value, std::strlen(value)); + } + } + else if constexpr ( + std::is_same_v || + std::is_same_v) + { + writer.writeString(value); + if (outStream) + { + outStream->write(value.data(), value.size()); + } + } + else + { + if constexpr (ToCharsFormattable) + { + char buffer[1024]; + std::to_chars_result result = + to_chars(std::begin(buffer), std::end(buffer), value); + if (result.ec == std::errc{}) + { + std::string_view sv{std::begin(buffer), result.ptr}; + writer.writeString(sv); + if (outStream) + { + outStream->write(sv.data(), sv.size()); + } + return; + } + } + + if constexpr (StreamFormattable) + { + std::ostringstream oss; + oss.imbue(std::locale::classic()); + oss << value; + + auto str = oss.str(); + + writer.writeString(str); + + if (outStream) + { + outStream->write( + str.c_str(), static_cast(str.size())); + } + + return; + } + + static_assert( + ToCharsFormattable || StreamFormattable); + } +} +} // namespace detail + +template +std::ostream& +operator<<(std::ostream& os, LogParameter const& param) +{ + if (!beast::Journal::jsonLogsEnabled_) + { + os << param.value_; + return os; + } + beast::Journal::currentJsonLogContext_.startMessageParams(); + detail::setJsonValue( + beast::Journal::currentJsonLogContext_.writer(), + param.name_, + param.value_, + &os); + return os; +} + +template +std::ostream& +operator<<(std::ostream& os, LogField const& param) +{ + if (!beast::Journal::jsonLogsEnabled_) + return os; + beast::Journal::currentJsonLogContext_.startMessageParams(); + detail::setJsonValue( + beast::Journal::currentJsonLogContext_.writer(), + param.name_, + param.value_, + nullptr); + return os; +} + +template +LogParameter +param(char const* name, T&& value) +{ + return LogParameter{name, std::forward(value)}; +} + +template +LogField +field(char const* name, T&& value) +{ + return LogField{name, std::forward(value)}; +} + +template +[[nodiscard]] auto +attributes(Pair&&... pairs) +{ + return [&](beast::detail::SimpleJsonWriter& writer) { + if (beast::Journal::isStructuredJournalEnabled()) + { + (detail::setJsonValue(writer, pairs.first, pairs.second, nullptr), + ...); + } + else + { + (detail::setTextValue(writer, pairs.first, pairs.second), ...); + } + }; +} + +template +[[nodiscard]] std::pair> +attr(char const* name, T&& value) +{ + return std::make_pair(name, std::forward(value)); +} + +} // namespace ripple::log + #endif diff --git a/include/xrpl/server/detail/BasePeer.h b/include/xrpl/server/detail/BasePeer.h index 30de63e6ff0..e733b9e4f5c 100644 --- a/include/xrpl/server/detail/BasePeer.h +++ b/include/xrpl/server/detail/BasePeer.h @@ -47,7 +47,6 @@ class BasePeer : public io_list::work Port const& port_; Handler& handler_; endpoint_type remote_address_; - beast::WrappedSink sink_; beast::Journal const j_; boost::asio::executor_work_guard work_; @@ -84,13 +83,13 @@ BasePeer::BasePeer( : port_(port) , handler_(handler) , remote_address_(remote_address) - , sink_( - journal.sink(), - [] { - static std::atomic id{0}; - return "##" + std::to_string(++id) + " "; - }()) - , j_(sink_) + , j_(journal, + log::attributes(log::attr( + "PeerID", + [] { + static std::atomic id{0}; + return "##" + std::to_string(++id) + " "; + }()))) , work_(boost::asio::make_work_guard(executor)) , strand_(boost::asio::make_strand(executor)) { diff --git a/src/libxrpl/basics/Log.cpp b/src/libxrpl/basics/Log.cpp index 14873a3fd79..8352e13e77e 100644 --- a/src/libxrpl/basics/Log.cpp +++ b/src/libxrpl/basics/Log.cpp @@ -113,14 +113,14 @@ Logs::File::close() } void -Logs::File::write(char const* text) +Logs::File::write(std::string_view text) { if (m_stream != nullptr) (*m_stream) << text; } void -Logs::File::writeln(char const* text) +Logs::File::writeln(std::string_view text) { if (m_stream != nullptr) { @@ -196,11 +196,15 @@ Logs::write( bool console) { std::string s; - format(s, text, level, partition); + std::string_view result = text; + if (!beast::Journal::isStructuredJournalEnabled()) + { + format(s, text, level, partition); + result = text; + } + std::lock_guard lock(mutex_); - file_.writeln(s); - if (!silent_) - std::cerr << s << '\n'; + file_.writeln(result); // VFALCO TODO Fix console output // if (console) // out_.write_console(s); diff --git a/src/libxrpl/beast/utility/beast_Journal.cpp b/src/libxrpl/beast/utility/beast_Journal.cpp index 828f2fa619e..1b4f9b375a7 100644 --- a/src/libxrpl/beast/utility/beast_Journal.cpp +++ b/src/libxrpl/beast/utility/beast_Journal.cpp @@ -19,12 +19,102 @@ #include +#include #include #include +#include #include +#include namespace beast { +namespace { + +// Fast timestamp to ISO string conversion +// Returns string like "2024-01-15T10:30:45.123Z" +std::string_view +fastTimestampToString(std::int64_t milliseconds_since_epoch) +{ + thread_local char buffer[64]; // "2024-01-15T10:30:45.123Z" + + // Precomputed lookup table for 2-digit numbers 00-99 + static constexpr char digits[200] = { + '0', '0', '0', '1', '0', '2', '0', '3', '0', '4', '0', '5', '0', '6', + '0', '7', '0', '8', '0', '9', '1', '0', '1', '1', '1', '2', '1', '3', + '1', '4', '1', '5', '1', '6', '1', '7', '1', '8', '1', '9', '2', '0', + '2', '1', '2', '2', '2', '3', '2', '4', '2', '5', '2', '6', '2', '7', + '2', '8', '2', '9', '3', '0', '3', '1', '3', '2', '3', '3', '3', '4', + '3', '5', '3', '6', '3', '7', '3', '8', '3', '9', '4', '0', '4', '1', + '4', '2', '4', '3', '4', '4', '4', '5', '4', '6', '4', '7', '4', '8', + '4', '9', '5', '0', '5', '1', '5', '2', '5', '3', '5', '4', '5', '5', + '5', '6', '5', '7', '5', '8', '5', '9', '6', '0', '6', '1', '6', '2', + '6', '3', '6', '4', '6', '5', '6', '6', '6', '7', '6', '8', '6', '9', + '7', '0', '7', '1', '7', '2', '7', '3', '7', '4', '7', '5', '7', '6', + '7', '7', '7', '8', '7', '9', '8', '0', '8', '1', '8', '2', '8', '3', + '8', '4', '8', '5', '8', '6', '8', '7', '8', '8', '8', '9', '9', '0', + '9', '1', '9', '2', '9', '3', '9', '4', '9', '5', '9', '6', '9', '7', + '9', '8', '9', '9'}; + + constexpr std::int64_t UNIX_EPOCH_DAYS = + 719468; // Days from year 0 to 1970-01-01 + + std::int64_t seconds = milliseconds_since_epoch / 1000; + int ms = milliseconds_since_epoch % 1000; + std::int64_t days = seconds / 86400 + UNIX_EPOCH_DAYS; + int sec_of_day = seconds % 86400; + + // Calculate year, month, day from days using Gregorian calendar algorithm + int era = (days >= 0 ? days : days - 146096) / 146097; + int doe = days - era * 146097; + int yoe = (doe - doe / 1460 + doe / 36524 - doe / 146096) / 365; + int year = yoe + era * 400; + int doy = doe - (365 * yoe + yoe / 4 - yoe / 100); + int mp = (5 * doy + 2) / 153; + int day = doy - (153 * mp + 2) / 5 + 1; + int month = mp + (mp < 10 ? 3 : -9); + year += (month <= 2); + + // Calculate hour, minute, second + int hour = sec_of_day / 3600; + int min = (sec_of_day % 3600) / 60; + int sec = sec_of_day % 60; + + // Format: "2024-01-15T10:30:45.123Z" + buffer[0] = '0' + year / 1000; + buffer[1] = '0' + (year / 100) % 10; + buffer[2] = '0' + (year / 10) % 10; + buffer[3] = '0' + year % 10; + buffer[4] = '-'; + buffer[5] = digits[month * 2]; + buffer[6] = digits[month * 2 + 1]; + buffer[7] = '-'; + buffer[8] = digits[day * 2]; + buffer[9] = digits[day * 2 + 1]; + buffer[10] = 'T'; + buffer[11] = digits[hour * 2]; + buffer[12] = digits[hour * 2 + 1]; + buffer[13] = ':'; + buffer[14] = digits[min * 2]; + buffer[15] = digits[min * 2 + 1]; + buffer[16] = ':'; + buffer[17] = digits[sec * 2]; + buffer[18] = digits[sec * 2 + 1]; + buffer[19] = '.'; + buffer[20] = '0' + ms / 100; + buffer[21] = '0' + (ms / 10) % 10; + buffer[22] = '0' + ms % 10; + buffer[23] = 'Z'; + + return {buffer, 24}; +} + +} // anonymous namespace + +std::string Journal::globalLogAttributes_; +std::shared_mutex Journal::globalLogAttributesMutex_; +bool Journal::jsonLogsEnabled_ = false; +thread_local Journal::JsonLogContext Journal::currentJsonLogContext_{}; + //------------------------------------------------------------------------------ // A Sink that does nothing. @@ -87,6 +177,186 @@ Journal::getNullSink() //------------------------------------------------------------------------------ +std::string_view +severities::to_string(Severity severity) +{ + using namespace std::string_view_literals; + switch (severity) + { + case kDisabled: + return "disabled"sv; + case kTrace: + return "trace"sv; + case kDebug: + return "debug"sv; + case kInfo: + return "info"sv; + case kWarning: + return "warning"sv; + case kError: + return "error"sv; + case kFatal: + return "fatal"sv; + default: + UNREACHABLE("Unexpected severity value!"); + } + return ""sv; +} + +void +Journal::JsonLogContext::start( + std::source_location location, + severities::Severity severity, + std::string_view moduleName, + std::string_view journalAttributes) noexcept +{ + struct ThreadIdStringInitializer + { + std::string value; + ThreadIdStringInitializer() + { + std::stringstream threadIdStream; + threadIdStream << std::this_thread::get_id(); + value = threadIdStream.str(); + } + }; + thread_local ThreadIdStringInitializer const threadId; + + messageOffset_ = 0; + messageBuffer_.clear(); + jsonWriter_ = detail::SimpleJsonWriter{&messageBuffer_}; + + if (!jsonLogsEnabled_) + { + messageBuffer_ = journalAttributes; + return; + } + + writer().startObject(); + + if (!journalAttributes.empty()) + { + writer().writeKey("Jnl"); + writer().writeRaw(journalAttributes); + writer().endObject(); + } + + { + std::shared_lock lock(globalLogAttributesMutex_); + if (!globalLogAttributes_.empty()) + { + writer().writeKey("Glb"); + writer().writeRaw(globalLogAttributes_); + writer().endObject(); + } + } + + writer().writeKey("Mtd"); + writer().startObject(); + + writer().writeKey("Mdl"); + writer().writeString(moduleName); + + writer().writeKey("Fl"); + constexpr size_t FILE_NAME_KEEP_CHARS = 20; + std::string_view fileName = location.file_name(); + std::string_view trimmedFileName = (fileName.size() > FILE_NAME_KEEP_CHARS) + ? fileName.substr(fileName.size() - FILE_NAME_KEEP_CHARS) + : fileName; + writer().writeString(trimmedFileName); + + writer().writeKey("Ln"); + writer().writeUInt(location.line()); + + writer().writeKey("ThId"); + writer().writeString(threadId.value); + + auto severityStr = to_string(severity); + writer().writeKey("Lv"); + writer().writeString(severityStr); + + auto nowMs = std::chrono::duration_cast( + std::chrono::system_clock::now().time_since_epoch()) + .count(); + writer().writeKey("Tm"); + writer().writeString(fastTimestampToString(nowMs)); + + writer().endObject(); + + hasMessageParams_ = false; +} + +void +Journal::JsonLogContext::reuseJson() +{ + messageOffset_ = messageBuffer_.size(); +} + +void +Journal::JsonLogContext::finish() +{ + if (messageOffset_ != 0) + { + messageBuffer_.erase(messageOffset_); + } + else + { + messageBuffer_.clear(); + } + + jsonWriter_ = detail::SimpleJsonWriter{&messageBuffer_}; +} + +void +Journal::initMessageContext( + std::source_location location, + severities::Severity severity) const +{ + currentJsonLogContext_.start(location, severity, name_, attributes_); +} + +std::string& +Journal::formatLog(std::string const& message) +{ + if (!jsonLogsEnabled_) + { + currentJsonLogContext_.writer().buffer() += message; + return currentJsonLogContext_.messageBuffer(); + } + + auto& writer = currentJsonLogContext_.writer(); + + currentJsonLogContext_.endMessageParams(); + + writer.writeKey("Msg"); + writer.writeString(message); + + writer.endObject(); + + writer.finish(); + + return currentJsonLogContext_.messageBuffer(); +} + +void +Journal::enableStructuredJournal() +{ + jsonLogsEnabled_ = true; +} + +void +Journal::disableStructuredJournal() +{ + jsonLogsEnabled_ = false; + resetGlobalAttributes(); +} + +bool +Journal::isStructuredJournalEnabled() +{ + return jsonLogsEnabled_; +} + Journal::Sink::Sink(Severity thresh, bool console) : thresh_(thresh), m_console(console) { @@ -143,13 +413,14 @@ Journal::ScopedStream::ScopedStream( Journal::ScopedStream::~ScopedStream() { - std::string const& s(m_ostream.str()); + std::string s = m_ostream.str(); if (!s.empty()) { if (s == "\n") - m_sink.write(m_level, ""); - else - m_sink.write(m_level, s); + s = ""; + + m_sink.write(m_level, formatLog(s)); + currentJsonLogContext_.finish(); } } @@ -159,12 +430,4 @@ Journal::ScopedStream::operator<<(std::ostream& manip(std::ostream&)) const return m_ostream << manip; } -//------------------------------------------------------------------------------ - -Journal::ScopedStream -Journal::Stream::operator<<(std::ostream& manip(std::ostream&)) const -{ - return ScopedStream(*this, manip); -} - } // namespace beast diff --git a/src/test/csf/Peer.h b/src/test/csf/Peer.h index 1cb2d03cc6d..6785846b0f4 100644 --- a/src/test/csf/Peer.h +++ b/src/test/csf/Peer.h @@ -178,7 +178,6 @@ struct Peer using NodeKey = Validation::NodeKey; //! Logging support that prefixes messages with the peer ID - beast::WrappedSink sink; beast::Journal j; //! Generic consensus @@ -284,8 +283,7 @@ struct Peer TrustGraph& tg, CollectorRefs& c, beast::Journal jIn) - : sink(jIn, "Peer " + to_string(i) + ": ") - , j(sink) + : j(jIn, log::attributes(log::attr("Peer", "Peer " + to_string(i)))) , consensus(s.clock(), *this, j) , id{i} , key{id, 0} diff --git a/src/tests/libxrpl/basics/log.cpp b/src/tests/libxrpl/basics/log.cpp new file mode 100644 index 00000000000..47e76d202c8 --- /dev/null +++ b/src/tests/libxrpl/basics/log.cpp @@ -0,0 +1,766 @@ +//------------------------------------------------------------------------------ +/* + This file is part of rippled: https://github.com/ripple/rippled + Copyright (c) 2012 Ripple Labs Inc. + + Permission to use, copy, modify, and/or distribute this software for any + purpose with or without fee is hereby granted, provided that the above + copyright notice and this permission notice appear in all copies. + + THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES + WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF + MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR + ANY SPECIAL , DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES + WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN + ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF + OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE. +*/ +//============================================================================== + +#include + +#include + +#include + +#include +#include + +using namespace ripple; + +class MockLogs : public Logs +{ +private: + class Sink : public beast::Journal::Sink + { + private: + MockLogs& logs_; + std::string partition_; + + public: + Sink( + std::string const& partition, + beast::severities::Severity thresh, + MockLogs& logs) + : beast::Journal::Sink(thresh, false) + , logs_(logs) + , partition_(partition) + { + } + + Sink(Sink const&) = delete; + Sink& + operator=(Sink const&) = delete; + + void + write(beast::severities::Severity level, std::string const& text) + override + { + logs_.write(level, partition_, text, false); + } + + void + writeAlways(beast::severities::Severity level, std::string const& text) + override + { + logs_.write(level, partition_, text, false); + } + }; + + std::string& logStream_; + +public: + MockLogs(std::string& logStream, beast::severities::Severity level) + : Logs(level), logStream_(logStream) + { + } + + std::unique_ptr + makeSink( + std::string const& partition, + beast::severities::Severity startingLevel) override + { + return std::make_unique(partition, startingLevel, *this); + } + + void + write( + beast::severities::Severity level, + std::string const& partition, + std::string const& text, + bool console) + { + std::string s; + std::string_view result = text; + if (!beast::Journal::isStructuredJournalEnabled()) + { + format(s, text, level, partition); + result = s; + } + logStream_.append(result); + } +}; + +TEST_CASE("Text logs") +{ + std::string logStream; + + MockLogs logs{logStream, beast::severities::kAll}; + + logs.journal("Test").debug() << "Test"; + + CHECK(logStream.find("Test") != std::string::npos); + + logStream.clear(); + + logs.journal("Test").debug() << "\n"; + + CHECK(logStream.find("\n") == std::string::npos); +} + +TEST_CASE("Test format output") +{ + std::string output; + Logs::format(output, "Msg", beast::severities::kDebug, "Test"); + CHECK(output.find("Msg") != std::string::npos); + CHECK(output != "Msg"); +} + +TEST_CASE("Enable json logs") +{ + std::string logStream; + + MockLogs logs{logStream, beast::severities::kAll}; + + logs.journal("Test ").debug() << "Test123"; + + CHECK(logStream.find("Test123") != std::string::npos); + + logStream.clear(); + + beast::Journal::enableStructuredJournal(); + + logs.journal("Test").debug() << "\n"; + + boost::system::error_code ec; + auto doc = boost::json::parse(logStream, ec); + CHECK(ec == boost::system::errc::success); + + CHECK(doc.is_object()); + CHECK(doc.as_object().contains("Msg")); + CHECK(doc.as_object()["Msg"].is_string()); + CHECK(doc.as_object()["Msg"].get_string() == ""); + beast::Journal::disableStructuredJournal(); +} + +TEST_CASE("Global attributes") +{ + std::string logStream; + + MockLogs logs{logStream, beast::severities::kAll}; + + beast::Journal::enableStructuredJournal(); + beast::Journal::addGlobalAttributes( + log::attributes(log::attr("Field1", "Value1"))); + + logs.journal("Test").debug() << "Test"; + + boost::system::error_code ec; + auto jsonLog = boost::json::parse(logStream, ec); + CHECK(ec == boost::system::errc::success); + + CHECK(jsonLog.is_object()); + CHECK(jsonLog.as_object().contains("Glb")); + CHECK(jsonLog.as_object()["Glb"].is_object()); + CHECK(jsonLog.as_object()["Glb"].as_object().contains("Field1")); + CHECK(jsonLog.as_object()["Glb"].as_object()["Field1"].is_string()); + CHECK( + jsonLog.as_object()["Glb"].as_object()["Field1"].get_string() == + "Value1"); + beast::Journal::disableStructuredJournal(); +} + +TEST_CASE("Global attributes inheritable") +{ + std::string logStream; + + MockLogs logs{logStream, beast::severities::kAll}; + + beast::Journal::enableStructuredJournal(); + beast::Journal::addGlobalAttributes( + log::attributes(log::attr("Field1", "Value1"))); + + logs.journal( + "Test", + log::attributes( + log::attr("Field1", "Value3"), log::attr("Field2", "Value2"))) + .debug() + << "Test"; + + boost::system::error_code ec; + auto jsonLog = boost::json::parse(logStream, ec); + CHECK(ec == boost::system::errc::success); + + CHECK(jsonLog.is_object()); + CHECK(jsonLog.as_object()["Glb"].as_object().contains("Field1")); + CHECK(jsonLog.as_object()["Glb"].as_object()["Field1"].is_string()); + CHECK( + jsonLog.as_object()["Glb"].as_object()["Field1"].get_string() == + "Value1"); + CHECK( + jsonLog.as_object()["Jnl"].as_object()["Field1"].get_string() == + "Value3"); + CHECK( + jsonLog.as_object()["Jnl"].as_object()["Field2"].get_string() == + "Value2"); + beast::Journal::disableStructuredJournal(); +} + +TEST_CASE("Test JsonWriter") +{ + { + std::string buffer; + beast::detail::SimpleJsonWriter writer{&buffer}; + + writer.writeString("\n\r\t123\b\f123"); + writer.finish(); + CHECK(writer.buffer() == "\"\\n\\r\\t123\\b\\f123\""); + } + + { + std::string buffer; + beast::detail::SimpleJsonWriter writer{&buffer}; + + writer.writeString("\t"); + writer.finish(); + CHECK(writer.buffer() == "\"\\t\""); + } + + { + std::string buffer; + beast::detail::SimpleJsonWriter writer{&buffer}; + + writer.writeString(std::string_view{"\0", 1}); + writer.finish(); + CHECK(writer.buffer() == "\"\\u0000\""); + } + + { + std::string buffer; + beast::detail::SimpleJsonWriter writer{&buffer}; + + writer.writeString("\"\\"); + writer.finish(); + CHECK(writer.buffer() == "\"\\\"\\\\\""); + } + + { + std::string buffer; + beast::detail::SimpleJsonWriter writer{&buffer}; + + writer.startArray(); + writer.writeBool(true); + writer.writeBool(false); + writer.writeNull(); + writer.endArray(); + writer.finish(); + CHECK(writer.buffer() == "[true,false,null]"); + } +} + +namespace test_detail { +struct ToCharsStruct +{ +}; + +std::to_chars_result +to_chars(char* first, char* last, ToCharsStruct) +{ + *first = '0'; + return std::to_chars_result{first + 1, std::errc{}}; +} + +struct StreamStruct +{ +}; + +std::ostream& +operator<<(std::ostream& os, StreamStruct) +{ + os << "0"; + return os; +} + +} // namespace test_detail + +TEST_CASE("Test setJsonValue") +{ + std::ostringstream stringBuf; + std::string buffer; + beast::detail::SimpleJsonWriter writer{&buffer}; + writer.startObject(); + + log::detail::setJsonValue(writer, "testBool", true, &stringBuf); + log::detail::setJsonValue( + writer, "testInt32", -1, &stringBuf); + log::detail::setJsonValue( + writer, "testUInt32", 1, &stringBuf); + log::detail::setJsonValue( + writer, "testInt64", -1, &stringBuf); + log::detail::setJsonValue( + writer, "testUInt64", 1, &stringBuf); + log::detail::setJsonValue(writer, "testDouble", 1.1, &stringBuf); + log::detail::setJsonValue( + writer, "testCharStar", "Char*", &stringBuf); + log::detail::setJsonValue( + writer, "testStdString", "StdString", &stringBuf); + log::detail::setJsonValue( + writer, "testStdStringView", "StdStringView", &stringBuf); + log::detail::setJsonValue( + writer, "testToChars", {}, &stringBuf); + log::detail::setJsonValue( + writer, "testStream", {}, &stringBuf); + writer.endObject(); + writer.finish(); + + CHECK( + writer.buffer() == + R"AAA({"testBool":true,"testInt32":-1,"testUInt32":1,"testInt64":-1,"testUInt64":1,"testDouble":1.1,"testCharStar":"Char*","testStdString":"StdString","testStdStringView":"StdStringView","testToChars":"0","testStream":"0"})AAA"); +} + +TEST_CASE("Test json logging not enabled") +{ + std::string logStream; + + MockLogs logs{logStream, beast::severities::kAll}; + + beast::Journal::disableStructuredJournal(); + beast::Journal::addGlobalAttributes( + log::attributes(log::attr("Field1", "Value1"))); + + logs.journal("Test123").debug() + << "Test " << log::param(" Field1", "Value1") + << log::field("Field2", "Value2"); + + CHECK(logStream.find("Test Value1") != std::string::npos); +} + +/** + * @brief sink for writing all log messages to a stringstream + */ +class MockSink : public beast::Journal::Sink +{ + std::stringstream& strm_; + +public: + MockSink(beast::severities::Severity threshold, std::stringstream& strm) + : beast::Journal::Sink(threshold, false), strm_(strm) + { + } + + void + write(beast::severities::Severity level, std::string const& text) override + { + strm_ << text; + } + + void + writeAlways(beast::severities::Severity level, std::string const& text) + override + { + strm_ << text; + } +}; + +class JsonLogStreamFixture +{ +public: + JsonLogStreamFixture() + : sink_(beast::severities::kAll, logStream_) + , j_(beast::Journal::getNullSink()) + { + beast::Journal::resetGlobalAttributes(); + beast::Journal::enableStructuredJournal(); + j_ = beast::Journal{ + sink_, "Test", log::attributes(log::attr("Field1", "Value1"))}; + } + + ~JsonLogStreamFixture() + { + beast::Journal::disableStructuredJournal(); + } + + std::stringstream& + stream() + { + return logStream_; + } + + beast::Journal& + journal() + { + return j_; + } + +private: + MockSink sink_; + std::stringstream logStream_; + beast::Journal j_; +}; + +TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test json log fields") +{ + beast::Journal::addGlobalAttributes( + log::attributes(log::attr("Field2", "Value2"))); + journal().debug() << std::boolalpha << true << std::noboolalpha << " Test " + << std::boolalpha << false + << log::field("Field3", "Value3"); + + boost::system::error_code ec; + auto logValue = boost::json::parse(stream().str(), ec); + CHECK(ec == boost::system::errc::success); + + CHECK(logValue.is_object()); + CHECK(logValue.as_object().contains("Glb")); + CHECK(logValue.as_object().contains("Jnl")); + CHECK(logValue.as_object().contains("Mtd")); + CHECK(logValue.as_object().contains("Msg")); + + CHECK(logValue.as_object()["Glb"].is_object()); + CHECK(logValue.as_object()["Jnl"].is_object()); + CHECK(logValue.as_object()["Mtd"].is_object()); + CHECK(logValue.as_object()["Msg"].is_string()); + + CHECK(logValue.as_object()["Mtd"].as_object().contains("Fl")); + CHECK(logValue.as_object()["Mtd"].as_object().contains("Ln")); + CHECK(logValue.as_object()["Mtd"].as_object().contains("ThId")); + CHECK(logValue.as_object()["Mtd"].as_object().contains("Lv")); + CHECK(logValue.as_object()["Mtd"].as_object().contains("Tm")); + + CHECK(logValue.as_object()["Mtd"].as_object()["Fl"].is_string()); + CHECK(logValue.as_object()["Mtd"].as_object()["Ln"].is_number()); + + CHECK( + logValue.as_object()["Msg"].get_string() == + std::string{"true Test false"}); +} + +TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test json log levels") +{ + { + stream().str(""); + journal().trace() << "Test"; + + boost::system::error_code ec; + auto logValue = boost::json::parse(stream().str(), ec); + CHECK(ec == boost::system::errc::success); + + CHECK( + logValue.as_object()["Mtd"].as_object()["Lv"].get_string() == + beast::severities::to_string(beast::severities::kTrace)); + } + + { + stream().str(""); + journal().debug() << "Test"; + + boost::system::error_code ec; + auto logValue = boost::json::parse(stream().str(), ec); + CHECK(ec == boost::system::errc::success); + + CHECK( + logValue.as_object()["Mtd"].as_object()["Lv"].get_string() == + beast::severities::to_string(beast::severities::kDebug)); + } + + { + stream().str(""); + journal().info() << "Test"; + + boost::system::error_code ec; + auto logValue = boost::json::parse(stream().str(), ec); + CHECK(ec == boost::system::errc::success); + + CHECK( + logValue.as_object()["Mtd"].as_object()["Lv"].get_string() == + beast::severities::to_string(beast::severities::kInfo)); + } + + { + stream().str(""); + journal().warn() << "Test"; + + boost::system::error_code ec; + auto logValue = boost::json::parse(stream().str(), ec); + CHECK(ec == boost::system::errc::success); + + CHECK( + logValue.as_object()["Mtd"].as_object()["Lv"].get_string() == + beast::severities::to_string(beast::severities::kWarning)); + } + + { + stream().str(""); + journal().error() << "Test"; + + boost::system::error_code ec; + auto logValue = boost::json::parse(stream().str(), ec); + CHECK(ec == boost::system::errc::success); + + CHECK( + logValue.as_object()["Mtd"].as_object()["Lv"].get_string() == + beast::severities::to_string(beast::severities::kError)); + } + + { + stream().str(""); + journal().fatal() << "Test"; + + boost::system::error_code ec; + auto logValue = boost::json::parse(stream().str(), ec); + CHECK(ec == boost::system::errc::success); + + CHECK( + logValue.as_object()["Mtd"].as_object()["Lv"].get_string() == + beast::severities::to_string(beast::severities::kFatal)); + } +} + +TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test json log stream") +{ + journal().stream(beast::severities::kError) << "Test"; + + boost::system::error_code ec; + auto logValue = boost::json::parse(stream().str(), ec); + CHECK(ec == boost::system::errc::success); + + CHECK( + logValue.as_object()["Mtd"].as_object()["Lv"].get_string() == + beast::severities::to_string(beast::severities::kError)); +} + +TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test json log params") +{ + journal().debug() << "Test: " << log::param("Field1", 1) << ", " + << log::param( + "Field2", + std::numeric_limits::max()) + << ", " << log::param("Field3", std::numbers::pi); + + boost::system::error_code ec; + auto logValue = boost::json::parse(stream().str(), ec); + CHECK(ec == boost::system::errc::success); + + CHECK(logValue.as_object()["Dt"].is_object()); + CHECK(logValue.as_object()["Dt"].as_object()["Field1"].is_number()); + CHECK(logValue.as_object()["Dt"].as_object()["Field1"].get_int64() == 1); + CHECK(logValue.as_object()["Dt"].as_object()["Field2"].is_number()); + CHECK( + logValue.as_object()["Dt"].as_object()["Field2"].get_uint64() == + std::numeric_limits::max()); + auto field3Val = + logValue.as_object()["Dt"].as_object()["Field3"].get_double(); + auto difference = std::abs(field3Val - std::numbers::pi); + CHECK(difference < 1e-4); + CHECK(logValue.as_object()["Msg"].is_string()); + CHECK( + logValue.as_object()["Msg"].get_string() == + std::string{"Test: 1, 18446744073709551615, 3.141592653589793"}); +} + +TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test json log fields") +{ + journal().debug() << "Test" << log::field("Field1", 1) + << log::field( + "Field2", + std::numeric_limits::max()); + + boost::system::error_code ec; + auto logValue = boost::json::parse(stream().str(), ec); + CHECK(ec == boost::system::errc::success); + + CHECK(logValue.as_object()["Dt"].is_object()); + CHECK(logValue.as_object()["Dt"].as_object()["Field1"].is_number()); + CHECK(logValue.as_object()["Dt"].as_object()["Field1"].get_int64() == 1); + // UInt64 doesn't fit in Json::Value so it should be converted to a string + // NOTE: We should expect it to be an int64 after we make the json library + // support in64 and uint64 + CHECK(logValue.as_object()["Dt"].as_object()["Field2"].is_number()); + CHECK( + logValue.as_object()["Dt"].as_object()["Field2"].get_uint64() == + std::numeric_limits::max()); + CHECK(logValue.as_object()["Msg"].is_string()); + CHECK(logValue.as_object()["Msg"].get_string() == "Test"); +} + +TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test journal attributes") +{ + beast::Journal j{ + journal(), + log::attributes(log::attr("Field1", "Value1"), log::attr("Field2", 2))}; + + j.debug() << "Test"; + + boost::system::error_code ec; + auto logValue = boost::json::parse(stream().str(), ec); + CHECK(ec == boost::system::errc::success); + + CHECK(logValue.as_object()["Jnl"].as_object()["Field1"].is_string()); + CHECK( + logValue.as_object()["Jnl"].as_object()["Field1"].get_string() == + std::string{"Value1"}); + CHECK(logValue.as_object()["Jnl"].as_object()["Field2"].is_number()); + CHECK(logValue.as_object()["Jnl"].as_object()["Field2"].get_int64() == 2); +} + +TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test journal attributes inheritable") +{ + beast::Journal j{ + journal(), + log::attributes(log::attr("Field1", "Value1"), log::attr("Field2", 2))}; + beast::Journal j2{j, log::attributes(log::attr("Field3", "Value3"))}; + + j2.debug() << "Test"; + + boost::system::error_code ec; + auto logValue = boost::json::parse(stream().str(), ec); + CHECK(ec == boost::system::errc::success); + + CHECK(logValue.as_object()["Jnl"].as_object()["Field1"].is_string()); + CHECK( + logValue.as_object()["Jnl"].as_object()["Field1"].get_string() == + std::string{"Value1"}); + CHECK(logValue.as_object()["Jnl"].as_object()["Field3"].is_string()); + CHECK( + logValue.as_object()["Jnl"].as_object()["Field3"].get_string() == + std::string{"Value3"}); + CHECK(logValue.as_object()["Jnl"].as_object()["Field2"].is_number()); + CHECK(logValue.as_object()["Jnl"].as_object()["Field2"].get_int64() == 2); +} + +TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test copying journal") +{ + { + beast::Journal j{ + journal(), + log::attributes( + log::attr("Field1", "Value1"), log::attr("Field2", 2))}; + beast::Journal j2{j}; + + j2.debug() << "Test"; + + boost::system::error_code ec; + auto logValue = boost::json::parse(stream().str(), ec); + CHECK(ec == boost::system::errc::success); + + CHECK(logValue.as_object()["Jnl"].as_object()["Field1"].is_string()); + CHECK( + logValue.as_object()["Jnl"].as_object()["Field1"].get_string() == + std::string{"Value1"}); + CHECK(logValue.as_object()["Jnl"].as_object()["Field2"].is_number()); + CHECK( + logValue.as_object()["Jnl"].as_object()["Field2"].get_int64() == 2); + } + { + stream().str(""); + beast::Journal j{journal().sink()}; + beast::Journal j2{ + j, + log::attributes( + log::attr("Field1", "Value1"), log::attr("Field2", 2))}; + + j2.debug() << "Test"; + + boost::system::error_code ec; + auto logValue = boost::json::parse(stream().str(), ec); + CHECK(ec == boost::system::errc::success); + + CHECK(logValue.as_object()["Jnl"].as_object()["Field1"].is_string()); + CHECK( + logValue.as_object()["Jnl"].as_object()["Field1"].get_string() == + std::string{"Value1"}); + CHECK(logValue.as_object()["Jnl"].as_object()["Field2"].is_number()); + CHECK( + logValue.as_object()["Jnl"].as_object()["Field2"].get_int64() == 2); + } +} + +TEST_CASE_FIXTURE( + JsonLogStreamFixture, + "Test journal attributes inheritable after moving") +{ + beast::Journal j{ + journal(), + log::attributes(log::attr("Field1", "Value1"), log::attr("Field2", 2))}; + beast::Journal j2{j, log::attributes(log::attr("Field3", "Value3"))}; + + j2.debug() << "Test"; + + boost::system::error_code ec; + auto logValue = boost::json::parse(stream().str(), ec); + CHECK(ec == boost::system::errc::success); + + CHECK(logValue.as_object()["Jnl"].as_object()["Field1"].is_string()); + CHECK( + logValue.as_object()["Jnl"].as_object()["Field1"].get_string() == + std::string{"Value1"}); + CHECK(logValue.as_object()["Jnl"].as_object()["Field3"].is_string()); + CHECK( + logValue.as_object()["Jnl"].as_object()["Field3"].get_string() == + std::string{"Value3"}); + // Field2 should be overwritten to 0 + CHECK(logValue.as_object()["Jnl"].as_object()["Field2"].is_number()); + CHECK(logValue.as_object()["Jnl"].as_object()["Field2"].get_int64() == 2); +} + +TEST_CASE_FIXTURE( + JsonLogStreamFixture, + "Test journal attributes inheritable after copy assignment") +{ + beast::Journal j{ + std::move(journal()), + log::attributes(log::attr("Field1", "Value1"), log::attr("Field2", 2))}; + + beast::Journal j2{beast::Journal::getNullSink()}; + + j2 = j; + + j2.debug() << "Test"; + + boost::system::error_code ec; + auto logValue = boost::json::parse(stream().str(), ec); + CHECK(ec == boost::system::errc::success); + + CHECK(logValue.as_object()["Jnl"].as_object()["Field1"].is_string()); + CHECK( + logValue.as_object()["Jnl"].as_object()["Field1"].get_string() == + std::string{"Value1"}); + CHECK(logValue.as_object()["Jnl"].as_object()["Field2"].is_number()); + CHECK(logValue.as_object()["Jnl"].as_object()["Field2"].get_int64() == 2); +} + +TEST_CASE_FIXTURE( + JsonLogStreamFixture, + "Test journal attributes inheritable after move assignment") +{ + beast::Journal j{ + journal(), + log::attributes(log::attr("Field1", "Value1"), log::attr("Field2", 2))}; + + beast::Journal j2{beast::Journal::getNullSink()}; + + j2 = std::move(j); + + j2.debug() << "Test"; + + boost::system::error_code ec; + auto logValue = boost::json::parse(stream().str(), ec); + CHECK(ec == boost::system::errc::success); + + CHECK(logValue.as_object()["Jnl"].as_object()["Field1"].is_string()); + CHECK( + logValue.as_object()["Jnl"].as_object()["Field1"].get_string() == + std::string{"Value1"}); + CHECK(logValue.as_object()["Jnl"].as_object()["Field2"].is_number()); + CHECK(logValue.as_object()["Jnl"].as_object()["Field2"].get_int64() == 2); +} diff --git a/src/xrpld/app/consensus/RCLConsensus.cpp b/src/xrpld/app/consensus/RCLConsensus.cpp index 292ba7d483d..d3485239d1d 100644 --- a/src/xrpld/app/consensus/RCLConsensus.cpp +++ b/src/xrpld/app/consensus/RCLConsensus.cpp @@ -1129,7 +1129,25 @@ RclConsensusLogger::~RclConsensusLogger() outSs << header_ << "duration " << (duration.count() / 1000) << '.' << std::setw(3) << std::setfill('0') << (duration.count() % 1000) << "s. " << ss_->str(); - j_.sink().writeAlways(beast::severities::kInfo, outSs.str()); + + thread_local std::string buffer; + if (beast::Journal::isStructuredJournalEnabled()) + { + buffer.resize(5 * 1024); + beast::detail::SimpleJsonWriter writer{&buffer}; + writer.startObject(); + writer.writeKey("Msg"); + writer.writeString(outSs.str()); + writer.writeKey("Tm"); + writer.writeString(to_string(std::chrono::system_clock::now())); + writer.endObject(); + writer.finish(); + } + else + { + buffer = outSs.str(); + } + j_.sink().writeAlways(beast::severities::kInfo, buffer); } } // namespace ripple diff --git a/src/xrpld/app/main/Application.cpp b/src/xrpld/app/main/Application.cpp index 05b8f5e5fab..397261f4178 100644 --- a/src/xrpld/app/main/Application.cpp +++ b/src/xrpld/app/main/Application.cpp @@ -831,9 +831,6 @@ class ApplicationImp : public Application, public BasicApp bool serverOkay(std::string& reason) override; - beast::Journal - journal(std::string const& name) override; - //-------------------------------------------------------------------------- bool @@ -1210,8 +1207,11 @@ ApplicationImp::setup(boost::program_options::variables_map const& cmdline) } JLOG(m_journal.info()) << "Process starting: " - << BuildInfo::getFullVersionString() - << ", Instance Cookie: " << instanceCookie_; + << log::param( + "RippledVersion", + BuildInfo::getFullVersionString()) + << ", Instance Cookie: " + << log::param("InstanceCookie", instanceCookie_); if (numberOfThreads(*config_) < 2) { @@ -2162,12 +2162,6 @@ ApplicationImp::serverOkay(std::string& reason) return true; } -beast::Journal -ApplicationImp::journal(std::string const& name) -{ - return logs_->journal(name); -} - void ApplicationImp::setMaxDisallowedLedger() { diff --git a/src/xrpld/app/main/Application.h b/src/xrpld/app/main/Application.h index b3a433fee8d..474982bddfd 100644 --- a/src/xrpld/app/main/Application.h +++ b/src/xrpld/app/main/Application.h @@ -257,8 +257,18 @@ class Application : public beast::PropertyStream::Source virtual bool serverOkay(std::string& reason) = 0; - virtual beast::Journal - journal(std::string const& name) = 0; + template + beast::Journal + journal(std::string const& name, TAttributesFactory&& factory) + { + return logs().journal(name, std::forward(factory)); + } + + beast::Journal + journal(std::string const& name) + { + return logs().journal(name); + } /* Returns the number of file descriptors the application needs */ virtual int diff --git a/src/xrpld/app/main/Main.cpp b/src/xrpld/app/main/Main.cpp index 2353d7acd1d..115bb792674 100644 --- a/src/xrpld/app/main/Main.cpp +++ b/src/xrpld/app/main/Main.cpp @@ -794,6 +794,11 @@ run(int argc, char** argv) else if (vm.count("verbose")) thresh = kTrace; + if (config->LOG_STYLE == LogStyle::Json) + { + beast::Journal::enableStructuredJournal(); + } + auto logs = std::make_unique(thresh); // No arguments. Run server. diff --git a/src/xrpld/app/paths/Flow.cpp b/src/xrpld/app/paths/Flow.cpp index 3b14b8b968d..e6ce4d359ea 100644 --- a/src/xrpld/app/paths/Flow.cpp +++ b/src/xrpld/app/paths/Flow.cpp @@ -111,19 +111,22 @@ flow( ammContext.setMultiPath(strands.size() > 1); - if (j.trace()) + if (auto stream = j.trace()) { - j.trace() << "\nsrc: " << src << "\ndst: " << dst - << "\nsrcIssue: " << srcIssue << "\ndstIssue: " << dstIssue; - j.trace() << "\nNumStrands: " << strands.size(); + std::stringstream ss; + ss << "\nsrc: " << src << "\ndst: " << dst << "\nsrcIssue: " << srcIssue + << "\ndstIssue: " << dstIssue; + ss << "\nNumStrands: " << strands.size(); for (auto const& curStrand : strands) { - j.trace() << "NumSteps: " << curStrand.size(); + ss << "NumSteps: " << curStrand.size(); for (auto const& step : curStrand) { - j.trace() << '\n' << *step << '\n'; + ss << '\n' << *step << '\n'; } } + + std::move(stream) << ss.str(); } bool const srcIsXRP = isXRP(srcIssue.currency); diff --git a/src/xrpld/app/rdb/backend/detail/Node.cpp b/src/xrpld/app/rdb/backend/detail/Node.cpp index 6a0544091b4..4e542988f6d 100644 --- a/src/xrpld/app/rdb/backend/detail/Node.cpp +++ b/src/xrpld/app/rdb/backend/detail/Node.cpp @@ -565,8 +565,7 @@ getHashesByIndex( if (!lhO || !phO) { - auto stream = j.trace(); - JLOG(stream) << "Don't have ledger " << ledgerIndex; + JLOG(j.trace()) << "Don't have ledger " << ledgerIndex; return {}; } diff --git a/src/xrpld/app/tx/detail/Transactor.cpp b/src/xrpld/app/tx/detail/Transactor.cpp index fd396e45560..8f881d7252f 100644 --- a/src/xrpld/app/tx/detail/Transactor.cpp +++ b/src/xrpld/app/tx/detail/Transactor.cpp @@ -206,10 +206,7 @@ preflight2(PreflightContext const& ctx) //------------------------------------------------------------------------------ Transactor::Transactor(ApplyContext& ctx) - : ctx_(ctx) - , sink_(ctx.journal, to_short_string(ctx.tx.getTransactionID()) + " ") - , j_(sink_) - , account_(ctx.tx.getAccountID(sfAccount)) + : ctx_(ctx), j_(ctx.journal), account_(ctx.tx.getAccountID(sfAccount)) { } diff --git a/src/xrpld/app/tx/detail/Transactor.h b/src/xrpld/app/tx/detail/Transactor.h index e94b93523da..fc58a50b844 100644 --- a/src/xrpld/app/tx/detail/Transactor.h +++ b/src/xrpld/app/tx/detail/Transactor.h @@ -139,7 +139,6 @@ class Transactor { protected: ApplyContext& ctx_; - beast::WrappedSink sink_; beast::Journal const j_; AccountID const account_; diff --git a/src/xrpld/core/Config.h b/src/xrpld/core/Config.h index a58867958b1..d155976d7e2 100644 --- a/src/xrpld/core/Config.h +++ b/src/xrpld/core/Config.h @@ -77,6 +77,16 @@ struct FeeSetup * values.) */ }; +/** + * We support producing plain text logs and structured json logs. + */ +namespace LogStyle { +enum LogStyle { LogFmt, Json }; + +LogStyle +fromString(std::string const&); +}; // namespace LogStyle + // This entire derived class is deprecated. // For new config information use the style implied // in the base class. For existing config information @@ -299,6 +309,9 @@ class Config : public BasicConfig std::optional VALIDATOR_LIST_THRESHOLD; + // Set it to LogStyle::Json to get structured json logs. + LogStyle::LogStyle LOG_STYLE = LogStyle::LogFmt; + public: Config(); diff --git a/src/xrpld/core/ConfigSections.h b/src/xrpld/core/ConfigSections.h index 59af2bcf67b..b896cf8c31e 100644 --- a/src/xrpld/core/ConfigSections.h +++ b/src/xrpld/core/ConfigSections.h @@ -48,6 +48,7 @@ struct ConfigSection #define SECTION_CLUSTER_NODES "cluster_nodes" #define SECTION_COMPRESSION "compression" #define SECTION_DEBUG_LOGFILE "debug_logfile" +#define SECTION_LOG_STYLE "log_style" #define SECTION_ELB_SUPPORT "elb_support" #define SECTION_FEE_DEFAULT "fee_default" #define SECTION_FETCH_DEPTH "fetch_depth" diff --git a/src/xrpld/core/detail/Config.cpp b/src/xrpld/core/detail/Config.cpp index 95147e23d5f..7eb3a68a46d 100644 --- a/src/xrpld/core/detail/Config.cpp +++ b/src/xrpld/core/detail/Config.cpp @@ -690,6 +690,9 @@ Config::loadFromString(std::string const& fileContents) if (getSingleSection(secConfig, SECTION_DEBUG_LOGFILE, strTemp, j_)) DEBUG_LOGFILE = strTemp; + if (getSingleSection(secConfig, SECTION_LOG_STYLE, strTemp, j_)) + LOG_STYLE = LogStyle::fromString(strTemp); + if (getSingleSection(secConfig, SECTION_SWEEP_INTERVAL, strTemp, j_)) { SWEEP_INTERVAL = beast::lexicalCastThrow(strTemp); @@ -1078,6 +1081,14 @@ Config::loadFromString(std::string const& fileContents) } } +LogStyle::LogStyle +LogStyle::fromString(std::string const& str) +{ + if (str == "json") + return Json; + return LogFmt; +} + boost::filesystem::path Config::getDebugLogFile() const { diff --git a/src/xrpld/overlay/Slot.h b/src/xrpld/overlay/Slot.h index ea9fc3285ba..88afb040753 100644 --- a/src/xrpld/overlay/Slot.h +++ b/src/xrpld/overlay/Slot.h @@ -406,7 +406,7 @@ Slot::update( v.state = PeerState::Selected; else if (v.state != PeerState::Squelched) { - if (journal_.trace()) + if (journal_.active(beast::severities::kTrace)) str << k << " "; v.state = PeerState::Squelched; std::chrono::seconds duration = diff --git a/src/xrpld/overlay/detail/ConnectAttempt.cpp b/src/xrpld/overlay/detail/ConnectAttempt.cpp index c1bc4bb069e..4764c063319 100644 --- a/src/xrpld/overlay/detail/ConnectAttempt.cpp +++ b/src/xrpld/overlay/detail/ConnectAttempt.cpp @@ -41,8 +41,7 @@ ConnectAttempt::ConnectAttempt( : Child(overlay) , app_(app) , id_(id) - , sink_(journal, OverlayImpl::makePrefix(id)) - , journal_(sink_) + , journal_(journal, log::attributes(log::attr("NodeID", id))) , remote_endpoint_(remote_endpoint) , usage_(usage) , strand_(boost::asio::make_strand(io_context)) diff --git a/src/xrpld/overlay/detail/ConnectAttempt.h b/src/xrpld/overlay/detail/ConnectAttempt.h index 38b9482d9d9..24fbbb56cf3 100644 --- a/src/xrpld/overlay/detail/ConnectAttempt.h +++ b/src/xrpld/overlay/detail/ConnectAttempt.h @@ -117,7 +117,6 @@ class ConnectAttempt : public OverlayImpl::Child, // Core application and networking components Application& app_; Peer::id_t const id_; - beast::WrappedSink sink_; beast::Journal const journal_; endpoint_type remote_endpoint_; Resource::Consumer usage_; diff --git a/src/xrpld/overlay/detail/OverlayImpl.cpp b/src/xrpld/overlay/detail/OverlayImpl.cpp index 8d295faace7..ad7e5f3897e 100644 --- a/src/xrpld/overlay/detail/OverlayImpl.cpp +++ b/src/xrpld/overlay/detail/OverlayImpl.cpp @@ -168,8 +168,8 @@ OverlayImpl::onHandoff( endpoint_type remote_endpoint) { auto const id = next_id_++; - beast::WrappedSink sink(app_.logs()["Peer"], makePrefix(id)); - beast::Journal journal(sink); + auto journal = + app_.journal("Peer", log::attributes(log::attr("NodeID", id))); Handoff handoff; if (processRequest(request, handoff)) @@ -337,14 +337,6 @@ OverlayImpl::isPeerUpgrade(http_request_type const& request) return !versions.empty(); } -std::string -OverlayImpl::makePrefix(std::uint32_t id) -{ - std::stringstream ss; - ss << "[" << std::setfill('0') << std::setw(3) << id << "] "; - return ss.str(); -} - std::shared_ptr OverlayImpl::makeRedirectResponse( std::shared_ptr const& slot, diff --git a/src/xrpld/overlay/detail/OverlayImpl.h b/src/xrpld/overlay/detail/OverlayImpl.h index b4ea3307ec7..b8ef7f3fa09 100644 --- a/src/xrpld/overlay/detail/OverlayImpl.h +++ b/src/xrpld/overlay/detail/OverlayImpl.h @@ -344,9 +344,6 @@ class OverlayImpl : public Overlay, public reduce_relay::SquelchHandler return true; } - static std::string - makePrefix(std::uint32_t id); - void reportInboundTraffic(TrafficCount::category cat, int bytes); diff --git a/src/xrpld/overlay/detail/PeerImp.cpp b/src/xrpld/overlay/detail/PeerImp.cpp index 93371f42abb..988cbc2cae4 100644 --- a/src/xrpld/overlay/detail/PeerImp.cpp +++ b/src/xrpld/overlay/detail/PeerImp.cpp @@ -82,10 +82,22 @@ PeerImp::PeerImp( : Child(overlay) , app_(app) , id_(id) - , sink_(app_.journal("Peer"), makePrefix(id)) - , p_sink_(app_.journal("Protocol"), makePrefix(id)) - , journal_(sink_) - , p_journal_(p_sink_) + , journal_( + app_.journal("Peer"), + log::attributes( + log::attr("NodeID", id), + log::attr("RemoteAddress", to_string(slot->remote_endpoint())), + log::attr( + "PublicKey", + toBase58(TokenType::NodePublic, publicKey)))) + , p_journal_( + app_.journal("Protocol"), + log::attributes( + log::attr("NodeID", id), + log::attr("RemoteAddress", to_string(slot->remote_endpoint())), + log::attr( + "PublicKey", + toBase58(TokenType::NodePublic, publicKey)))) , stream_ptr_(std::move(stream_ptr)) , socket_(stream_ptr_->next_layer().socket()) , stream_(*stream_ptr_) @@ -810,14 +822,6 @@ PeerImp::cancelTimer() noexcept } } -std::string -PeerImp::makePrefix(id_t id) -{ - std::stringstream ss; - ss << "[" << std::setfill('0') << std::setw(3) << id << "] "; - return ss.str(); -} - //------------------------------------------------------------------------------ void PeerImp::doAccept() @@ -981,10 +985,10 @@ PeerImp::onReadMessage(error_code ec, std::size_t bytes_transferred) if (auto stream = journal_.trace()) { - stream << "onReadMessage: " - << (bytes_transferred > 0 - ? to_string(bytes_transferred) + " bytes" - : ""); + std::move(stream) << "onReadMessage: " + << (bytes_transferred > 0 + ? to_string(bytes_transferred) + " bytes" + : ""); } metrics_.recv.add_message(bytes_transferred); @@ -1063,10 +1067,10 @@ PeerImp::onWriteMessage(error_code ec, std::size_t bytes_transferred) if (auto stream = journal_.trace()) { - stream << "onWriteMessage: " - << (bytes_transferred > 0 - ? to_string(bytes_transferred) + " bytes" - : ""); + std::move(stream) << "onWriteMessage: " + << (bytes_transferred > 0 + ? to_string(bytes_transferred) + " bytes" + : ""); } metrics_.sent.add_message(bytes_transferred); diff --git a/src/xrpld/overlay/detail/PeerImp.h b/src/xrpld/overlay/detail/PeerImp.h index c2221c136db..7e8f96368b5 100644 --- a/src/xrpld/overlay/detail/PeerImp.h +++ b/src/xrpld/overlay/detail/PeerImp.h @@ -134,8 +134,6 @@ class PeerImp : public Peer, Application& app_; id_t const id_; - beast::WrappedSink sink_; - beast::WrappedSink p_sink_; beast::Journal const journal_; beast::Journal const p_journal_; std::unique_ptr stream_ptr_; @@ -634,9 +632,6 @@ class PeerImp : public Peer, void cancelTimer() noexcept; - static std::string - makePrefix(id_t id); - void doAccept(); @@ -832,10 +827,22 @@ PeerImp::PeerImp( : Child(overlay) , app_(app) , id_(id) - , sink_(app_.journal("Peer"), makePrefix(id)) - , p_sink_(app_.journal("Protocol"), makePrefix(id)) - , journal_(sink_) - , p_journal_(p_sink_) + , journal_( + app_.journal("Peer"), + log::attributes( + log::attr("NodeID", id), + log::attr("RemoteAddress", to_string(slot->remote_endpoint())), + log::attr( + "PublicKey", + toBase58(TokenType::NodePublic, publicKey)))) + , p_journal_( + app_.journal("Protocol"), + log::attributes( + log::attr("NodeID", id), + log::attr("RemoteAddress", to_string(slot->remote_endpoint())), + log::attr( + "PublicKey", + toBase58(TokenType::NodePublic, publicKey)))) , stream_ptr_(std::move(stream_ptr)) , socket_(stream_ptr_->next_layer().socket()) , stream_(*stream_ptr_) diff --git a/src/xrpld/shamap/detail/SHAMap.cpp b/src/xrpld/shamap/detail/SHAMap.cpp index d2415a2ff24..3f6cb7c7ea9 100644 --- a/src/xrpld/shamap/detail/SHAMap.cpp +++ b/src/xrpld/shamap/detail/SHAMap.cpp @@ -950,15 +950,15 @@ SHAMap::fetchRoot(SHAMapHash const& hash, SHAMapSyncFilter* filter) { if (type_ == SHAMapType::TRANSACTION) { - stream << "Fetch root TXN node " << hash; + std::move(stream) << "Fetch root TXN node " << hash; } else if (type_ == SHAMapType::STATE) { - stream << "Fetch root STATE node " << hash; + std::move(stream) << "Fetch root STATE node " << hash; } else { - stream << "Fetch root SHAMap node " << hash; + std::move(stream) << "Fetch root SHAMap node " << hash; } }