From 92fdbfb301f8b301b28ab5c99e7361e775c2fb8a Mon Sep 17 00:00:00 2001 From: Gennadiy Rozental Date: Thu, 25 Aug 2022 14:15:03 -0700 Subject: Release the Abseil Logging library PiperOrigin-RevId: 470080638 Change-Id: I8d9ddfabc7704c383ed5a73abf0411f4c58a4bf7 --- absl/log/internal/test_actions.cc | 68 +++++++++++++++++++++++++++++++++++++++ 1 file changed, 68 insertions(+) create mode 100644 absl/log/internal/test_actions.cc (limited to 'absl/log/internal/test_actions.cc') diff --git a/absl/log/internal/test_actions.cc b/absl/log/internal/test_actions.cc new file mode 100644 index 00000000..41ca9887 --- /dev/null +++ b/absl/log/internal/test_actions.cc @@ -0,0 +1,68 @@ +// +// 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/internal/test_actions.h" + +#include +#include +#include + +#include "absl/base/config.h" +#include "absl/log/internal/config.h" +#include "absl/strings/escaping.h" +#include "absl/strings/string_view.h" +#include "absl/time/time.h" + +namespace absl { +ABSL_NAMESPACE_BEGIN +namespace log_internal { + +void WriteToStderrWithFilename::operator()(const absl::LogEntry& entry) const { + std::cerr << message << " (file: " << entry.source_filename() << ")" + << std::endl; +} + +void WriteEntryToStderr::operator()(const absl::LogEntry& entry) const { + if (!message.empty()) std::cerr << message << std::endl; + + std::cerr << "LogEntry{\n" + << " source_filename: \"" + << absl::CHexEscape(entry.source_filename()) << "\"\n" + << " source_basename: \"" + << absl::CHexEscape(entry.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: \"" << absl::CHexEscape(entry.text_message()) + << "\"\n verbosity: " << entry.verbosity() << "\n" + << "}" << std::endl; +} + +void WriteEntryToStderr::operator()(absl::LogSeverity severity, + absl::string_view filename, + absl::string_view log_message) const { + if (!message.empty()) std::cerr << message << std::endl; + + std::cerr << "LogEntry{\n" + << " source_filename: \"" << absl::CHexEscape(filename) << "\"\n" + << " log_severity: " << severity << "\n" + << " text_message: \"" << absl::CHexEscape(log_message) << "}" + << std::endl; +} + +} // namespace log_internal +ABSL_NAMESPACE_END +} // namespace absl -- cgit v1.2.3 From 32e928d29c5edb8a196e876d71a4bb124bff9de2 Mon Sep 17 00:00:00 2001 From: Andy Getzendanner Date: Thu, 3 Nov 2022 18:18:19 -0700 Subject: Small cleanups in logging test helpers PiperOrigin-RevId: 486023797 Change-Id: I0b82754fd40c2d6fb451f304aaf1d795eed8d009 --- absl/log/internal/BUILD.bazel | 2 ++ absl/log/internal/test_actions.cc | 47 ++++++++++++++++++++------------------ absl/log/internal/test_matchers.cc | 2 ++ 3 files changed, 29 insertions(+), 22 deletions(-) (limited to 'absl/log/internal/test_actions.cc') diff --git a/absl/log/internal/BUILD.bazel b/absl/log/internal/BUILD.bazel index 19243a58..3ddae933 100644 --- a/absl/log/internal/BUILD.bazel +++ b/absl/log/internal/BUILD.bazel @@ -230,6 +230,7 @@ cc_library( deps = [ ":config", "//absl/base:config", + "//absl/base:core_headers", "//absl/base:log_severity", "//absl/log:log_entry", "//absl/strings", @@ -265,6 +266,7 @@ cc_library( ":config", ":test_helpers", "//absl/base:config", + "//absl/base:core_headers", "//absl/base:log_severity", "//absl/log:log_entry", "//absl/strings", diff --git a/absl/log/internal/test_actions.cc b/absl/log/internal/test_actions.cc index 41ca9887..c0d04e18 100644 --- a/absl/log/internal/test_actions.cc +++ b/absl/log/internal/test_actions.cc @@ -19,9 +19,11 @@ #include #include +#include "absl/base/attributes.h" #include "absl/base/config.h" #include "absl/log/internal/config.h" #include "absl/strings/escaping.h" +#include "absl/strings/str_cat.h" #include "absl/strings/string_view.h" #include "absl/time/time.h" @@ -30,37 +32,38 @@ ABSL_NAMESPACE_BEGIN namespace log_internal { void WriteToStderrWithFilename::operator()(const absl::LogEntry& entry) const { - std::cerr << message << " (file: " << entry.source_filename() << ")" - << std::endl; + std::cerr << message << " (file: " << entry.source_filename() << ")\n"; } void WriteEntryToStderr::operator()(const absl::LogEntry& entry) const { - if (!message.empty()) std::cerr << message << std::endl; + if (!message.empty()) std::cerr << message << "\n"; - std::cerr << "LogEntry{\n" - << " source_filename: \"" - << absl::CHexEscape(entry.source_filename()) << "\"\n" - << " source_basename: \"" - << absl::CHexEscape(entry.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: \"" << absl::CHexEscape(entry.text_message()) - << "\"\n verbosity: " << entry.verbosity() << "\n" - << "}" << std::endl; + 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" // + << "}\n"; } void WriteEntryToStderr::operator()(absl::LogSeverity severity, absl::string_view filename, absl::string_view log_message) const { - if (!message.empty()) std::cerr << message << std::endl; - - std::cerr << "LogEntry{\n" - << " source_filename: \"" << absl::CHexEscape(filename) << "\"\n" - << " log_severity: " << severity << "\n" - << " text_message: \"" << absl::CHexEscape(log_message) << "}" - << std::endl; + if (!message.empty()) std::cerr << message << "\n"; + const std::string source_filename = absl::CHexEscape(filename); + const std::string text_message = absl::CHexEscape(log_message); + std::cerr << "LogEntry{\n" // + << " source_filename: \"" << source_filename << "\"\n" // + << " log_severity: " << severity << "\n" // + << " text_message: \"" << text_message << "\"\n" // + << "}\n"; } } // namespace log_internal diff --git a/absl/log/internal/test_matchers.cc b/absl/log/internal/test_matchers.cc index ee32617b..10f4111f 100644 --- a/absl/log/internal/test_matchers.cc +++ b/absl/log/internal/test_matchers.cc @@ -17,10 +17,12 @@ #include #include +#include #include #include "gmock/gmock.h" #include "gtest/gtest.h" +#include "absl/base/attributes.h" #include "absl/base/config.h" #include "absl/log/internal/config.h" #include "absl/log/internal/test_helpers.h" -- cgit v1.2.3 From 0c048353d2e7347f148228d785c3f0a8c81e2223 Mon Sep 17 00:00:00 2001 From: Andy Getzendanner Date: Wed, 16 Nov 2022 14:47:18 -0800 Subject: Minor formatting changes in preparation for structured logging... PiperOrigin-RevId: 489044912 Change-Id: I1657dd60bcfa2d0fb4b889f27f4f237325b73f08 --- absl/log/BUILD.bazel | 1 - absl/log/CMakeLists.txt | 4 ---- absl/log/internal/BUILD.bazel | 3 --- absl/log/internal/log_message.cc | 27 ++++++++++++++------------- absl/log/internal/log_message.h | 18 ++++++++++-------- absl/log/internal/test_actions.cc | 4 ++-- absl/log/internal/test_matchers.cc | 1 - absl/log/internal/test_matchers.h | 1 - absl/log/log_format_test.cc | 19 ++++++++++--------- 9 files changed, 36 insertions(+), 42 deletions(-) (limited to 'absl/log/internal/test_actions.cc') diff --git a/absl/log/BUILD.bazel b/absl/log/BUILD.bazel index 261a3384..3e9d1421 100644 --- a/absl/log/BUILD.bazel +++ b/absl/log/BUILD.bazel @@ -322,7 +322,6 @@ cc_test( deps = [ ":log", ":scoped_mock_log", - "//absl/log/internal:config", "//absl/log/internal:test_matchers", "//absl/strings", "//absl/strings:str_format", diff --git a/absl/log/CMakeLists.txt b/absl/log/CMakeLists.txt index 25531209..0bc8a22f 100644 --- a/absl/log/CMakeLists.txt +++ b/absl/log/CMakeLists.txt @@ -145,7 +145,6 @@ absl_cc_library( absl::inlined_vector absl::examine_stack absl::log_internal_append_truncated - absl::log_internal_config absl::log_internal_format absl::log_internal_globals absl::log_internal_log_sink_set @@ -253,7 +252,6 @@ absl_cc_library( DEPS absl::config absl::log_entry - absl::log_internal_config absl::log_severity absl::strings absl::time @@ -295,7 +293,6 @@ absl_cc_library( DEPS absl::config absl::log_entry - absl::log_internal_config absl::log_internal_test_helpers absl::log_severity absl::strings @@ -696,7 +693,6 @@ absl_cc_test( ${ABSL_DEFAULT_LINKOPTS} DEPS absl::log - absl::log_internal_config absl::log_internal_test_matchers absl::scoped_mock_log absl::str_format diff --git a/absl/log/internal/BUILD.bazel b/absl/log/internal/BUILD.bazel index b4eb1df1..4f600753 100644 --- a/absl/log/internal/BUILD.bazel +++ b/absl/log/internal/BUILD.bazel @@ -134,7 +134,6 @@ cc_library( ], deps = [ ":append_truncated", - ":config", ":format", ":globals", ":log_sink_set", @@ -241,7 +240,6 @@ cc_library( copts = ABSL_DEFAULT_COPTS, linkopts = ABSL_DEFAULT_LINKOPTS, deps = [ - ":config", "//absl/base:config", "//absl/base:core_headers", "//absl/base:log_severity", @@ -276,7 +274,6 @@ cc_library( copts = ABSL_DEFAULT_COPTS, linkopts = ABSL_DEFAULT_LINKOPTS, deps = [ - ":config", ":test_helpers", "//absl/base:config", "//absl/base:core_headers", diff --git a/absl/log/internal/log_message.cc b/absl/log/internal/log_message.cc index 648086e9..8329597e 100644 --- a/absl/log/internal/log_message.cc +++ b/absl/log/internal/log_message.cc @@ -42,7 +42,6 @@ #include "absl/debugging/internal/examine_stack.h" #include "absl/log/globals.h" #include "absl/log/internal/append_truncated.h" -#include "absl/log/internal/config.h" #include "absl/log/internal/globals.h" #include "absl/log/internal/log_format.h" #include "absl/log/internal/log_sink_set.h" @@ -87,8 +86,8 @@ void WriteToStream(const char* data, void* os) { // A write-only `std::streambuf` that writes into an `absl::Span`. // -// This class is responsible for writing a metadata prefix just before the first -// data are streamed in. The metadata are subject to change (cf. +// 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 @@ -96,7 +95,8 @@ void WriteToStream(const char* data, void* os) { // streamed in. class LogEntryStreambuf final : public std::streambuf { public: - explicit LogEntryStreambuf(absl::Span buf, const absl::LogEntry& entry) + explicit LogEntryStreambuf(absl::Span 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`. @@ -107,7 +107,8 @@ class LogEntryStreambuf final : public std::streambuf { absl::Span Finalize() { assert(!finalized_); - // If no data were ever streamed in, this is where we must write the prefix. + // 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(); @@ -140,8 +141,8 @@ class LogEntryStreambuf final : public std::streambuf { private: void Initialize() { - // Here we reserve two bytes in our buffer to guarantee `Finalize` space to - // add a trailing "\n\0". + // 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()) { @@ -157,7 +158,8 @@ class LogEntryStreambuf final : public std::streambuf { } size_t Append(absl::string_view data) { - absl::Span remaining(pptr(), static_cast(epptr() - pptr())); + absl::Span remaining(pptr(), + static_cast(epptr() - pptr())); const size_t written = log_internal::AppendTruncated(data, remaining); pbump(static_cast(written)); return written; @@ -202,7 +204,7 @@ LogMessage::LogMessageData::LogMessageData(const char* file, int line, absl::LogSeverity severity, absl::Time timestamp) : extra_sinks_only(false), - streambuf_(absl::MakeSpan(string_buf), entry) { + streambuf_(absl::MakeSpan(string_buf), entry) { entry.full_filename_ = file; entry.base_filename_ = Basename(file); entry.line_ = line; @@ -216,8 +218,7 @@ LogMessage::LogMessageData::LogMessageData(const char* file, int line, LogMessage::LogMessage(const char* file, int line, absl::LogSeverity severity) : data_( absl::make_unique(file, line, severity, absl::Now())) - , - stream_(&data_->streambuf_) +, stream_(&data_->streambuf_) { data_->first_fatal = false; data_->is_perror = false; @@ -225,8 +226,8 @@ LogMessage::LogMessage(const char* file, int line, absl::LogSeverity severity) // 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. + // `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, diff --git a/absl/log/internal/log_message.h b/absl/log/internal/log_message.h index 992bb630..8868f8c8 100644 --- a/absl/log/internal/log_message.h +++ b/absl/log/internal/log_message.h @@ -37,7 +37,6 @@ #include "absl/base/config.h" #include "absl/base/internal/errno_saver.h" #include "absl/base/log_severity.h" -#include "absl/log/internal/config.h" #include "absl/log/internal/nullguard.h" #include "absl/log/log_entry.h" #include "absl/log/log_sink.h" @@ -234,9 +233,10 @@ class StringifySink final { }; // Note: the following is declared `ABSL_ATTRIBUTE_NOINLINE` -template ::value, - int>::type> +template < + typename T, + typename std::enable_if::value, + int>::type> LogMessage& LogMessage::operator<<(const T& v) { StringifySink sink(*this); // Replace with public API. @@ -245,9 +245,10 @@ LogMessage& LogMessage::operator<<(const T& v) { } // Note: the following is declared `ABSL_ATTRIBUTE_NOINLINE` -template ::value, - int>::type> +template < + typename T, + typename std::enable_if::value, + int>::type> LogMessage& LogMessage::operator<<(const T& v) { stream_ << log_internal::NullGuard().Guard(v); return *this; @@ -299,7 +300,8 @@ 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); +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/test_actions.cc b/absl/log/internal/test_actions.cc index c0d04e18..6c8a7b13 100644 --- a/absl/log/internal/test_actions.cc +++ b/absl/log/internal/test_actions.cc @@ -21,7 +21,6 @@ #include "absl/base/attributes.h" #include "absl/base/config.h" -#include "absl/log/internal/config.h" #include "absl/strings/escaping.h" #include "absl/strings/str_cat.h" #include "absl/strings/string_view.h" @@ -49,7 +48,8 @@ void WriteEntryToStderr::operator()(const absl::LogEntry& entry) const { << " log_severity: " << entry.log_severity() << "\n" // << " timestamp: " << entry.timestamp() << "\n" // << " text_message: \"" << text_message << "\"\n" // - << " verbosity: " << entry.verbosity() << "\n" // + << " verbosity: " << entry.verbosity() + << "\n" // << "}\n"; } diff --git a/absl/log/internal/test_matchers.cc b/absl/log/internal/test_matchers.cc index 10f4111f..72ca704e 100644 --- a/absl/log/internal/test_matchers.cc +++ b/absl/log/internal/test_matchers.cc @@ -24,7 +24,6 @@ #include "gtest/gtest.h" #include "absl/base/attributes.h" #include "absl/base/config.h" -#include "absl/log/internal/config.h" #include "absl/log/internal/test_helpers.h" #include "absl/strings/string_view.h" #include "absl/time/clock.h" diff --git a/absl/log/internal/test_matchers.h b/absl/log/internal/test_matchers.h index b8179ccc..98cb33d3 100644 --- a/absl/log/internal/test_matchers.h +++ b/absl/log/internal/test_matchers.h @@ -30,7 +30,6 @@ #include "gtest/gtest.h" #include "absl/base/config.h" #include "absl/base/log_severity.h" -#include "absl/log/internal/config.h" #include "absl/log/internal/test_helpers.h" #include "absl/log/log_entry.h" #include "absl/strings/string_view.h" diff --git a/absl/log/log_format_test.cc b/absl/log/log_format_test.cc index f88650fe..ad426214 100644 --- a/absl/log/log_format_test.cc +++ b/absl/log/log_format_test.cc @@ -26,7 +26,6 @@ #endif #include "gmock/gmock.h" #include "gtest/gtest.h" -#include "absl/log/internal/config.h" #include "absl/log/internal/test_matchers.h" #include "absl/log/log.h" #include "absl/log/scoped_mock_log.h" @@ -612,8 +611,9 @@ 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(EqualsProto(R"pb(value { str: + "-nan" })pb"))))); test_sink.StartCapturingLogs(); LOG(INFO) << value; @@ -1642,19 +1642,20 @@ TEST(ManipulatorLogFormatTest, IOManipsDoNotAffectAbslStringify) { // 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. +// Structured logging scenario is tested in other unit tests since the output +// is significantly different. TEST(OverflowTest, 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. + // 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))), + AllOf(SizeIs(AllOf(Ge(buffer_size - 256), + Le(buffer_size))), Each(Eq('x')))))); test_sink.StartCapturingLogs(); -- cgit v1.2.3 From ebab79b5783b3298ee2f31251174c660c322d7ef Mon Sep 17 00:00:00 2001 From: Andy Getzendanner Date: Thu, 17 Nov 2022 12:17:17 -0800 Subject: 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 --- absl/log/BUILD.bazel | 29 ++++ absl/log/CMakeLists.txt | 73 ++++++++++ absl/log/internal/BUILD.bazel | 40 +++++- absl/log/internal/log_message.cc | 286 ++++++++++++++++++++++++-------------- absl/log/internal/log_message.h | 70 ++++++---- absl/log/internal/proto.cc | 214 ++++++++++++++++++++++++++++ absl/log/internal/proto.h | 267 +++++++++++++++++++++++++++++++++++ absl/log/internal/structured.h | 57 ++++++++ absl/log/internal/test_actions.cc | 23 +-- absl/log/internal/test_matchers.h | 1 - absl/log/log_entry.h | 10 ++ absl/log/log_format_test.cc | 73 ++++++---- absl/log/structured.h | 70 ++++++++++ absl/log/structured_test.cc | 63 +++++++++ 14 files changed, 1097 insertions(+), 179 deletions(-) create mode 100644 absl/log/internal/proto.cc create mode 100644 absl/log/internal/proto.h create mode 100644 absl/log/internal/structured.h create mode 100644 absl/log/structured.h create mode 100644 absl/log/structured_test.cc (limited to 'absl/log/internal/test_actions.cc') 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 @@ -126,6 +126,25 @@ absl_cc_library( absl::time ) +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 @@ -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", @@ -232,6 +233,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, @@ -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& dst, absl::Span 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`. -// -// 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 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 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(idx)); - sputc('\n'); - sputc('\0'); - finalized_ = true; - return absl::Span(pbase(), - static_cast(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( - Append(absl::string_view(s, static_cast(n)))); - } - - int overflow(int ch = EOF) override { - if (pbase() == nullptr) Initialize(); - if (ch == EOF) return 0; - if (pptr() == epptr()) return EOF; - *pptr() = static_cast(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 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(prefix_len_)); - } - } - - size_t Append(absl::string_view data) { - absl::Span remaining(pptr(), - static_cast(epptr() - pptr())); - const size_t written = log_internal::AppendTruncated(data, remaining); - pbump(static_cast(written)); - return written; - } - - const absl::Span 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 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 encoded_remaining; + // A formatted string message is built in `string_buf`. std::array 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 encoded_data( + encoded_buf.data(), + static_cast(encoded_remaining.data() - encoded_buf.data())); + // `string_remaining` is the suffix of `string_buf` that has not been filled + // yet. + absl::Span 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(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(file, line, severity, absl::Now())) -, stream_(&data_->streambuf_) -{ + : data_(absl::make_unique(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(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 contents(pbase(), + static_cast(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<< (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 encoded_remaining_copy_; + absl::Span message_start_; + absl::Span 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 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::value, - int>::type> +template ::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::value, - int>::type> +template ::value, + int>::type> LogMessage& LogMessage::operator<<(const T& v) { - stream_ << log_internal::NullGuard().Guard(v); + OstreamView view(*data_); + view.stream() << log_internal::NullGuard().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 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 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 +#include +#include +#include + +#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 *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(type); +} +} // namespace + +bool EncodeVarint(uint64_t tag, uint64_t value, absl::Span *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 *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 *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 value, + absl::Span *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 value, + absl::Span *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 EncodeMessageStart( + uint64_t tag, uint64_t max_size, absl::Span *buf) { + const uint64_t tag_type = MakeTagType(tag, WireType::kLengthDelimited); + const uint64_t tag_type_size = VarintSize(tag_type); + max_size = std::min(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(); + } + EncodeRawVarint(tag_type, tag_type_size, buf); + const absl::Span ret = buf->subspan(0, length_size); + EncodeRawVarint(0, length_size, buf); + return ret; +} + +void EncodeMessageLength(absl::Span msg, const absl::Span *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 *buf) { + uint64_t value = 0; + size_t s = 0; + while (s < buf->size()) { + value |= static_cast(static_cast((*buf)[s]) & 0x7f) + << 7 * s; + if (!((*buf)[s++] & 0x80)) break; + } + buf->remove_prefix(s); + return value; +} + +uint64_t Decode64Bit(absl::Span *buf) { + uint64_t value = 0; + size_t s = 0; + while (s < buf->size()) { + value |= static_cast(static_cast((*buf)[s])) + << 8 * s; + if (++s == sizeof(value)) break; + } + buf->remove_prefix(s); + return value; +} + +uint32_t Decode32Bit(absl::Span *buf) { + uint32_t value = 0; + size_t s = 0; + while (s < buf->size()) { + value |= static_cast(static_cast((*buf)[s])) + << 8 * s; + if (++s == sizeof(value)) break; + } + buf->remove_prefix(s); + return value; +} +} // namespace + +bool ProtoField::DecodeFrom(absl::Span *data) { + if (data->empty()) return false; + const uint64_t tag_type = DecodeVarint(data); + tag_ = tag_type >> 3; + type_ = static_cast(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(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 +#include +#include + +#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 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 *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 *buf) { + if (value < 0) + return EncodeVarint(tag, 2 * static_cast(-(value + 1)) + 1, buf); + return EncodeVarint(tag, 2 * static_cast(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 *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 *buf) { + return Encode64Bit(tag, absl::bit_cast(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 *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 *buf) { + return Encode32Bit(tag, absl::bit_cast(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 value, + absl::Span *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 value, + absl::Span *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 *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 *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 EncodeMessageStart(uint64_t tag, + uint64_t max_size, + absl::Span *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 msg, const absl::Span *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::min)()); +} +constexpr uint64_t MaxVarintSize() { + return VarintSize((std::numeric_limits::max)()); +} + +constexpr uint64_t MaxVarintForSize(size_t size) { + return size >= 10 ? (std::numeric_limits::max)() + : (static_cast(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 +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 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 *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(value_); } + float float_value() const { + return absl::bit_cast(static_cast(value_)); + } + int32_t int32_value() const { return static_cast(value_); } + int64_t int64_value() const { return static_cast(value_); } + int32_t sint32_value() const { + if (value_ % 2) return static_cast(0 - ((value_ - 1) / 2) - 1); + return static_cast(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(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 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 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 + +#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 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 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 #include +#include #include +#include #include #include #include @@ -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 + +#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 +#include +#include + +#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 -- cgit v1.2.3 From 9a7e8e36300c6d89c7f9a2539f7aabf8e0031106 Mon Sep 17 00:00:00 2001 From: Andy Getzendanner Date: Mon, 21 Nov 2022 21:17:53 -0800 Subject: Zero encoded_remaining when a string field doesn't fit, so that we don't leave partial data in the buffer (all decoders should ignore it anyway) and to be sure that we don't try to put any subsequent operands in either (there shouldn't be enough space). PiperOrigin-RevId: 490143656 Change-Id: I4d743dd9214013fbd151478ef662d50affd5ff7a --- absl/log/BUILD.bazel | 1 + absl/log/CMakeLists.txt | 1 + absl/log/internal/log_message.cc | 57 +++++---- absl/log/internal/log_message.h | 18 +-- absl/log/internal/proto.cc | 3 +- absl/log/internal/structured.h | 7 +- absl/log/internal/test_actions.cc | 1 + absl/log/internal/test_matchers.cc | 172 +++++++++++++++++---------- absl/log/internal/test_matchers.h | 6 + absl/log/log_format_test.cc | 234 +++++++++++++++++++++++++++++++++---- 10 files changed, 382 insertions(+), 118 deletions(-) (limited to 'absl/log/internal/test_actions.cc') diff --git a/absl/log/BUILD.bazel b/absl/log/BUILD.bazel index 733b0c3f..b5ce616c 100644 --- a/absl/log/BUILD.bazel +++ b/absl/log/BUILD.bazel @@ -332,6 +332,7 @@ cc_test( copts = ABSL_TEST_COPTS, linkopts = ABSL_DEFAULT_LINKOPTS, deps = [ + ":check", ":log", ":scoped_mock_log", "//absl/log/internal:test_matchers", diff --git a/absl/log/CMakeLists.txt b/absl/log/CMakeLists.txt index 2337d0c0..2ab08d81 100644 --- a/absl/log/CMakeLists.txt +++ b/absl/log/CMakeLists.txt @@ -745,6 +745,7 @@ absl_cc_test( LINKOPTS ${ABSL_DEFAULT_LINKOPTS} DEPS + absl::check absl::log absl::log_internal_test_matchers absl::scoped_mock_log diff --git a/absl/log/internal/log_message.cc b/absl/log/internal/log_message.cc index b7313551..6b4804f1 100644 --- a/absl/log/internal/log_message.cc +++ b/absl/log/internal/log_message.cc @@ -345,11 +345,13 @@ void LogMessage::FailQuietly() { } LogMessage& LogMessage::operator<<(const std::string& v) { - return LogString(false, v); + CopyToEncodedBuffer(v, StringType::kNotLiteral); + return *this; } LogMessage& LogMessage::operator<<(absl::string_view v) { - return LogString(false, v); + CopyToEncodedBuffer(v, StringType::kNotLiteral); + return *this; } LogMessage& LogMessage::operator<<(std::ostream& (*m)(std::ostream& os)) { OstreamView view(*data_); @@ -424,27 +426,28 @@ LogMessage::OstreamView::OstreamView(LogMessageData& message_data) &encoded_remaining_copy_); string_start_ = EncodeMessageStart(ValueTag::kString, encoded_remaining_copy_.size(), - &encoded_remaining_copy_); + &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 contents(pbase(), - static_cast(pptr() - pbase())); - encoded_remaining_copy_.remove_prefix(contents.size()); + data_.manipulated.rdbuf(nullptr); 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. + // The second field header didn't fit. Whether the first one did or not, we + // shouldn't commit `encoded_remaining_copy_`, and we also need to zero the + // size of `data_->encoded_remaining` so that no more data are 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_; + return; } - data_.manipulated.rdbuf(nullptr); + const absl::Span contents(pbase(), + static_cast(pptr() - pbase())); + if (contents.empty()) return; + encoded_remaining_copy_.remove_prefix(contents.size()); + EncodeMessageLength(string_start_, &encoded_remaining_copy_); + EncodeMessageLength(message_start_, &encoded_remaining_copy_); + data_.encoded_remaining = encoded_remaining_copy_; } std::ostream& LogMessage::OstreamView::stream() { return data_.manipulated; } @@ -511,21 +514,31 @@ void LogMessage::LogBacktraceIfNeeded() { 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. +// Encodes into `data_->encoded_remaining` a partial `logging.proto.Event` +// containing the specified string data using a `Value` field appropriate to +// `str_type`. Truncates `str` if necessary, but emits nothing and marks the +// buffer full if even the field headers do not fit. +void LogMessage::CopyToEncodedBuffer(absl::string_view str, + StringType str_type) { 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)) { + // If the `logging.proto.Event.value` field header did not fit, + // `EncodeMessageStart` will have zeroed `encoded_remaining_copy`'s size and + // `EncodeStringTruncate` will fail too. + if (EncodeStringTruncate(str_type == StringType::kLiteral + ? ValueTag::kStringLiteral + : ValueTag::kString, + str, &encoded_remaining_copy)) { + // The string may have been truncated, but the field header fit. EncodeMessageLength(start, &encoded_remaining_copy); data_->encoded_remaining = encoded_remaining_copy; + } else { + // The field header(s) did not fit; zero `encoded_remaining` so we don't + // write anything else later. + data_->encoded_remaining.remove_suffix(data_->encoded_remaining.size()); } - 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 5914a535..7302dde0 100644 --- a/absl/log/internal/log_message.h +++ b/absl/log/internal/log_message.h @@ -216,6 +216,13 @@ class LogMessage { absl::Span string_start_; }; + enum class StringType { + kLiteral, + kNotLiteral, + }; + void CopyToEncodedBuffer(absl::string_view str, + StringType str_type) ABSL_ATTRIBUTE_NOINLINE; + // Returns `true` if the message is fatal or enabled debug-fatal. bool IsFatal() const; @@ -228,9 +235,6 @@ 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). @@ -282,15 +286,15 @@ LogMessage& LogMessage::operator<<(const T& v) { template LogMessage& LogMessage::operator<<(const char (&buf)[SIZE]) { - const bool literal = true; - return LogString(literal, buf); + CopyToEncodedBuffer(buf, StringType::kLiteral); + return *this; } // Note: the following is declared `ABSL_ATTRIBUTE_NOINLINE` template LogMessage& LogMessage::operator<<(char (&buf)[SIZE]) { - const bool literal = false; - return LogString(literal, buf); + CopyToEncodedBuffer(buf, StringType::kNotLiteral); + return *this; } // 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 diff --git a/absl/log/internal/proto.cc b/absl/log/internal/proto.cc index 80d78eed..86c459b0 100644 --- a/absl/log/internal/proto.cc +++ b/absl/log/internal/proto.cc @@ -106,7 +106,8 @@ bool EncodeBytesTruncate(uint64_t tag, absl::Span value, 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); + const uint64_t length_size = + VarintSize(std::min(length, buf->size())); 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() - diff --git a/absl/log/internal/structured.h b/absl/log/internal/structured.h index 8888e7d7..08caea66 100644 --- a/absl/log/internal/structured.h +++ b/absl/log/internal/structured.h @@ -41,12 +41,13 @@ class ABSL_MUST_USE_RESULT AsLiteralImpl final { 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_); + void AddToMessage(log_internal::LogMessage& m) { + m.CopyToEncodedBuffer(str_, log_internal::LogMessage::StringType::kLiteral); } friend log_internal::LogMessage& operator<<(log_internal::LogMessage& m, AsLiteralImpl as_literal) { - return as_literal.AddToMessage(m); + as_literal.AddToMessage(m); + return m; } }; diff --git a/absl/log/internal/test_actions.cc b/absl/log/internal/test_actions.cc index bb4af17f..bdfd6377 100644 --- a/absl/log/internal/test_actions.cc +++ b/absl/log/internal/test_actions.cc @@ -18,6 +18,7 @@ #include #include #include +#include #include "absl/base/attributes.h" #include "absl/base/config.h" diff --git a/absl/log/internal/test_matchers.cc b/absl/log/internal/test_matchers.cc index 72ca704e..8c6515c4 100644 --- a/absl/log/internal/test_matchers.cc +++ b/absl/log/internal/test_matchers.cc @@ -15,6 +15,7 @@ #include "absl/log/internal/test_matchers.h" +#include #include #include #include @@ -32,74 +33,138 @@ namespace absl { ABSL_NAMESPACE_BEGIN namespace log_internal { +namespace { +using ::testing::_; +using ::testing::AllOf; +using ::testing::Ge; +using ::testing::HasSubstr; +using ::testing::MakeMatcher; +using ::testing::Matcher; +using ::testing::MatcherInterface; +using ::testing::MatchResultListener; +using ::testing::Not; +using ::testing::Property; +using ::testing::ResultOf; +using ::testing::Truly; + +class AsStringImpl final + : public MatcherInterface { + public: + explicit AsStringImpl( + const Matcher& str_matcher) + : str_matcher_(str_matcher) {} + bool MatchAndExplain( + absl::string_view actual, + MatchResultListener* listener) const override { + return str_matcher_.MatchAndExplain(std::string(actual), listener); + } + void DescribeTo(std::ostream* os) const override { + return str_matcher_.DescribeTo(os); + } + + void DescribeNegationTo(std::ostream* os) const override { + return str_matcher_.DescribeNegationTo(os); + } + + private: + const Matcher str_matcher_; +}; + +class MatchesOstreamImpl final + : public MatcherInterface { + public: + explicit MatchesOstreamImpl(std::string expected) + : expected_(std::move(expected)) {} + bool MatchAndExplain(absl::string_view actual, + MatchResultListener*) const override { + return actual == expected_; + } + void DescribeTo(std::ostream* os) const override { + *os << "matches the contents of the ostringstream, which are \"" + << expected_ << "\""; + } + + void DescribeNegationTo(std::ostream* os) const override { + *os << "does not match the contents of the ostringstream, which are \"" + << expected_ << "\""; + } -::testing::Matcher SourceFilename( - const ::testing::Matcher& source_filename) { + private: + const std::string expected_; +}; +} // namespace + +Matcher AsString( + const Matcher& str_matcher) { + return MakeMatcher(new AsStringImpl(str_matcher)); +} + +Matcher SourceFilename( + const Matcher& source_filename) { return Property("source_filename", &absl::LogEntry::source_filename, source_filename); } -::testing::Matcher SourceBasename( - const ::testing::Matcher& source_basename) { +Matcher SourceBasename( + const Matcher& source_basename) { return Property("source_basename", &absl::LogEntry::source_basename, source_basename); } -::testing::Matcher SourceLine( - const ::testing::Matcher& source_line) { +Matcher SourceLine( + const Matcher& source_line) { return Property("source_line", &absl::LogEntry::source_line, source_line); } -::testing::Matcher Prefix( - const ::testing::Matcher& prefix) { +Matcher Prefix( + const Matcher& prefix) { return Property("prefix", &absl::LogEntry::prefix, prefix); } -::testing::Matcher LogSeverity( - const ::testing::Matcher& log_severity) { +Matcher LogSeverity( + const Matcher& log_severity) { return Property("log_severity", &absl::LogEntry::log_severity, log_severity); } -::testing::Matcher Timestamp( - const ::testing::Matcher& timestamp) { +Matcher Timestamp( + const Matcher& timestamp) { return Property("timestamp", &absl::LogEntry::timestamp, timestamp); } -::testing::Matcher TimestampInMatchWindow() { +Matcher TimestampInMatchWindow() { return Property("timestamp", &absl::LogEntry::timestamp, - ::testing::AllOf(::testing::Ge(absl::Now()), - ::testing::Truly([](absl::Time arg) { - return arg <= absl::Now(); - }))); + AllOf(Ge(absl::Now()), Truly([](absl::Time arg) { + return arg <= absl::Now(); + }))); } -::testing::Matcher ThreadID( - const ::testing::Matcher& tid) { +Matcher ThreadID( + const Matcher& tid) { return Property("tid", &absl::LogEntry::tid, tid); } -::testing::Matcher TextMessageWithPrefixAndNewline( - const ::testing::Matcher& +Matcher TextMessageWithPrefixAndNewline( + const Matcher& text_message_with_prefix_and_newline) { return Property("text_message_with_prefix_and_newline", &absl::LogEntry::text_message_with_prefix_and_newline, text_message_with_prefix_and_newline); } -::testing::Matcher TextMessageWithPrefix( - const ::testing::Matcher& text_message_with_prefix) { +Matcher TextMessageWithPrefix( + const Matcher& text_message_with_prefix) { return Property("text_message_with_prefix", &absl::LogEntry::text_message_with_prefix, text_message_with_prefix); } -::testing::Matcher TextMessage( - const ::testing::Matcher& text_message) { +Matcher TextMessage( + const Matcher& text_message) { return Property("text_message", &absl::LogEntry::text_message, text_message); } -::testing::Matcher TextPrefix( - const ::testing::Matcher& text_prefix) { +Matcher TextPrefix( + const Matcher& text_prefix) { return ResultOf( [](const absl::LogEntry& entry) { absl::string_view msg = entry.text_message_with_prefix(); @@ -108,42 +173,25 @@ namespace log_internal { }, text_prefix); } +Matcher RawEncodedMessage( + const Matcher& raw_encoded_message) { + return Property("encoded_message", &absl::LogEntry::encoded_message, + raw_encoded_message); +} -::testing::Matcher Verbosity( - const ::testing::Matcher& verbosity) { +Matcher Verbosity( + const Matcher& verbosity) { return Property("verbosity", &absl::LogEntry::verbosity, verbosity); } -::testing::Matcher Stacktrace( - const ::testing::Matcher& stacktrace) { +Matcher Stacktrace( + const Matcher& stacktrace) { return Property("stacktrace", &absl::LogEntry::stacktrace, stacktrace); } -class MatchesOstreamImpl final - : public ::testing::MatcherInterface { - public: - explicit MatchesOstreamImpl(std::string expected) - : expected_(std::move(expected)) {} - bool MatchAndExplain(absl::string_view actual, - ::testing::MatchResultListener*) const override { - return actual == expected_; - } - void DescribeTo(std::ostream* os) const override { - *os << "matches the contents of the ostringstream, which are \"" - << expected_ << "\""; - } - - void DescribeNegationTo(std::ostream* os) const override { - *os << "does not match the contents of the ostringstream, which are \"" - << expected_ << "\""; - } - - private: - const std::string expected_; -}; -::testing::Matcher MatchesOstream( +Matcher MatchesOstream( const std::ostringstream& stream) { - return ::testing::MakeMatcher(new MatchesOstreamImpl(stream.str())); + return MakeMatcher(new MatchesOstreamImpl(stream.str())); } // We need to validate what is and isn't logged as the process dies due to @@ -152,16 +200,16 @@ class MatchesOstreamImpl final // Instead, we use the mock actions `DeathTestExpectedLogging` and // `DeathTestUnexpectedLogging` to write specific phrases to `stderr` that we // can validate in the parent process using this matcher. -::testing::Matcher DeathTestValidateExpectations() { +Matcher DeathTestValidateExpectations() { if (log_internal::LoggingEnabledAt(absl::LogSeverity::kFatal)) { - return ::testing::Matcher(::testing::AllOf( - ::testing::HasSubstr("Mock received expected entry"), - Not(::testing::HasSubstr("Mock received unexpected entry")))); + return Matcher( + AllOf(HasSubstr("Mock received expected entry"), + Not(HasSubstr("Mock received unexpected entry")))); } // If `FATAL` logging is disabled, neither message should have been written. - return ::testing::Matcher(::testing::AllOf( - Not(::testing::HasSubstr("Mock received expected entry")), - Not(::testing::HasSubstr("Mock received unexpected entry")))); + return Matcher( + AllOf(Not(HasSubstr("Mock received expected entry")), + Not(HasSubstr("Mock received unexpected entry")))); } } // namespace log_internal diff --git a/absl/log/internal/test_matchers.h b/absl/log/internal/test_matchers.h index c18cb6e9..fc653a91 100644 --- a/absl/log/internal/test_matchers.h +++ b/absl/log/internal/test_matchers.h @@ -38,6 +38,10 @@ namespace absl { ABSL_NAMESPACE_BEGIN namespace log_internal { +// In some configurations, Googletest's string matchers (e.g. +// `::testing::EndsWith`) need help to match `absl::string_view`. +::testing::Matcher AsString( + const ::testing::Matcher& str_matcher); // These matchers correspond to the components of `absl::LogEntry`. ::testing::Matcher SourceFilename( @@ -79,6 +83,8 @@ namespace log_internal { const std::ostringstream& stream); ::testing::Matcher DeathTestValidateExpectations(); +::testing::Matcher RawEncodedMessage( + const ::testing::Matcher& raw_encoded_message); #define ENCODED_MESSAGE(message_matcher) ::testing::_ } // namespace log_internal diff --git a/absl/log/log_format_test.cc b/absl/log/log_format_test.cc index cf087ca8..5ff6f159 100644 --- a/absl/log/log_format_test.cc +++ b/absl/log/log_format_test.cc @@ -28,6 +28,7 @@ #endif #include "gmock/gmock.h" #include "gtest/gtest.h" +#include "absl/log/check.h" #include "absl/log/internal/test_matchers.h" #include "absl/log/log.h" #include "absl/log/scoped_mock_log.h" @@ -37,21 +38,20 @@ #include "absl/strings/string_view.h" namespace { +using ::absl::log_internal::AsString; using ::absl::log_internal::MatchesOstream; +using ::absl::log_internal::RawEncodedMessage; using ::absl::log_internal::TextMessage; using ::absl::log_internal::TextPrefix; - using ::testing::AllOf; using ::testing::AnyOf; using ::testing::Each; -using ::testing::ElementsAre; +using ::testing::EndsWith; 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 @@ -72,15 +72,12 @@ TEST(LogFormatTest, NoMessage) { const int log_line = __LINE__ + 1; auto do_log = [] { LOG(INFO); }; - EXPECT_CALL( - test_sink, - Send(AllOf( - TextMessage(MatchesOstream(ComparisonStream())), - TextPrefix(Truly([=](absl::string_view msg) { - return absl::EndsWith( - msg, absl::StrCat(" log_format_test.cc:", log_line, "] ")); - })), - TextMessage(IsEmpty()), ENCODED_MESSAGE(EqualsProto(R"pb()pb"))))); + EXPECT_CALL(test_sink, + Send(AllOf(TextMessage(MatchesOstream(ComparisonStream())), + TextPrefix(AsString(EndsWith(absl::StrCat( + " log_format_test.cc:", log_line, "] ")))), + TextMessage(IsEmpty()), + ENCODED_MESSAGE(EqualsProto(R"pb()pb"))))); test_sink.StartCapturingLogs(); do_log(); @@ -1660,19 +1657,210 @@ TEST(StructuredLoggingOverflowTest, TruncatesStrings) { 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')))))))))); + ENCODED_MESSAGE(HasOneStrThat(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'); } +struct StringLike { + absl::string_view data; +}; +std::ostream& operator<<(std::ostream& os, StringLike str) { + return os << str.data; +} + +TEST(StructuredLoggingOverflowTest, TruncatesInsertionOperators) { + 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. + 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(HasOneStrThat(AllOf( + SizeIs(AllOf(Ge(absl::log_internal::kLogMessageBufferSize - 256), + Le(absl::log_internal::kLogMessageBufferSize))), + Each(Eq('x')))))))); + + test_sink.StartCapturingLogs(); + LOG(INFO) << StringLike{ + std::string(2 * absl::log_internal::kLogMessageBufferSize, 'x')}; +} + +// Returns the size of the largest string that will fit in a `LOG` message +// buffer with no prefix. +size_t MaxLogFieldLengthNoPrefix() { + class StringLengthExtractorSink : public absl::LogSink { + public: + void Send(const absl::LogEntry& entry) override { + CHECK_EQ(size_, -1); + CHECK_EQ(entry.text_message().find_first_not_of('x'), + absl::string_view::npos); + size_ = entry.text_message().size(); + } + size_t size() const { + CHECK_GT(size_, 0); + return size_; + } + + private: + size_t size_ = -1; + } extractor_sink; + LOG(INFO).NoPrefix().ToSinkOnly(&extractor_sink) + << std::string(2 * absl::log_internal::kLogMessageBufferSize, 'x'); + return extractor_sink.size(); +} + +TEST(StructuredLoggingOverflowTest, TruncatesStringsCleanly) { + const size_t longest_fit = MaxLogFieldLengthNoPrefix(); + // To log a second value field, we need four bytes: two tag/type bytes and two + // sizes. To put any data in the field we need a fifth byte. + { + absl::ScopedMockLog test_sink(absl::MockLogDefault::kDisallowUnexpected); + EXPECT_CALL(test_sink, + Send(AllOf(ENCODED_MESSAGE(HasOneStrThat( + AllOf(SizeIs(longest_fit), Each(Eq('x'))))), + RawEncodedMessage(AsString(EndsWith("x")))))); + test_sink.StartCapturingLogs(); + // x fits exactly, no part of y fits. + LOG(INFO).NoPrefix() << std::string(longest_fit, 'x') << "y"; + } + { + absl::ScopedMockLog test_sink(absl::MockLogDefault::kDisallowUnexpected); + EXPECT_CALL(test_sink, + Send(AllOf(ENCODED_MESSAGE(HasOneStrThat( + AllOf(SizeIs(longest_fit - 1), Each(Eq('x'))))), + RawEncodedMessage(AsString(EndsWith("x")))))); + test_sink.StartCapturingLogs(); + // x fits, one byte from y's header fits but shouldn't be visible. + LOG(INFO).NoPrefix() << std::string(longest_fit - 1, 'x') << "y"; + } + { + absl::ScopedMockLog test_sink(absl::MockLogDefault::kDisallowUnexpected); + EXPECT_CALL(test_sink, + Send(AllOf(ENCODED_MESSAGE(HasOneStrThat( + AllOf(SizeIs(longest_fit - 2), Each(Eq('x'))))), + RawEncodedMessage(AsString(EndsWith("x")))))); + test_sink.StartCapturingLogs(); + // x fits, two bytes from y's header fit but shouldn't be visible. + LOG(INFO).NoPrefix() << std::string(longest_fit - 2, 'x') << "y"; + } + { + absl::ScopedMockLog test_sink(absl::MockLogDefault::kDisallowUnexpected); + EXPECT_CALL(test_sink, + Send(AllOf(ENCODED_MESSAGE(HasOneStrThat( + AllOf(SizeIs(longest_fit - 3), Each(Eq('x'))))), + RawEncodedMessage(AsString(EndsWith("x")))))); + test_sink.StartCapturingLogs(); + // x fits, three bytes from y's header fit but shouldn't be visible. + LOG(INFO).NoPrefix() << std::string(longest_fit - 3, 'x') << "y"; + } + { + absl::ScopedMockLog test_sink(absl::MockLogDefault::kDisallowUnexpected); + EXPECT_CALL(test_sink, + Send(AllOf(ENCODED_MESSAGE(HasOneStrAndOneLiteralThat( + AllOf(SizeIs(longest_fit - 4), Each(Eq('x'))), + IsEmpty())), + RawEncodedMessage(Not(AsString(EndsWith("x"))))))); + test_sink.StartCapturingLogs(); + // x fits, all four bytes from y's header fit but no data bytes do, so we + // encode an empty string. + LOG(INFO).NoPrefix() << std::string(longest_fit - 4, 'x') << "y"; + } + { + absl::ScopedMockLog test_sink(absl::MockLogDefault::kDisallowUnexpected); + EXPECT_CALL( + test_sink, + Send(AllOf(ENCODED_MESSAGE(HasOneStrAndOneLiteralThat( + AllOf(SizeIs(longest_fit - 5), Each(Eq('x'))), Eq("y"))), + RawEncodedMessage(AsString(EndsWith("y")))))); + test_sink.StartCapturingLogs(); + // x fits, y fits exactly. + LOG(INFO).NoPrefix() << std::string(longest_fit - 5, 'x') << "y"; + } +} + +TEST(StructuredLoggingOverflowTest, TruncatesInsertionOperatorsCleanly) { + const size_t longest_fit = MaxLogFieldLengthNoPrefix(); + // To log a second value field, we need four bytes: two tag/type bytes and two + // sizes. To put any data in the field we need a fifth byte. + { + absl::ScopedMockLog test_sink(absl::MockLogDefault::kDisallowUnexpected); + EXPECT_CALL(test_sink, + Send(AllOf(ENCODED_MESSAGE(HasOneStrThat( + AllOf(SizeIs(longest_fit), Each(Eq('x'))))), + RawEncodedMessage(AsString(EndsWith("x")))))); + test_sink.StartCapturingLogs(); + // x fits exactly, no part of y fits. + LOG(INFO).NoPrefix() << std::string(longest_fit, 'x') << StringLike{"y"}; + } + { + absl::ScopedMockLog test_sink(absl::MockLogDefault::kDisallowUnexpected); + EXPECT_CALL(test_sink, + Send(AllOf(ENCODED_MESSAGE(HasOneStrThat( + AllOf(SizeIs(longest_fit - 1), Each(Eq('x'))))), + RawEncodedMessage(AsString(EndsWith("x")))))); + test_sink.StartCapturingLogs(); + // x fits, one byte from y's header fits but shouldn't be visible. + LOG(INFO).NoPrefix() << std::string(longest_fit - 1, 'x') + << StringLike{"y"}; + } + { + absl::ScopedMockLog test_sink(absl::MockLogDefault::kDisallowUnexpected); + EXPECT_CALL(test_sink, + Send(AllOf(ENCODED_MESSAGE(HasOneStrThat( + AllOf(SizeIs(longest_fit - 2), Each(Eq('x'))))), + RawEncodedMessage(AsString(EndsWith("x")))))); + test_sink.StartCapturingLogs(); + // x fits, two bytes from y's header fit but shouldn't be visible. + LOG(INFO).NoPrefix() << std::string(longest_fit - 2, 'x') + << StringLike{"y"}; + } + { + absl::ScopedMockLog test_sink(absl::MockLogDefault::kDisallowUnexpected); + EXPECT_CALL(test_sink, + Send(AllOf(ENCODED_MESSAGE(HasOneStrThat( + AllOf(SizeIs(longest_fit - 3), Each(Eq('x'))))), + RawEncodedMessage(AsString(EndsWith("x")))))); + test_sink.StartCapturingLogs(); + // x fits, three bytes from y's header fit but shouldn't be visible. + LOG(INFO).NoPrefix() << std::string(longest_fit - 3, 'x') + << StringLike{"y"}; + } + { + absl::ScopedMockLog test_sink(absl::MockLogDefault::kDisallowUnexpected); + EXPECT_CALL(test_sink, + Send(AllOf(ENCODED_MESSAGE(HasOneStrThat( + AllOf(SizeIs(longest_fit - 4), Each(Eq('x'))))), + RawEncodedMessage(AsString(EndsWith("x")))))); + test_sink.StartCapturingLogs(); + // x fits, all four bytes from y's header fit but no data bytes do. We + // don't encode an empty string here because every I/O manipulator hits this + // codepath and those shouldn't leave empty strings behind. + LOG(INFO).NoPrefix() << std::string(longest_fit - 4, 'x') + << StringLike{"y"}; + } + { + absl::ScopedMockLog test_sink(absl::MockLogDefault::kDisallowUnexpected); + EXPECT_CALL( + test_sink, + Send(AllOf(ENCODED_MESSAGE(HasTwoStrsThat( + AllOf(SizeIs(longest_fit - 5), Each(Eq('x'))), Eq("y"))), + RawEncodedMessage(AsString(EndsWith("y")))))); + test_sink.StartCapturingLogs(); + // x fits, y fits exactly. + LOG(INFO).NoPrefix() << std::string(longest_fit - 5, 'x') + << StringLike{"y"}; + } +} + } // namespace -- cgit v1.2.3