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') 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