diff options
author | Andy Getzendanner <durandal@google.com> | 2022-11-17 12:17:17 -0800 |
---|---|---|
committer | Copybara-Service <copybara-worker@google.com> | 2022-11-17 12:18:03 -0800 |
commit | ebab79b5783b3298ee2f31251174c660c322d7ef (patch) | |
tree | 1b5309a16ca6e3c871b9df96d10a036f73cdc3eb /absl | |
parent | 0c048353d2e7347f148228d785c3f0a8c81e2223 (diff) |
Release structured logging.
This stores the operands to LOG (and CHECK) as separate fields in a serialized protobuf. The protobuf format is not yet published.
PiperOrigin-RevId: 489275799
Change-Id: I86d83671a6b1feb2bddd5bee51552907897ca8eb
Diffstat (limited to 'absl')
-rw-r--r-- | absl/log/BUILD.bazel | 29 | ||||
-rw-r--r-- | absl/log/CMakeLists.txt | 73 | ||||
-rw-r--r-- | absl/log/internal/BUILD.bazel | 40 | ||||
-rw-r--r-- | absl/log/internal/log_message.cc | 286 | ||||
-rw-r--r-- | absl/log/internal/log_message.h | 70 | ||||
-rw-r--r-- | absl/log/internal/proto.cc | 214 | ||||
-rw-r--r-- | absl/log/internal/proto.h | 267 | ||||
-rw-r--r-- | absl/log/internal/structured.h | 57 | ||||
-rw-r--r-- | absl/log/internal/test_actions.cc | 23 | ||||
-rw-r--r-- | absl/log/internal/test_matchers.h | 1 | ||||
-rw-r--r-- | absl/log/log_entry.h | 10 | ||||
-rw-r--r-- | absl/log/log_format_test.cc | 73 | ||||
-rw-r--r-- | absl/log/structured.h | 70 | ||||
-rw-r--r-- | absl/log/structured_test.cc | 63 |
14 files changed, 1097 insertions, 179 deletions
diff --git a/absl/log/BUILD.bazel b/absl/log/BUILD.bazel index 3e9d1421..733b0c3f 100644 --- a/absl/log/BUILD.bazel +++ b/absl/log/BUILD.bazel @@ -196,6 +196,18 @@ cc_library( ], ) +cc_library( + name = "structured", + hdrs = ["structured.h"], + copts = ABSL_DEFAULT_COPTS, + linkopts = ABSL_DEFAULT_LINKOPTS, + deps = [ + "//absl/base:config", + "//absl/log/internal:structured", + "//absl/strings", + ], +) + # Test targets cc_test( name = "basic_log_test", @@ -458,6 +470,23 @@ cc_test( ], ) +cc_test( + name = "structured_test", + size = "small", + srcs = ["structured_test.cc"], + copts = ABSL_TEST_COPTS, + linkopts = ABSL_DEFAULT_LINKOPTS, + deps = [ + ":log", + ":scoped_mock_log", + ":structured", + "//absl/base:core_headers", + "//absl/log/internal:test_helpers", + "//absl/log/internal:test_matchers", + "@com_google_googletest//:gtest_main", + ], +) + cc_binary( name = "log_benchmark", testonly = 1, diff --git a/absl/log/CMakeLists.txt b/absl/log/CMakeLists.txt index 0bc8a22f..2337d0c0 100644 --- a/absl/log/CMakeLists.txt +++ b/absl/log/CMakeLists.txt @@ -128,6 +128,25 @@ absl_cc_library( absl_cc_library( NAME + log_internal_proto + SRCS + "internal/proto.cc" + HDRS + "internal/proto.h" + COPTS + ${ABSL_DEFAULT_COPTS} + LINKOPTS + ${ABSL_DEFAULT_LINKOPTS} + DEPS + absl::base + absl::config + absl::core_headers + absl::strings + absl::span +) + +absl_cc_library( + NAME log_internal_message SRCS "internal/log_message.cc" @@ -147,6 +166,7 @@ absl_cc_library( absl::log_internal_append_truncated absl::log_internal_format absl::log_internal_globals + absl::log_internal_proto absl::log_internal_log_sink_set absl::log_internal_nullguard absl::log_globals @@ -251,6 +271,7 @@ absl_cc_library( ${ABSL_DEFAULT_LINKOPTS} DEPS absl::config + absl::core_headers absl::log_entry absl::log_severity absl::strings @@ -292,6 +313,7 @@ absl_cc_library( ${ABSL_DEFAULT_LINKOPTS} DEPS absl::config + absl::core_headers absl::log_entry absl::log_internal_test_helpers absl::log_severity @@ -553,6 +575,37 @@ absl_cc_library( TESTONLY ) +absl_cc_library( + NAME + log_internal_structured + HDRS + "internal/structured.h" + COPTS + ${ABSL_DEFAULT_COPTS} + LINKOPTS + ${ABSL_DEFAULT_LINKOPTS} + DEPS + absl::config + absl::log_internal_message + absl::strings +) + +absl_cc_library( + NAME + log_structured + HDRS + "structured.h" + COPTS + ${ABSL_DEFAULT_COPTS} + LINKOPTS + ${ABSL_DEFAULT_LINKOPTS} + DEPS + absl::config + absl::log_internal_structured + absl::strings + PUBLIC +) + # Test targets absl_cc_test( NAME @@ -852,3 +905,23 @@ absl_cc_test( GTest::gmock GTest::gtest_main ) + +absl_cc_test( + NAME + log_structured_test + SRCS + "structured_test.cc" + COPTS + ${ABSL_TEST_COPTS} + LINKOPTS + ${ABSL_DEFAULT_LINKOPTS} + DEPS + absl::core_headers + absl::log + absl::log_internal_test_helpers + absl::log_internal_test_matchers + absl::log_structured + absl::scoped_mock_log + GTest::gmock + GTest::gtest_main +) diff --git a/absl/log/internal/BUILD.bazel b/absl/log/internal/BUILD.bazel index 4f600753..b2e7085f 100644 --- a/absl/log/internal/BUILD.bazel +++ b/absl/log/internal/BUILD.bazel @@ -138,6 +138,7 @@ cc_library( ":globals", ":log_sink_set", ":nullguard", + ":proto", "//absl/base", "//absl/base:config", "//absl/base:core_headers", @@ -233,6 +234,18 @@ cc_library( ) cc_library( + name = "structured", + hdrs = ["structured.h"], + copts = ABSL_DEFAULT_COPTS, + linkopts = ABSL_DEFAULT_LINKOPTS, + deps = [ + ":log_message", + "//absl/base:config", + "//absl/strings", + ], +) + +cc_library( name = "test_actions", testonly = True, srcs = ["test_actions.cc"], @@ -246,7 +259,11 @@ cc_library( "//absl/log:log_entry", "//absl/strings", "//absl/time", - ], + ] + select({ + "//absl:msvc_compiler": [], + "//conditions:default": [ + ], + }), ) cc_library( @@ -275,14 +292,18 @@ cc_library( linkopts = ABSL_DEFAULT_LINKOPTS, deps = [ ":test_helpers", + "@com_google_googletest//:gtest", "//absl/base:config", "//absl/base:core_headers", "//absl/base:log_severity", "//absl/log:log_entry", "//absl/strings", "//absl/time", - "@com_google_googletest//:gtest", - ], + ] + select({ + "//absl:msvc_compiler": [], + "//conditions:default": [ + ], + }), ) cc_library( @@ -293,6 +314,19 @@ cc_library( deps = ["//absl/base:config"], ) +cc_library( + name = "proto", + srcs = ["proto.cc"], + hdrs = ["proto.h"], + deps = [ + "//absl/base", + "//absl/base:config", + "//absl/base:core_headers", + "//absl/strings", + "//absl/types:span", + ], +) + # Test targets cc_test( name = "stderr_log_sink_test", diff --git a/absl/log/internal/log_message.cc b/absl/log/internal/log_message.cc index 8329597e..b7313551 100644 --- a/absl/log/internal/log_message.cc +++ b/absl/log/internal/log_message.cc @@ -45,6 +45,7 @@ #include "absl/log/internal/globals.h" #include "absl/log/internal/log_format.h" #include "absl/log/internal/log_sink_set.h" +#include "absl/log/internal/proto.h" #include "absl/log/log_entry.h" #include "absl/log/log_sink.h" #include "absl/log/log_sink_registry.h" @@ -64,6 +65,40 @@ ABSL_NAMESPACE_BEGIN namespace log_internal { namespace { +// message `logging.proto.Event` +enum EventTag : uint8_t { + kValue = 7, +}; + +// message `logging.proto.Value` +enum ValueTag : uint8_t { + kString = 1, + kStringLiteral = 6, +}; + +// Decodes a `logging.proto.Value` from `buf` and writes a string representation +// into `dst`. The string representation will be truncated if `dst` is not +// large enough to hold it. Returns false if `dst` has size zero or one (i.e. +// sufficient only for a nul-terminator) and no decoded data could be written. +// This function may or may not write a nul-terminator into `dst`, and it may or +// may not truncate the data it writes in order to do make space for that nul +// terminator. In any case, `dst` will be advanced to point at the byte where +// subsequent writes should begin. +bool PrintValue(absl::Span<char>& dst, absl::Span<const char> buf) { + if (dst.size() <= 1) return false; + ProtoField field; + while (field.DecodeFrom(&buf)) { + switch (field.tag()) { + case ValueTag::kString: + case ValueTag::kStringLiteral: + if (field.type() == WireType::kLengthDelimited) + if (log_internal::AppendTruncated(field.string_value(), dst) < + field.string_value().size()) + return false; + } + } + return true; +} absl::string_view Basename(absl::string_view filepath) { #ifdef _WIN32 @@ -84,93 +119,6 @@ void WriteToStream(const char* data, void* os) { } } // namespace -// A write-only `std::streambuf` that writes into an `absl::Span<char>`. -// -// This class is responsible for writing a metadata prefix just before the -// first data are streamed in. The metadata are subject to change (cf. -// `LogMessage::AtLocation`) until then, so we wait as long as possible. -// -// This class is also responsible for reserving space for a trailing newline -// so that one can be added later by `Finalize` no matter how many data are -// streamed in. -class LogEntryStreambuf final : public std::streambuf { - public: - explicit LogEntryStreambuf(absl::Span<char> buf, - const absl::LogEntry& entry) - : buf_(buf), entry_(entry), prefix_len_(0), finalized_(false) { - // To detect when data are first written, we leave the put area null, - // override `overflow`, and check ourselves in `xsputn`. - } - - LogEntryStreambuf(LogEntryStreambuf&&) = delete; - LogEntryStreambuf& operator=(LogEntryStreambuf&&) = delete; - - absl::Span<const char> Finalize() { - assert(!finalized_); - // If no data were ever streamed in, this is where we must write the - // prefix. - if (pbase() == nullptr) Initialize(); - // Here we reclaim the two bytes we reserved. - ptrdiff_t idx = pptr() - pbase(); - setp(buf_.data(), buf_.data() + buf_.size()); - pbump(static_cast<int>(idx)); - sputc('\n'); - sputc('\0'); - finalized_ = true; - return absl::Span<const char>(pbase(), - static_cast<size_t>(pptr() - pbase())); - } - size_t prefix_len() const { return prefix_len_; } - - protected: - std::streamsize xsputn(const char* s, std::streamsize n) override { - if (n < 0) return 0; - if (pbase() == nullptr) Initialize(); - return static_cast<std::streamsize>( - Append(absl::string_view(s, static_cast<size_t>(n)))); - } - - int overflow(int ch = EOF) override { - if (pbase() == nullptr) Initialize(); - if (ch == EOF) return 0; - if (pptr() == epptr()) return EOF; - *pptr() = static_cast<char>(ch); - pbump(1); - return 1; - } - - private: - void Initialize() { - // Here we reserve two bytes in our buffer to guarantee `Finalize` space - // to add a trailing "\n\0". - assert(buf_.size() >= 2); - setp(buf_.data(), buf_.data() + buf_.size() - 2); - if (entry_.prefix()) { - absl::Span<char> remaining = buf_; - prefix_len_ = log_internal::FormatLogPrefix( - entry_.log_severity(), entry_.timestamp(), entry_.tid(), - entry_.source_basename(), entry_.source_line(), - log_internal::ThreadIsLoggingToLogSink() ? PrefixFormat::kRaw - : PrefixFormat::kNotRaw, - remaining); - pbump(static_cast<int>(prefix_len_)); - } - } - - size_t Append(absl::string_view data) { - absl::Span<char> remaining(pptr(), - static_cast<size_t>(epptr() - pptr())); - const size_t written = log_internal::AppendTruncated(data, remaining); - pbump(static_cast<int>(written)); - return written; - } - - const absl::Span<char> buf_; - const absl::LogEntry& entry_; - size_t prefix_len_; - bool finalized_; -}; - struct LogMessage::LogMessageData final { LogMessageData(const char* file, int line, absl::LogSeverity severity, absl::Time timestamp); @@ -193,18 +141,31 @@ struct LogMessage::LogMessageData final { // non-sink targets (e.g. stderr, log files). bool extra_sinks_only; + std::ostream manipulated; // ostream with IO manipulators applied + + // A `logging.proto.Event` proto message is built into `encoded_buf`. + std::array<char, kLogMessageBufferSize> encoded_buf; + // `encoded_remaining` is the suffix of `encoded_buf` that has not been filled + // yet. If a datum to be encoded does not fit into `encoded_remaining` and + // cannot be truncated to fit, the size of `encoded_remaining` will be zeroed + // to prevent encoding of any further data. Note that in this case its data() + // pointer will not point past the end of `encoded_buf`. + absl::Span<char> encoded_remaining; + // A formatted string message is built in `string_buf`. std::array<char, kLogMessageBufferSize> string_buf; - // A `std::streambuf` that stores into `string_buf`. - LogEntryStreambuf streambuf_; + void FinalizeEncodingAndFormat(); }; LogMessage::LogMessageData::LogMessageData(const char* file, int line, absl::LogSeverity severity, absl::Time timestamp) : extra_sinks_only(false), - streambuf_(absl::MakeSpan(string_buf), entry) { + manipulated(nullptr), + encoded_remaining(encoded_buf) { + // Legacy defaults for LOG's ostream: + manipulated.setf(std::ios_base::showbase | std::ios_base::boolalpha); entry.full_filename_ = file; entry.base_filename_ = Basename(file); entry.line_ = line; @@ -215,20 +176,57 @@ LogMessage::LogMessageData::LogMessageData(const char* file, int line, entry.tid_ = absl::base_internal::GetCachedTID(); } +void LogMessage::LogMessageData::FinalizeEncodingAndFormat() { + // Note that `encoded_remaining` may have zero size without pointing past the + // end of `encoded_buf`, so the difference between `data()` pointers is used + // to compute the size of `encoded_data`. + absl::Span<const char> encoded_data( + encoded_buf.data(), + static_cast<size_t>(encoded_remaining.data() - encoded_buf.data())); + // `string_remaining` is the suffix of `string_buf` that has not been filled + // yet. + absl::Span<char> string_remaining(string_buf); + // We may need to write a newline and nul-terminator at the end of the decoded + // string data. Rather than worry about whether those should overwrite the + // end of the string (if the buffer is full) or be appended, we avoid writing + // into the last two bytes so we always have space to append. + string_remaining.remove_suffix(2); + entry.prefix_len_ = + entry.prefix() ? log_internal::FormatLogPrefix( + entry.log_severity(), entry.timestamp(), entry.tid(), + entry.source_basename(), entry.source_line(), + log_internal::ThreadIsLoggingToLogSink() + ? PrefixFormat::kRaw + : PrefixFormat::kNotRaw, + string_remaining) + : 0; + // Decode data from `encoded_buf` until we run out of data or we run out of + // `string_remaining`. + ProtoField field; + while (field.DecodeFrom(&encoded_data)) { + switch (field.tag()) { + case EventTag::kValue: + if (field.type() != WireType::kLengthDelimited) continue; + if (PrintValue(string_remaining, field.bytes_value())) continue; + break; + } + break; + } + auto chars_written = + static_cast<size_t>(string_remaining.data() - string_buf.data()); + string_buf[chars_written++] = '\n'; + string_buf[chars_written++] = '\0'; + entry.text_message_with_prefix_and_newline_and_nul_ = + absl::MakeSpan(string_buf).subspan(0, chars_written); +} + LogMessage::LogMessage(const char* file, int line, absl::LogSeverity severity) - : data_( - absl::make_unique<LogMessageData>(file, line, severity, absl::Now())) -, stream_(&data_->streambuf_) -{ + : data_(absl::make_unique<LogMessageData>(file, line, severity, + absl::Now())) { data_->first_fatal = false; data_->is_perror = false; data_->fail_quietly = false; - // Legacy defaults for LOG's ostream: - stream_.setf(std::ios_base::showbase | std::ios_base::boolalpha); - // `fill('0')` is omitted here because its effects are very different - // without structured logging. Resolution is tracked in b/111310488. - // This logs a backtrace even if the location is subsequently changed using // AtLocation. This quirk, and the behavior when AtLocation is called twice, // are fixable but probably not worth fixing. @@ -346,6 +344,23 @@ void LogMessage::FailQuietly() { _exit(1); } +LogMessage& LogMessage::operator<<(const std::string& v) { + return LogString(false, v); +} + +LogMessage& LogMessage::operator<<(absl::string_view v) { + return LogString(false, v); +} +LogMessage& LogMessage::operator<<(std::ostream& (*m)(std::ostream& os)) { + OstreamView view(*data_); + data_->manipulated << m; + return *this; +} +LogMessage& LogMessage::operator<<(std::ios_base& (*m)(std::ios_base& os)) { + OstreamView view(*data_); + data_->manipulated << m; + return *this; +} template LogMessage& LogMessage::operator<<(const char& v); template LogMessage& LogMessage::operator<<(const signed char& v); template LogMessage& LogMessage::operator<<(const unsigned char& v); @@ -363,8 +378,6 @@ template LogMessage& LogMessage::operator<<(const void* const& v); template LogMessage& LogMessage::operator<<(const float& v); template LogMessage& LogMessage::operator<<(const double& v); template LogMessage& LogMessage::operator<<(const bool& v); -template LogMessage& LogMessage::operator<<(const std::string& v); -template LogMessage& LogMessage::operator<<(const absl::string_view& v); void LogMessage::Flush() { if (data_->entry.log_severity() < absl::MinLogLevel()) @@ -388,14 +401,54 @@ void LogMessage::Flush() { } } - data_->entry.text_message_with_prefix_and_newline_and_nul_ = - data_->streambuf_.Finalize(); - data_->entry.prefix_len_ = data_->streambuf_.prefix_len(); + data_->FinalizeEncodingAndFormat(); + data_->entry.encoding_ = + absl::string_view(data_->encoded_buf.data(), + static_cast<size_t>(data_->encoded_remaining.data() - + data_->encoded_buf.data())); SendToLog(); } void LogMessage::SetFailQuietly() { data_->fail_quietly = true; } +LogMessage::OstreamView::OstreamView(LogMessageData& message_data) + : data_(message_data), encoded_remaining_copy_(data_.encoded_remaining) { + // This constructor sets the `streambuf` up so that streaming into an attached + // ostream encodes string data in-place. To do that, we write appropriate + // headers into the buffer using a copy of the buffer view so that we can + // decide not to keep them later if nothing is ever streamed in. We don't + // know how much data we'll get, but we can use the size of the remaining + // buffer as an upper bound and fill in the right size once we know it. + message_start_ = + EncodeMessageStart(EventTag::kValue, encoded_remaining_copy_.size(), + &encoded_remaining_copy_); + string_start_ = + EncodeMessageStart(ValueTag::kString, encoded_remaining_copy_.size(), + &encoded_remaining_copy_); + setp(encoded_remaining_copy_.data(), + encoded_remaining_copy_.data() + encoded_remaining_copy_.size()); + data_.manipulated.rdbuf(this); +} + +LogMessage::OstreamView::~OstreamView() { + const absl::Span<const char> contents(pbase(), + static_cast<size_t>(pptr() - pbase())); + encoded_remaining_copy_.remove_prefix(contents.size()); + if (!string_start_.data()) { + // The headers didn't fit; we won't write anything to the buffer, but we + // also need to zero the size of `data_->encoded_remaining` so that no more + // data is encoded. + data_.encoded_remaining.remove_suffix(data_.encoded_remaining.size()); + } else if (!contents.empty()) { + EncodeMessageLength(string_start_, &encoded_remaining_copy_); + EncodeMessageLength(message_start_, &encoded_remaining_copy_); + data_.encoded_remaining = encoded_remaining_copy_; + } + data_.manipulated.rdbuf(nullptr); +} + +std::ostream& LogMessage::OstreamView::stream() { return data_.manipulated; } + bool LogMessage::IsFatal() const { return data_->entry.log_severity() == absl::LogSeverity::kFatal && absl::log_internal::ExitOnDFatal(); @@ -449,11 +502,30 @@ void LogMessage::LogBacktraceIfNeeded() { if (!absl::log_internal::ShouldLogBacktraceAt(data_->entry.source_basename(), data_->entry.source_line())) return; - stream_ << " (stacktrace:\n"; + OstreamView view(*data_); + view.stream() << " (stacktrace:\n"; debugging_internal::DumpStackTrace( 1, log_internal::MaxFramesInLogStackTrace(), - log_internal::ShouldSymbolizeLogStackTrace(), WriteToStream, &stream_); - stream_ << ") "; + log_internal::ShouldSymbolizeLogStackTrace(), WriteToStream, + &view.stream()); + view.stream() << ") "; +} + +// Encodes a partial `logging.proto.Event` containing the specified string data +// into `data_->encoded_remaining`. +LogMessage& LogMessage::LogString(bool literal, absl::string_view str) { + // Don't commit the MessageStart if the String tag_type and length don't fit. + auto encoded_remaining_copy = data_->encoded_remaining; + auto start = EncodeMessageStart( + EventTag::kValue, BufferSizeFor(WireType::kLengthDelimited) + str.size(), + &encoded_remaining_copy); + if (EncodeStringTruncate( + literal ? ValueTag::kStringLiteral : ValueTag::kString, str, + &encoded_remaining_copy)) { + EncodeMessageLength(start, &encoded_remaining_copy); + data_->encoded_remaining = encoded_remaining_copy; + } + return *this; } LogMessageFatal::LogMessageFatal(const char* file, int line) diff --git a/absl/log/internal/log_message.h b/absl/log/internal/log_message.h index 8868f8c8..5914a535 100644 --- a/absl/log/internal/log_message.h +++ b/absl/log/internal/log_message.h @@ -47,6 +47,7 @@ namespace absl { ABSL_NAMESPACE_BEGIN namespace log_internal { +class AsLiteralImpl; constexpr int kLogMessageBufferSize = 15000; @@ -130,6 +131,10 @@ class LogMessage { LogMessage& operator<<(bool v) { return operator<< <bool>(v); } // clang-format on + // These overloads are more efficient since no `ostream` is involved. + LogMessage& operator<<(const std::string& v); + LogMessage& operator<<(absl::string_view v); + // Handle stream manipulators e.g. std::endl. LogMessage& operator<<(std::ostream& (*m)(std::ostream& os)); LogMessage& operator<<(std::ios_base& (*m)(std::ios_base& os)); @@ -189,6 +194,27 @@ class LogMessage { private: struct LogMessageData; // Opaque type containing message state + friend class AsLiteralImpl; + + // This streambuf writes directly into the structured logging buffer so that + // arbitrary types can be encoded as string data (using + // `operator<<(std::ostream &, ...)` without any extra allocation or copying. + // Space is reserved before the data to store the length field, which is + // filled in by `~OstreamView`. + class OstreamView final : public std::streambuf { + public: + explicit OstreamView(LogMessageData& message_data); + ~OstreamView() override; + OstreamView(const OstreamView&) = delete; + OstreamView& operator=(const OstreamView&) = delete; + std::ostream& stream(); + + private: + LogMessageData& data_; + absl::Span<char> encoded_remaining_copy_; + absl::Span<char> message_start_; + absl::Span<char> string_start_; + }; // Returns `true` if the message is fatal or enabled debug-fatal. bool IsFatal() const; @@ -202,6 +228,9 @@ class LogMessage { // Checks `FLAGS_log_backtrace_at` and appends a backtrace if appropriate. void LogBacktraceIfNeeded(); + LogMessage& LogString(bool literal, + absl::string_view str) ABSL_ATTRIBUTE_NOINLINE; + // This should be the first data member so that its initializer captures errno // before any other initializers alter it (e.g. with calls to new) and so that // no other destructors run afterward an alter it (e.g. with calls to delete). @@ -210,8 +239,6 @@ class LogMessage { // We keep the data in a separate struct so that each instance of `LogMessage` // uses less stack space. std::unique_ptr<LogMessageData> data_; - - std::ostream stream_; }; // Helper class so that `AbslStringify()` can modify the LogMessage. @@ -233,10 +260,9 @@ class StringifySink final { }; // Note: the following is declared `ABSL_ATTRIBUTE_NOINLINE` -template < - typename T, - typename std::enable_if<strings_internal::HasAbslStringify<T>::value, - int>::type> +template <typename T, + typename std::enable_if<strings_internal::HasAbslStringify<T>::value, + int>::type> LogMessage& LogMessage::operator<<(const T& v) { StringifySink sink(*this); // Replace with public API. @@ -245,35 +271,26 @@ LogMessage& LogMessage::operator<<(const T& v) { } // Note: the following is declared `ABSL_ATTRIBUTE_NOINLINE` -template < - typename T, - typename std::enable_if<!strings_internal::HasAbslStringify<T>::value, - int>::type> +template <typename T, + typename std::enable_if<!strings_internal::HasAbslStringify<T>::value, + int>::type> LogMessage& LogMessage::operator<<(const T& v) { - stream_ << log_internal::NullGuard<T>().Guard(v); + OstreamView view(*data_); + view.stream() << log_internal::NullGuard<T>().Guard(v); return *this; } -inline LogMessage& LogMessage::operator<<( - std::ostream& (*m)(std::ostream& os)) { - stream_ << m; - return *this; -} -inline LogMessage& LogMessage::operator<<( - std::ios_base& (*m)(std::ios_base& os)) { - stream_ << m; - return *this; -} template <int SIZE> LogMessage& LogMessage::operator<<(const char (&buf)[SIZE]) { - stream_ << buf; - return *this; + const bool literal = true; + return LogString(literal, buf); } + // Note: the following is declared `ABSL_ATTRIBUTE_NOINLINE` template <int SIZE> LogMessage& LogMessage::operator<<(char (&buf)[SIZE]) { - stream_ << buf; - return *this; + const bool literal = false; + return LogString(literal, buf); } // We instantiate these specializations in the library's TU to save space in // other TUs. Since the template is marked `ABSL_ATTRIBUTE_NOINLINE` we will be @@ -299,9 +316,6 @@ extern template LogMessage& LogMessage::operator<<(const void* const& v); extern template LogMessage& LogMessage::operator<<(const float& v); extern template LogMessage& LogMessage::operator<<(const double& v); extern template LogMessage& LogMessage::operator<<(const bool& v); -extern template LogMessage& LogMessage::operator<<(const std::string& v); -extern template LogMessage& LogMessage::operator<<( - const absl::string_view& v); // `LogMessageFatal` ensures the process will exit in failure after logging this // message. diff --git a/absl/log/internal/proto.cc b/absl/log/internal/proto.cc new file mode 100644 index 00000000..80d78eed --- /dev/null +++ b/absl/log/internal/proto.cc @@ -0,0 +1,214 @@ +// Copyright 2020 The Abseil Authors. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// https://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +#include "absl/log/internal/proto.h" + +#include <algorithm> +#include <cstddef> +#include <cstdint> +#include <cstring> + +#include "absl/base/attributes.h" +#include "absl/base/config.h" +#include "absl/types/span.h" + +namespace absl { +ABSL_NAMESPACE_BEGIN +namespace log_internal { +namespace { +void EncodeRawVarint(uint64_t value, size_t size, absl::Span<char> *buf) { + for (size_t s = 0; s < size; s++) { + (*buf)[s] = (value & 0x7f) | (s + 1 == size ? 0 : 0x80); + value >>= 7; + } + buf->remove_prefix(size); +} +constexpr uint64_t MakeTagType(uint64_t tag, WireType type) { + return tag << 3 | static_cast<uint64_t>(type); +} +} // namespace + +bool EncodeVarint(uint64_t tag, uint64_t value, absl::Span<char> *buf) { + const uint64_t tag_type = MakeTagType(tag, WireType::kVarint); + const uint64_t tag_type_size = VarintSize(tag_type); + const uint64_t value_size = VarintSize(value); + if (tag_type_size + value_size > buf->size()) { + buf->remove_suffix(buf->size()); + return false; + } + EncodeRawVarint(tag_type, tag_type_size, buf); + EncodeRawVarint(value, value_size, buf); + return true; +} + +bool Encode64Bit(uint64_t tag, uint64_t value, absl::Span<char> *buf) { + const uint64_t tag_type = MakeTagType(tag, WireType::k64Bit); + const uint64_t tag_type_size = VarintSize(tag_type); + if (tag_type_size + sizeof(value) > buf->size()) { + buf->remove_suffix(buf->size()); + return false; + } + EncodeRawVarint(tag_type, tag_type_size, buf); + for (size_t s = 0; s < sizeof(value); s++) { + (*buf)[s] = value & 0xff; + value >>= 8; + } + buf->remove_prefix(sizeof(value)); + return true; +} + +bool Encode32Bit(uint64_t tag, uint32_t value, absl::Span<char> *buf) { + const uint64_t tag_type = MakeTagType(tag, WireType::k32Bit); + const uint64_t tag_type_size = VarintSize(tag_type); + if (tag_type_size + sizeof(value) > buf->size()) { + buf->remove_suffix(buf->size()); + return false; + } + EncodeRawVarint(tag_type, tag_type_size, buf); + for (size_t s = 0; s < sizeof(value); s++) { + (*buf)[s] = value & 0xff; + value >>= 8; + } + buf->remove_prefix(sizeof(value)); + return true; +} + +bool EncodeBytes(uint64_t tag, absl::Span<const char> value, + absl::Span<char> *buf) { + const uint64_t tag_type = MakeTagType(tag, WireType::kLengthDelimited); + const uint64_t tag_type_size = VarintSize(tag_type); + uint64_t length = value.size(); + const uint64_t length_size = VarintSize(length); + if (tag_type_size + length_size + value.size() > buf->size()) { + buf->remove_suffix(buf->size()); + return false; + } + EncodeRawVarint(tag_type, tag_type_size, buf); + EncodeRawVarint(length, length_size, buf); + memcpy(buf->data(), value.data(), value.size()); + buf->remove_prefix(value.size()); + return true; +} + +bool EncodeBytesTruncate(uint64_t tag, absl::Span<const char> value, + absl::Span<char> *buf) { + const uint64_t tag_type = MakeTagType(tag, WireType::kLengthDelimited); + const uint64_t tag_type_size = VarintSize(tag_type); + uint64_t length = value.size(); + const uint64_t length_size = VarintSize(length); + if (tag_type_size + length_size <= buf->size() && + tag_type_size + length_size + value.size() > buf->size()) { + value.remove_suffix(tag_type_size + length_size + value.size() - + buf->size()); + length = value.size(); + } + if (tag_type_size + length_size + value.size() > buf->size()) { + buf->remove_suffix(buf->size()); + return false; + } + EncodeRawVarint(tag_type, tag_type_size, buf); + EncodeRawVarint(length, length_size, buf); + memcpy(buf->data(), value.data(), value.size()); + buf->remove_prefix(value.size()); + return true; +} + +ABSL_MUST_USE_RESULT absl::Span<char> EncodeMessageStart( + uint64_t tag, uint64_t max_size, absl::Span<char> *buf) { + const uint64_t tag_type = MakeTagType(tag, WireType::kLengthDelimited); + const uint64_t tag_type_size = VarintSize(tag_type); + max_size = std::min<uint64_t>(max_size, buf->size()); + const uint64_t length_size = VarintSize(max_size); + if (tag_type_size + length_size > buf->size()) { + buf->remove_suffix(buf->size()); + return absl::Span<char>(); + } + EncodeRawVarint(tag_type, tag_type_size, buf); + const absl::Span<char> ret = buf->subspan(0, length_size); + EncodeRawVarint(0, length_size, buf); + return ret; +} + +void EncodeMessageLength(absl::Span<char> msg, const absl::Span<char> *buf) { + if (!msg.data()) return; + const uint64_t length_size = msg.size(); + EncodeRawVarint(buf->data() - msg.data() - length_size, length_size, &msg); +} + +namespace { +uint64_t DecodeVarint(absl::Span<const char> *buf) { + uint64_t value = 0; + size_t s = 0; + while (s < buf->size()) { + value |= static_cast<uint64_t>(static_cast<unsigned char>((*buf)[s]) & 0x7f) + << 7 * s; + if (!((*buf)[s++] & 0x80)) break; + } + buf->remove_prefix(s); + return value; +} + +uint64_t Decode64Bit(absl::Span<const char> *buf) { + uint64_t value = 0; + size_t s = 0; + while (s < buf->size()) { + value |= static_cast<uint64_t>(static_cast<unsigned char>((*buf)[s])) + << 8 * s; + if (++s == sizeof(value)) break; + } + buf->remove_prefix(s); + return value; +} + +uint32_t Decode32Bit(absl::Span<const char> *buf) { + uint32_t value = 0; + size_t s = 0; + while (s < buf->size()) { + value |= static_cast<uint32_t>(static_cast<unsigned char>((*buf)[s])) + << 8 * s; + if (++s == sizeof(value)) break; + } + buf->remove_prefix(s); + return value; +} +} // namespace + +bool ProtoField::DecodeFrom(absl::Span<const char> *data) { + if (data->empty()) return false; + const uint64_t tag_type = DecodeVarint(data); + tag_ = tag_type >> 3; + type_ = static_cast<WireType>(tag_type & 0x07); + switch (type_) { + case WireType::kVarint: + value_ = DecodeVarint(data); + break; + case WireType::k64Bit: + value_ = Decode64Bit(data); + break; + case WireType::kLengthDelimited: { + value_ = DecodeVarint(data); + data_ = data->subspan(0, std::min<size_t>(value_, data->size())); + data->remove_prefix(data_.size()); + break; + } + case WireType::k32Bit: + value_ = Decode32Bit(data); + break; + } + return true; +} + +} // namespace log_internal +ABSL_NAMESPACE_END +} // namespace absl diff --git a/absl/log/internal/proto.h b/absl/log/internal/proto.h new file mode 100644 index 00000000..63c4e986 --- /dev/null +++ b/absl/log/internal/proto.h @@ -0,0 +1,267 @@ +// Copyright 2020 The Abseil Authors. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// https://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +// ----------------------------------------------------------------------------- +// File: internal/proto.h +// ----------------------------------------------------------------------------- +// +// Declares functions for serializing and deserializing data to and from memory +// buffers in protocol buffer wire format. This library takes no steps to +// ensure that the encoded data matches with any message specification. + +#ifndef ABSL_LOG_INTERNAL_PROTO_H_ +#define ABSL_LOG_INTERNAL_PROTO_H_ + +#include <cstddef> +#include <cstdint> +#include <limits> + +#include "absl/base/attributes.h" +#include "absl/base/casts.h" +#include "absl/base/config.h" +#include "absl/strings/string_view.h" +#include "absl/types/span.h" + +namespace absl { +ABSL_NAMESPACE_BEGIN +namespace log_internal { + +// absl::Span<char> represents a view into the available space in a mutable +// buffer during encoding. Encoding functions shrink the span as they go so +// that the same view can be passed to a series of Encode functions. If the +// data do not fit, nothing is encoded, the view is set to size zero (so that +// all subsequent encode calls fail), and false is returned. Otherwise true is +// returned. + +// In particular, attempting to encode a series of data into an insufficient +// buffer has consistent and efficient behavior without any caller-side error +// checking. Individual values will be encoded in their entirety or not at all +// (unless one of the `Truncate` functions is used). Once a value is omitted +// because it does not fit, no subsequent values will be encoded to preserve +// ordering; the decoded sequence will be a prefix of the original sequence. + +// There are two ways to encode a message-typed field: +// +// * Construct its contents in a separate buffer and use `EncodeBytes` to copy +// it into the primary buffer with type, tag, and length. +// * Use `EncodeMessageStart` to write type and tag fields and reserve space for +// the length field, then encode the contents directly into the buffer, then +// use `EncodeMessageLength` to write the actual length into the reserved +// bytes. This works fine if the actual length takes fewer bytes to encode +// than were reserved, although you don't get your extra bytes back. +// This approach will always produce a valid encoding, but your protocol may +// require that the whole message field by omitted if the buffer is too small +// to contain all desired subfields. In this case, operate on a copy of the +// buffer view and assign back only if everything fit, i.e. if the last +// `Encode` call returned true. + +// Encodes the specified integer as a varint field and returns true if it fits. +// Used for int32_t, int64_t, uint32_t, uint64_t, bool, and enum field types. +// Consumes up to kMaxVarintSize * 2 bytes (20). +bool EncodeVarint(uint64_t tag, uint64_t value, absl::Span<char> *buf); + +// Encodes the specified integer as a varint field using ZigZag encoding and +// returns true if it fits. +// Used for sint32 and sint64 field types. +// Consumes up to kMaxVarintSize * 2 bytes (20). +inline bool EncodeVarintZigZag(uint64_t tag, int64_t value, + absl::Span<char> *buf) { + if (value < 0) + return EncodeVarint(tag, 2 * static_cast<uint64_t>(-(value + 1)) + 1, buf); + return EncodeVarint(tag, 2 * static_cast<uint64_t>(value), buf); +} + +// Encodes the specified integer as a 64-bit field and returns true if it fits. +// Used for fixed64 and sfixed64 field types. +// Consumes up to kMaxVarintSize + 8 bytes (18). +bool Encode64Bit(uint64_t tag, uint64_t value, absl::Span<char> *buf); + +// Encodes the specified double as a 64-bit field and returns true if it fits. +// Used for double field type. +// Consumes up to kMaxVarintSize + 8 bytes (18). +inline bool EncodeDouble(uint64_t tag, double value, absl::Span<char> *buf) { + return Encode64Bit(tag, absl::bit_cast<uint64_t>(value), buf); +} + +// Encodes the specified integer as a 32-bit field and returns true if it fits. +// Used for fixed32 and sfixed32 field types. +// Consumes up to kMaxVarintSize + 4 bytes (14). +bool Encode32Bit(uint64_t tag, uint32_t value, absl::Span<char> *buf); + +// Encodes the specified float as a 32-bit field and returns true if it fits. +// Used for float field type. +// Consumes up to kMaxVarintSize + 4 bytes (14). +inline bool EncodeFloat(uint64_t tag, float value, absl::Span<char> *buf) { + return Encode32Bit(tag, absl::bit_cast<uint32_t>(value), buf); +} + +// Encodes the specified bytes as a length-delimited field and returns true if +// they fit. +// Used for string, bytes, message, and packed-repeated field type. +// Consumes up to kMaxVarintSize * 2 + value.size() bytes (20 + value.size()). +bool EncodeBytes(uint64_t tag, absl::Span<const char> value, + absl::Span<char> *buf); + +// Encodes as many of the specified bytes as will fit as a length-delimited +// field and returns true as long as the field header (`tag_type` and `length`) +// fits. +// Used for string, bytes, message, and packed-repeated field type. +// Consumes up to kMaxVarintSize * 2 + value.size() bytes (20 + value.size()). +bool EncodeBytesTruncate(uint64_t tag, absl::Span<const char> value, + absl::Span<char> *buf); + +// Encodes the specified string as a length-delimited field and returns true if +// it fits. +// Used for string, bytes, message, and packed-repeated field type. +// Consumes up to kMaxVarintSize * 2 + value.size() bytes (20 + value.size()). +inline bool EncodeString(uint64_t tag, absl::string_view value, + absl::Span<char> *buf) { + return EncodeBytes(tag, value, buf); +} + +// Encodes as much of the specified string as will fit as a length-delimited +// field and returns true as long as the field header (`tag_type` and `length`) +// fits. +// Used for string, bytes, message, and packed-repeated field type. +// Consumes up to kMaxVarintSize * 2 + value.size() bytes (20 + value.size()). +inline bool EncodeStringTruncate(uint64_t tag, absl::string_view value, + absl::Span<char> *buf) { + return EncodeBytesTruncate(tag, value, buf); +} + +// Encodes the header for a length-delimited field containing up to `max_size` +// bytes or the number remaining in the buffer, whichever is less. If the +// header fits, a non-nullptr `Span` is returned; this must be passed to +// `EncodeMessageLength` after all contents are encoded to finalize the length +// field. If the header does not fit, a nullptr `Span` is returned which is +// safe to pass to `EncodeMessageLength` but need not be. +// Used for string, bytes, message, and packed-repeated field type. +// Consumes up to kMaxVarintSize * 2 bytes (20). +ABSL_MUST_USE_RESULT absl::Span<char> EncodeMessageStart(uint64_t tag, + uint64_t max_size, + absl::Span<char> *buf); + +// Finalizes the length field in `msg` so that it encompasses all data encoded +// since the call to `EncodeMessageStart` which returned `msg`. Does nothing if +// `msg` is a `nullptr` `Span`. +void EncodeMessageLength(absl::Span<char> msg, const absl::Span<char> *buf); + +enum class WireType : uint64_t { + kVarint = 0, + k64Bit = 1, + kLengthDelimited = 2, + k32Bit = 5, +}; + +constexpr uint64_t VarintSize(uint64_t value) { + return value < 128 ? 1 : 1 + VarintSize(value >> 7); +} +constexpr uint64_t MinVarintSize() { + return VarintSize((std::numeric_limits<uint64_t>::min)()); +} +constexpr uint64_t MaxVarintSize() { + return VarintSize((std::numeric_limits<uint64_t>::max)()); +} + +constexpr uint64_t MaxVarintForSize(size_t size) { + return size >= 10 ? (std::numeric_limits<uint64_t>::max)() + : (static_cast<uint64_t>(1) << size * 7) - 1; +} + +// `BufferSizeFor` returns a number of bytes guaranteed to be sufficient to +// store encoded fields of the specified WireTypes regardless of tag numbers and +// data values. This only makes sense for `WireType::kLengthDelimited` if you +// add in the length of the contents yourself, e.g. for string and bytes fields +// by adding the lengths of any encoded strings to the return value or for +// submessage fields by enumerating the fields you may encode into their +// contents. +constexpr size_t BufferSizeFor() { return 0; } +template <typename... T> +constexpr size_t BufferSizeFor(WireType type, T... tail) { + // tag_type + data + ... + return MaxVarintSize() + + (type == WireType::kVarint ? MaxVarintSize() : // + type == WireType::k64Bit ? 8 : // + type == WireType::k32Bit ? 4 : MaxVarintSize()) + // + BufferSizeFor(tail...); +} + +// absl::Span<const char> represents a view into the un-processed space in a +// buffer during decoding. Decoding functions shrink the span as they go so +// that the same view can be decoded iteratively until all data are processed. +// In general, if the buffer is exhausted but additional bytes are expected by +// the decoder, it will return values as if the additional bytes were zeros. +// Length-delimited fields are an exception - if the encoded length field +// indicates more data bytes than are available in the buffer, the `bytes_value` +// and `string_value` accessors will return truncated views. + +class ProtoField final { + public: + // Consumes bytes from `data` and returns true if there were any bytes to + // decode. + bool DecodeFrom(absl::Span<const char> *data); + uint64_t tag() const { return tag_; } + WireType type() const { return type_; } + + // These value accessors will return nonsense if the data were not encoded in + // the corresponding wiretype from the corresponding C++ (or other language) + // type. + + double double_value() const { return absl::bit_cast<double>(value_); } + float float_value() const { + return absl::bit_cast<float>(static_cast<uint32_t>(value_)); + } + int32_t int32_value() const { return static_cast<int32_t>(value_); } + int64_t int64_value() const { return static_cast<int64_t>(value_); } + int32_t sint32_value() const { + if (value_ % 2) return static_cast<int32_t>(0 - ((value_ - 1) / 2) - 1); + return static_cast<int32_t>(value_ / 2); + } + int64_t sint64_value() const { + if (value_ % 2) return 0 - ((value_ - 1) / 2) - 1; + return value_ / 2; + } + uint32_t uint32_value() const { return static_cast<uint32_t>(value_); } + uint64_t uint64_value() const { return value_; } + bool bool_value() const { return value_ != 0; } + // To decode an enum, call int32_value() and cast to the appropriate type. + // Note that the official C++ proto compiler treats enum fields with values + // that do not correspond to a defined enumerator as unknown fields. + + // To decode fields within a submessage field, call + // `DecodeNextField(field.BytesValue())`. + absl::Span<const char> bytes_value() const { return data_; } + absl::string_view string_value() const { + const auto data = bytes_value(); + return absl::string_view(data.data(), data.size()); + } + // Returns the encoded length of a length-delimited field. This equals + // `bytes_value().size()` except when the latter has been truncated due to + // buffer underrun. + uint64_t encoded_length() const { return value_; } + + private: + uint64_t tag_; + WireType type_; + // For `kTypeVarint`, `kType64Bit`, and `kType32Bit`, holds the decoded value. + // For `kTypeLengthDelimited`, holds the decoded length. + uint64_t value_; + absl::Span<const char> data_; +}; + +} // namespace log_internal +ABSL_NAMESPACE_END +} // namespace absl + +#endif // ABSL_LOG_INTERNAL_PROTO_H_ diff --git a/absl/log/internal/structured.h b/absl/log/internal/structured.h new file mode 100644 index 00000000..8888e7d7 --- /dev/null +++ b/absl/log/internal/structured.h @@ -0,0 +1,57 @@ +// Copyright 2022 The Abseil Authors. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// https://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +// +// ----------------------------------------------------------------------------- +// File: log/internal/structured.h +// ----------------------------------------------------------------------------- + +#ifndef ABSL_LOG_INTERNAL_STRUCTURED_H_ +#define ABSL_LOG_INTERNAL_STRUCTURED_H_ + +#include <ostream> + +#include "absl/base/config.h" +#include "absl/log/internal/log_message.h" +#include "absl/strings/string_view.h" + +namespace absl { +ABSL_NAMESPACE_BEGIN +namespace log_internal { + +class ABSL_MUST_USE_RESULT AsLiteralImpl final { + public: + explicit AsLiteralImpl(absl::string_view str) : str_(str) {} + AsLiteralImpl(const AsLiteralImpl&) = default; + AsLiteralImpl& operator=(const AsLiteralImpl&) = default; + + private: + absl::string_view str_; + + friend std::ostream& operator<<(std::ostream& os, AsLiteralImpl as_literal) { + return os << as_literal.str_; + } + log_internal::LogMessage& AddToMessage(log_internal::LogMessage& m) { + return m.LogString(/* literal = */ true, str_); + } + friend log_internal::LogMessage& operator<<(log_internal::LogMessage& m, + AsLiteralImpl as_literal) { + return as_literal.AddToMessage(m); + } +}; + +} // namespace log_internal +ABSL_NAMESPACE_END +} // namespace absl + +#endif // ABSL_LOG_INTERNAL_STRUCTURED_H_ diff --git a/absl/log/internal/test_actions.cc b/absl/log/internal/test_actions.cc index 6c8a7b13..bb4af17f 100644 --- a/absl/log/internal/test_actions.cc +++ b/absl/log/internal/test_actions.cc @@ -40,16 +40,19 @@ void WriteEntryToStderr::operator()(const absl::LogEntry& entry) const { const std::string source_filename = absl::CHexEscape(entry.source_filename()); const std::string source_basename = absl::CHexEscape(entry.source_basename()); const std::string text_message = absl::CHexEscape(entry.text_message()); - std::cerr << "LogEntry{\n" // - << " source_filename: \"" << source_filename << "\"\n" // - << " source_basename: \"" << source_basename << "\"\n" // - << " source_line: " << entry.source_line() << "\n" // - << " prefix: " << (entry.prefix() ? "true\n" : "false\n") // - << " log_severity: " << entry.log_severity() << "\n" // - << " timestamp: " << entry.timestamp() << "\n" // - << " text_message: \"" << text_message << "\"\n" // - << " verbosity: " << entry.verbosity() - << "\n" // + const std::string encoded_message = absl::CHexEscape(entry.encoded_message()); + std::string encoded_message_str; + std::cerr << "LogEntry{\n" // + << " source_filename: \"" << source_filename << "\"\n" // + << " source_basename: \"" << source_basename << "\"\n" // + << " source_line: " << entry.source_line() << "\n" // + << " prefix: " << (entry.prefix() ? "true\n" : "false\n") // + << " log_severity: " << entry.log_severity() << "\n" // + << " timestamp: " << entry.timestamp() << "\n" // + << " text_message: \"" << text_message << "\"\n" // + << " verbosity: " << entry.verbosity() << "\n" // + << " encoded_message (raw): \"" << encoded_message << "\"\n" // + << encoded_message_str // << "}\n"; } diff --git a/absl/log/internal/test_matchers.h b/absl/log/internal/test_matchers.h index 98cb33d3..c18cb6e9 100644 --- a/absl/log/internal/test_matchers.h +++ b/absl/log/internal/test_matchers.h @@ -79,7 +79,6 @@ namespace log_internal { const std::ostringstream& stream); ::testing::Matcher<const std::string&> DeathTestValidateExpectations(); -// This feature coming soon =). #define ENCODED_MESSAGE(message_matcher) ::testing::_ } // namespace log_internal diff --git a/absl/log/log_entry.h b/absl/log/log_entry.h index 30114c33..41de6e66 100644 --- a/absl/log/log_entry.h +++ b/absl/log/log_entry.h @@ -169,6 +169,15 @@ class LogEntry final { return text_message_with_prefix_and_newline_and_nul_.data(); } + // Returns a serialized protobuf holding the operands streamed into this + // log message. The message definition is not yet published. + // + // The buffer does not outlive the entry; if you need the data later, you must + // copy them. + absl::string_view encoded_message() const ABSL_ATTRIBUTE_LIFETIME_BOUND { + return encoding_; + } + // LogEntry::stacktrace() // // Optional stacktrace, e.g. for `FATAL` logs and failed `CHECK`s. @@ -198,6 +207,7 @@ class LogEntry final { tid_t tid_; absl::Span<const char> text_message_with_prefix_and_newline_and_nul_; size_t prefix_len_; + absl::string_view encoding_; std::string stacktrace_; friend class log_internal::LogEntryTestPeer; diff --git a/absl/log/log_format_test.cc b/absl/log/log_format_test.cc index ad426214..cf087ca8 100644 --- a/absl/log/log_format_test.cc +++ b/absl/log/log_format_test.cc @@ -16,7 +16,9 @@ #include <math.h> #include <iomanip> +#include <ios> #include <limits> +#include <ostream> #include <sstream> #include <string> #include <type_traits> @@ -41,15 +43,16 @@ using ::absl::log_internal::TextPrefix; using ::testing::AllOf; using ::testing::AnyOf; -using ::testing::Eq; -using ::testing::IsEmpty; -using ::testing::Truly; -using ::testing::Types; - using ::testing::Each; +using ::testing::ElementsAre; +using ::testing::Eq; using ::testing::Ge; +using ::testing::IsEmpty; using ::testing::Le; +using ::testing::ResultOf; using ::testing::SizeIs; +using ::testing::Truly; +using ::testing::Types; // Some aspects of formatting streamed data (e.g. pointer handling) are // implementation-defined. Others are buggy in supported implementations. @@ -611,10 +614,11 @@ TYPED_TEST(FloatingPointLogFormatTest, NegativeNaN) { test_sink, Send(AllOf( TextMessage(MatchesOstream(comparison_stream)), - TextMessage(AnyOf(Eq("-nan"), Eq("nan"), Eq("NaN"), - Eq("-nan(ind)"))), ENCODED_MESSAGE(EqualsProto(R"pb(value { str: - "-nan" })pb"))))); - + TextMessage(AnyOf(Eq("-nan"), Eq("nan"), Eq("NaN"), Eq("-nan(ind)"))), + ENCODED_MESSAGE( + AnyOf(EqualsProto(R"pb(value { str: "-nan" })pb"), + EqualsProto(R"pb(value { str: "nan" })pb"), + EqualsProto(R"pb(value { str: "-nan(ind)" })pb")))))); test_sink.StartCapturingLogs(); LOG(INFO) << value; } @@ -1372,9 +1376,12 @@ TEST(ManipulatorLogFormatTest, Endl) { auto comparison_stream = ComparisonStream(); comparison_stream << std::endl; - EXPECT_CALL(test_sink, - Send(AllOf(TextMessage(MatchesOstream(comparison_stream)), - TextMessage(Eq("\n"))))); + EXPECT_CALL( + test_sink, + Send(AllOf( + TextMessage(MatchesOstream(comparison_stream)), + TextMessage(Eq("\n")), + ENCODED_MESSAGE(EqualsProto(R"pb(value { str: "\n" })pb"))))); test_sink.StartCapturingLogs(); LOG(INFO) << std::endl; @@ -1640,26 +1647,32 @@ TEST(ManipulatorLogFormatTest, IOManipsDoNotAffectAbslStringify) { LOG(INFO) << std::hex << p; } -// Tests that verify the behavior when more data are streamed into a `LOG` -// statement than fit in the buffer. -// Structured logging scenario is tested in other unit tests since the output -// is significantly different. -TEST(OverflowTest, TruncatesStrings) { +TEST(StructuredLoggingOverflowTest, TruncatesStrings) { absl::ScopedMockLog test_sink(absl::MockLogDefault::kDisallowUnexpected); - // This message is too long and should be truncated to some unspecified - // size no greater than the buffer size but not too much less either. It - // should be truncated rather than discarded. - constexpr size_t buffer_size = 15000; - - EXPECT_CALL(test_sink, - Send(TextMessage( - AllOf(SizeIs(AllOf(Ge(buffer_size - 256), - Le(buffer_size))), - Each(Eq('x')))))); - - test_sink.StartCapturingLogs(); - LOG(INFO) << std::string(2 * buffer_size, 'x'); + // This message is too long and should be truncated to some unspecified size + // no greater than the buffer size but not too much less either. It should be + // truncated rather than discarded. + EXPECT_CALL( + test_sink, + Send(AllOf( + TextMessage(AllOf( + SizeIs(AllOf(Ge(absl::log_internal::kLogMessageBufferSize - 256), + Le(absl::log_internal::kLogMessageBufferSize))), + Each(Eq('x')))), + ENCODED_MESSAGE(ResultOf( + [](const logging::proto::Event& e) { return e.value(); }, + ElementsAre(ResultOf( + [](const logging::proto::Value& v) { + return std::string(v.str()); + }, + AllOf(SizeIs(AllOf( + Ge(absl::log_internal::kLogMessageBufferSize - 256), + Le(absl::log_internal::kLogMessageBufferSize))), + Each(Eq('x')))))))))); + + test_sink.StartCapturingLogs(); + LOG(INFO) << std::string(2 * absl::log_internal::kLogMessageBufferSize, 'x'); } } // namespace diff --git a/absl/log/structured.h b/absl/log/structured.h new file mode 100644 index 00000000..9ad69fbd --- /dev/null +++ b/absl/log/structured.h @@ -0,0 +1,70 @@ +// Copyright 2022 The Abseil Authors. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// https://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +// +// ----------------------------------------------------------------------------- +// File: log/structured.h +// ----------------------------------------------------------------------------- +// +// This header declares APIs supporting structured logging, allowing log +// statements to be more easily parsed, especially by automated processes. +// +// When structured logging is in use, data streamed into a `LOG` statement are +// encoded as `Value` fields in a `logging.proto.Event` protocol buffer message. +// The individual data are exposed programmatically to `LogSink`s and to the +// user via some log reading tools which are able to query the structured data +// more usefully than would be possible if each message was a single opaque +// string. These helpers allow user code to add additional structure to the +// data they stream. + +#ifndef ABSL_LOG_STRUCTURED_H_ +#define ABSL_LOG_STRUCTURED_H_ + +#include <ostream> + +#include "absl/base/config.h" +#include "absl/log/internal/structured.h" +#include "absl/strings/string_view.h" + +namespace absl { +ABSL_NAMESPACE_BEGIN + +// LogAsLiteral() +// +// Annotates its argument as a string literal so that structured logging +// captures it as a `literal` field instead of a `str` field (the default). +// This does not affect the text representation, only the structure. +// +// Streaming `LogAsLiteral(s)` into a `std::ostream` behaves just like streaming +// `s` directly. +// +// Using `LogAsLiteral()` is occasionally appropriate and useful when proxying +// data logged from another system or another language. For example: +// +// void Logger::LogString(absl::string_view str, absl::LogSeverity severity, +// const char *file, int line) { +// LOG(LEVEL(severity)).AtLocation(file, line) << str; +// } +// void Logger::LogStringLiteral(absl::string_view str, +// absl::LogSeverity severity, const char *file, +// int line) { +// LOG(LEVEL(severity)).AtLocation(file, line) << absl::LogAsLiteral(str); +// } +inline log_internal::AsLiteralImpl LogAsLiteral(absl::string_view s) { + return log_internal::AsLiteralImpl(s); +} + +ABSL_NAMESPACE_END +} // namespace absl + +#endif // ABSL_LOG_STRUCTURED_H_ diff --git a/absl/log/structured_test.cc b/absl/log/structured_test.cc new file mode 100644 index 00000000..490a35d8 --- /dev/null +++ b/absl/log/structured_test.cc @@ -0,0 +1,63 @@ +// +// Copyright 2022 The Abseil Authors. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// https://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +#include "absl/log/structured.h" + +#include <ios> +#include <sstream> +#include <string> + +#include "gmock/gmock.h" +#include "gtest/gtest.h" +#include "absl/base/attributes.h" +#include "absl/log/internal/test_helpers.h" +#include "absl/log/internal/test_matchers.h" +#include "absl/log/log.h" +#include "absl/log/scoped_mock_log.h" + +namespace { +using ::absl::log_internal::MatchesOstream; +using ::absl::log_internal::TextMessage; +using ::testing::Eq; + +auto *test_env ABSL_ATTRIBUTE_UNUSED = ::testing::AddGlobalTestEnvironment( + new absl::log_internal::LogTestEnvironment); + +// Abseil Logging library uses these by default, so we set them on the +// `std::ostream` we compare against too. +std::ios &LoggingDefaults(std::ios &str) { + str.setf(std::ios_base::showbase | std::ios_base::boolalpha | + std::ios_base::internal); + return str; +} + +TEST(StreamingFormatTest, LogAsLiteral) { + std::ostringstream stream; + const std::string not_a_literal("hello world"); + stream << LoggingDefaults << absl::LogAsLiteral(not_a_literal); + + absl::ScopedMockLog sink; + + EXPECT_CALL(sink, + Send(AllOf(TextMessage(MatchesOstream(stream)), + TextMessage(Eq("hello world")), + ENCODED_MESSAGE(EqualsProto( + R"pb(value { literal: "hello world" })pb"))))); + + sink.StartCapturingLogs(); + LOG(INFO) << absl::LogAsLiteral(not_a_literal); +} + +} // namespace |