diff options
Diffstat (limited to 'absl/log/internal/log_message.cc')
-rw-r--r-- | absl/log/internal/log_message.cc | 340 |
1 files changed, 223 insertions, 117 deletions
diff --git a/absl/log/internal/log_message.cc b/absl/log/internal/log_message.cc index 82833af0..a8080610 100644 --- a/absl/log/internal/log_message.cc +++ b/absl/log/internal/log_message.cc @@ -41,15 +41,15 @@ #include "absl/container/inlined_vector.h" #include "absl/debugging/internal/examine_stack.h" #include "absl/log/globals.h" -#include "absl/log/internal/config.h" +#include "absl/log/internal/append_truncated.h" #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" #include "absl/memory/memory.h" -#include "absl/strings/str_format.h" #include "absl/strings/string_view.h" #include "absl/time/clock.h" #include "absl/time/time.h" @@ -65,13 +65,39 @@ ABSL_NAMESPACE_BEGIN namespace log_internal { namespace { -// Copies into `dst` as many bytes of `src` as will fit, then truncates the -// copied bytes from the front of `dst` and returns the number of bytes written. -size_t AppendTruncated(absl::string_view src, absl::Span<char>* dst) { - if (src.size() > dst->size()) src = src.substr(0, dst->size()); - memcpy(dst->data(), src.data(), src.size()); - dst->remove_prefix(src.size()); - return src.size(); +// message `logging.proto.Event` +enum EventTag : uint8_t { + kValue = 7, +}; + +// message `logging.proto.Value` +enum ValueTag : uint8_t { + kString = 1, + kStringLiteral = 6, +}; + +// Decodes a `logging.proto.Value` from `buf` and writes a string representation +// into `dst`. The string representation will be truncated if `dst` is not +// large enough to hold it. Returns false if `dst` has size zero or one (i.e. +// sufficient only for a nul-terminator) and no decoded data could be written. +// This function may or may not write a nul-terminator into `dst`, and it may or +// may not truncate the data it writes in order to do make space for that nul +// terminator. In any case, `dst` will be advanced to point at the byte where +// subsequent writes should begin. +bool PrintValue(absl::Span<char>& dst, absl::Span<const char> buf) { + if (dst.size() <= 1) return false; + ProtoField field; + while (field.DecodeFrom(&buf)) { + switch (field.tag()) { + case ValueTag::kString: + case ValueTag::kStringLiteral: + if (field.type() == WireType::kLengthDelimited) + if (log_internal::AppendTruncated(field.string_value(), dst) < + field.string_value().size()) + return false; + } + } + return true; } absl::string_view Basename(absl::string_view filepath) { @@ -93,87 +119,6 @@ void WriteToStream(const char* data, void* os) { } } // namespace -// A write-only `std::streambuf` that writes into an `absl::Span<char>`. -// -// This class is responsible for writing a metadata prefix just before the first -// data are streamed in. The metadata are subject to change (cf. -// `LogMessage::AtLocation`) until then, so we wait as long as possible. -// -// This class is also responsible for reserving space for a trailing newline -// so that one can be added later by `Finalize` no matter how many data are -// streamed in. -class LogEntryStreambuf final : public std::streambuf { - public: - explicit LogEntryStreambuf(absl::Span<char> buf, const absl::LogEntry& entry) - : buf_(buf), entry_(entry), prefix_len_(0), finalized_(false) { - // To detect when data are first written, we leave the put area null, - // override `overflow`, and check ourselves in `xsputn`. - } - - LogEntryStreambuf(LogEntryStreambuf&&) = delete; - LogEntryStreambuf& operator=(LogEntryStreambuf&&) = delete; - - absl::Span<const char> Finalize() { - assert(!finalized_); - // If no data were ever streamed in, this is where we must write the prefix. - if (pbase() == nullptr) Initialize(); - // Here we reclaim the two bytes we reserved. - ptrdiff_t idx = pptr() - pbase(); - setp(buf_.data(), buf_.data() + buf_.size()); - pbump(static_cast<int>(idx)); - sputc('\n'); - sputc('\0'); - finalized_ = true; - return absl::Span<const char>(pbase(), - static_cast<size_t>(pptr() - pbase())); - } - size_t prefix_len() const { return prefix_len_; } - - protected: - std::streamsize xsputn(const char* s, std::streamsize n) override { - if (n < 0) return 0; - if (pbase() == nullptr) Initialize(); - return static_cast<std::streamsize>( - Append(absl::string_view(s, static_cast<size_t>(n)))); - } - - int overflow(int ch = EOF) override { - if (pbase() == nullptr) Initialize(); - if (ch == EOF) return 0; - if (pptr() == epptr()) return EOF; - *pptr() = static_cast<char>(ch); - pbump(1); - return 1; - } - - private: - void Initialize() { - // Here we reserve two bytes in our buffer to guarantee `Finalize` space to - // add a trailing "\n\0". - assert(buf_.size() >= 2); - setp(buf_.data(), buf_.data() + buf_.size() - 2); - if (entry_.prefix()) { - absl::Span<char> remaining = buf_; - prefix_len_ = log_internal::FormatLogPrefix( - entry_.log_severity(), entry_.timestamp(), entry_.tid(), - entry_.source_basename(), entry_.source_line(), remaining); - pbump(static_cast<int>(prefix_len_)); - } - } - - size_t Append(absl::string_view data) { - absl::Span<char> remaining(pptr(), static_cast<size_t>(epptr() - pptr())); - const size_t written = AppendTruncated(data, &remaining); - pbump(static_cast<int>(written)); - return written; - } - - const absl::Span<char> buf_; - const absl::LogEntry& entry_; - size_t prefix_len_; - bool finalized_; -}; - struct LogMessage::LogMessageData final { LogMessageData(const char* file, int line, absl::LogSeverity severity, absl::Time timestamp); @@ -196,18 +141,31 @@ struct LogMessage::LogMessageData final { // non-sink targets (e.g. stderr, log files). bool extra_sinks_only; + std::ostream manipulated; // ostream with IO manipulators applied + + // A `logging.proto.Event` proto message is built into `encoded_buf`. + std::array<char, kLogMessageBufferSize> encoded_buf; + // `encoded_remaining` is the suffix of `encoded_buf` that has not been filled + // yet. If a datum to be encoded does not fit into `encoded_remaining` and + // cannot be truncated to fit, the size of `encoded_remaining` will be zeroed + // to prevent encoding of any further data. Note that in this case its data() + // pointer will not point past the end of `encoded_buf`. + absl::Span<char> encoded_remaining; + // A formatted string message is built in `string_buf`. std::array<char, kLogMessageBufferSize> string_buf; - // A `std::streambuf` that stores into `string_buf`. - LogEntryStreambuf streambuf_; + void FinalizeEncodingAndFormat(); }; LogMessage::LogMessageData::LogMessageData(const char* file, int line, absl::LogSeverity severity, absl::Time timestamp) : extra_sinks_only(false), - streambuf_(absl::MakeSpan(string_buf), entry) { + manipulated(nullptr), + encoded_remaining(encoded_buf) { + // Legacy defaults for LOG's ostream: + manipulated.setf(std::ios_base::showbase | std::ios_base::boolalpha); entry.full_filename_ = file; entry.base_filename_ = Basename(file); entry.line_ = line; @@ -218,21 +176,57 @@ LogMessage::LogMessageData::LogMessageData(const char* file, int line, entry.tid_ = absl::base_internal::GetCachedTID(); } +void LogMessage::LogMessageData::FinalizeEncodingAndFormat() { + // Note that `encoded_remaining` may have zero size without pointing past the + // end of `encoded_buf`, so the difference between `data()` pointers is used + // to compute the size of `encoded_data`. + absl::Span<const char> encoded_data( + encoded_buf.data(), + static_cast<size_t>(encoded_remaining.data() - encoded_buf.data())); + // `string_remaining` is the suffix of `string_buf` that has not been filled + // yet. + absl::Span<char> string_remaining(string_buf); + // We may need to write a newline and nul-terminator at the end of the decoded + // string data. Rather than worry about whether those should overwrite the + // end of the string (if the buffer is full) or be appended, we avoid writing + // into the last two bytes so we always have space to append. + string_remaining.remove_suffix(2); + entry.prefix_len_ = + entry.prefix() ? log_internal::FormatLogPrefix( + entry.log_severity(), entry.timestamp(), entry.tid(), + entry.source_basename(), entry.source_line(), + log_internal::ThreadIsLoggingToLogSink() + ? PrefixFormat::kRaw + : PrefixFormat::kNotRaw, + string_remaining) + : 0; + // Decode data from `encoded_buf` until we run out of data or we run out of + // `string_remaining`. + ProtoField field; + while (field.DecodeFrom(&encoded_data)) { + switch (field.tag()) { + case EventTag::kValue: + if (field.type() != WireType::kLengthDelimited) continue; + if (PrintValue(string_remaining, field.bytes_value())) continue; + break; + } + break; + } + auto chars_written = + static_cast<size_t>(string_remaining.data() - string_buf.data()); + string_buf[chars_written++] = '\n'; + string_buf[chars_written++] = '\0'; + entry.text_message_with_prefix_and_newline_and_nul_ = + absl::MakeSpan(string_buf).subspan(0, chars_written); +} + LogMessage::LogMessage(const char* file, int line, absl::LogSeverity severity) - : data_( - absl::make_unique<LogMessageData>(file, line, severity, absl::Now())) - , - stream_(&data_->streambuf_) -{ + : data_(absl::make_unique<LogMessageData>(file, line, severity, + absl::Now())) { data_->first_fatal = false; data_->is_perror = false; data_->fail_quietly = false; - // Legacy defaults for LOG's ostream: - stream_.setf(std::ios_base::showbase | std::ios_base::boolalpha); - // `fill('0')` is omitted here because its effects are very different without - // structured logging. Resolution is tracked in b/111310488. - // This logs a backtrace even if the location is subsequently changed using // AtLocation. This quirk, and the behavior when AtLocation is called twice, // are fixable but probably not worth fixing. @@ -350,6 +344,25 @@ void LogMessage::FailQuietly() { _exit(1); } +LogMessage& LogMessage::operator<<(const std::string& v) { + CopyToEncodedBuffer(v, StringType::kNotLiteral); + return *this; +} + +LogMessage& LogMessage::operator<<(absl::string_view v) { + CopyToEncodedBuffer(v, StringType::kNotLiteral); + return *this; +} +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); @@ -367,8 +380,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()) @@ -380,22 +391,67 @@ void LogMessage::Flush() { } // Have we already seen a fatal message? - ABSL_CONST_INIT static std::atomic_flag seen_fatal = ATOMIC_FLAG_INIT; + ABSL_CONST_INIT static std::atomic<bool> seen_fatal(false); if (data_->entry.log_severity() == absl::LogSeverity::kFatal && absl::log_internal::ExitOnDFatal()) { // Exactly one LOG(FATAL) message is responsible for aborting the process, // even if multiple threads LOG(FATAL) concurrently. - data_->first_fatal = !seen_fatal.test_and_set(std::memory_order_relaxed); + bool expected_seen_fatal = false; + if (seen_fatal.compare_exchange_strong(expected_seen_fatal, true, + std::memory_order_relaxed)) { + data_->first_fatal = true; + } } - data_->entry.text_message_with_prefix_and_newline_and_nul_ = - data_->streambuf_.Finalize(); - data_->entry.prefix_len_ = data_->streambuf_.prefix_len(); + data_->FinalizeEncodingAndFormat(); + data_->entry.encoding_ = + absl::string_view(data_->encoded_buf.data(), + static_cast<size_t>(data_->encoded_remaining.data() - + data_->encoded_buf.data())); SendToLog(); } void LogMessage::SetFailQuietly() { data_->fail_quietly = true; } +LogMessage::OstreamView::OstreamView(LogMessageData& message_data) + : data_(message_data), encoded_remaining_copy_(data_.encoded_remaining) { + // This constructor sets the `streambuf` up so that streaming into an attached + // ostream encodes string data in-place. To do that, we write appropriate + // headers into the buffer using a copy of the buffer view so that we can + // decide not to keep them later if nothing is ever streamed in. We don't + // know how much data we'll get, but we can use the size of the remaining + // buffer as an upper bound and fill in the right size once we know it. + message_start_ = + EncodeMessageStart(EventTag::kValue, encoded_remaining_copy_.size(), + &encoded_remaining_copy_); + string_start_ = + EncodeMessageStart(ValueTag::kString, encoded_remaining_copy_.size(), + &encoded_remaining_copy_); + setp(encoded_remaining_copy_.data(), + encoded_remaining_copy_.data() + encoded_remaining_copy_.size()); + data_.manipulated.rdbuf(this); +} + +LogMessage::OstreamView::~OstreamView() { + data_.manipulated.rdbuf(nullptr); + if (!string_start_.data()) { + // 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()); + return; + } + const absl::Span<const char> contents(pbase(), + static_cast<size_t>(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; } + bool LogMessage::IsFatal() const { return data_->entry.log_severity() == absl::LogSeverity::kFatal && absl::log_internal::ExitOnDFatal(); @@ -449,11 +505,61 @@ 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 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 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()); + } +} +void LogMessage::CopyToEncodedBuffer(char ch, size_t num, StringType str_type) { + auto encoded_remaining_copy = data_->encoded_remaining; + auto value_start = EncodeMessageStart( + EventTag::kValue, BufferSizeFor(WireType::kLengthDelimited) + num, + &encoded_remaining_copy); + auto str_start = EncodeMessageStart(str_type == StringType::kLiteral + ? ValueTag::kStringLiteral + : ValueTag::kString, + num, &encoded_remaining_copy); + if (str_start.data()) { + // The field headers fit. + log_internal::AppendTruncated(ch, num, encoded_remaining_copy); + EncodeMessageLength(str_start, &encoded_remaining_copy); + EncodeMessageLength(value_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()); + } } LogMessageFatal::LogMessageFatal(const char* file, int line) @@ -467,7 +573,7 @@ LogMessageFatal::LogMessageFatal(const char* file, int line, // ABSL_ATTRIBUTE_NORETURN doesn't seem to work on destructors with msvc, so // disable msvc's warning about the d'tor never returning. -#ifdef _MSC_VER +#if defined(_MSC_VER) && !defined(__clang__) #pragma warning(push) #pragma warning(disable : 4722) #endif @@ -475,7 +581,7 @@ LogMessageFatal::~LogMessageFatal() { Flush(); FailWithoutStackTrace(); } -#ifdef _MSC_VER +#if defined(_MSC_VER) && !defined(__clang__) #pragma warning(pop) #endif @@ -493,7 +599,7 @@ LogMessageQuietlyFatal::LogMessageQuietlyFatal(const char* file, int line, // ABSL_ATTRIBUTE_NORETURN doesn't seem to work on destructors with msvc, so // disable msvc's warning about the d'tor never returning. -#ifdef _MSC_VER +#if defined(_MSC_VER) && !defined(__clang__) #pragma warning(push) #pragma warning(disable : 4722) #endif @@ -501,7 +607,7 @@ LogMessageQuietlyFatal::~LogMessageQuietlyFatal() { Flush(); FailQuietly(); } -#ifdef _MSC_VER +#if defined(_MSC_VER) && !defined(__clang__) #pragma warning(pop) #endif |