diff options
Diffstat (limited to 'absl/log/internal/log_message.cc')
| -rw-r--r-- | absl/log/internal/log_message.cc | 618 |
1 files changed, 618 insertions, 0 deletions
diff --git a/absl/log/internal/log_message.cc b/absl/log/internal/log_message.cc new file mode 100644 index 00000000..bdb10f2a --- /dev/null +++ b/absl/log/internal/log_message.cc @@ -0,0 +1,618 @@ +// +// 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/log_message.h" + +#include <stddef.h> +#include <stdint.h> +#include <stdlib.h> +#include <string.h> + +#ifndef _WIN32 +#include <unistd.h> +#endif + +#include <algorithm> +#include <array> +#include <atomic> +#include <memory> +#include <ostream> +#include <string> +#include <tuple> + +#include "absl/base/attributes.h" +#include "absl/base/config.h" +#include "absl/base/internal/raw_logging.h" +#include "absl/base/internal/strerror.h" +#include "absl/base/internal/sysinfo.h" +#include "absl/base/log_severity.h" +#include "absl/container/inlined_vector.h" +#include "absl/debugging/internal/examine_stack.h" +#include "absl/log/globals.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/string_view.h" +#include "absl/time/clock.h" +#include "absl/time/time.h" +#include "absl/types/span.h" + +extern "C" ABSL_ATTRIBUTE_WEAK void ABSL_INTERNAL_C_SYMBOL( + AbslInternalOnFatalLogMessage)(const absl::LogEntry&) { + // Default - Do nothing +} + +namespace absl { +ABSL_NAMESPACE_BEGIN +namespace log_internal { + +namespace { +// message `logging.proto.Event` +enum EventTag : uint8_t { + kValue = 7, +}; + +// message `logging.proto.Value` +enum ValueTag : uint8_t { + kString = 1, + kStringLiteral = 6, +}; + +// Decodes a `logging.proto.Value` from `buf` and writes a string representation +// into `dst`. The string representation will be truncated if `dst` is not +// large enough to hold it. Returns false if `dst` has size zero or one (i.e. +// sufficient only for a nul-terminator) and no decoded data could be written. +// This function may or may not write a nul-terminator into `dst`, and it may or +// may not truncate the data it writes in order to do make space for that nul +// terminator. In any case, `dst` will be advanced to point at the byte where +// subsequent writes should begin. +bool PrintValue(absl::Span<char>& dst, absl::Span<const char> buf) { + if (dst.size() <= 1) return false; + ProtoField field; + while (field.DecodeFrom(&buf)) { + switch (field.tag()) { + case ValueTag::kString: + case ValueTag::kStringLiteral: + if (field.type() == WireType::kLengthDelimited) + if (log_internal::AppendTruncated(field.string_value(), dst) < + field.string_value().size()) + return false; + } + } + return true; +} + +absl::string_view Basename(absl::string_view filepath) { +#ifdef _WIN32 + size_t path = filepath.find_last_of("/\\"); +#else + size_t path = filepath.find_last_of('/'); +#endif + if (path != filepath.npos) filepath.remove_prefix(path + 1); + return filepath; +} + +void WriteToString(const char* data, void* str) { + reinterpret_cast<std::string*>(str)->append(data); +} +void WriteToStream(const char* data, void* os) { + auto* cast_os = static_cast<std::ostream*>(os); + *cast_os << data; +} +} // namespace + +struct LogMessage::LogMessageData final { + LogMessageData(const char* file, int line, absl::LogSeverity severity, + absl::Time timestamp); + LogMessageData(const LogMessageData&) = delete; + LogMessageData& operator=(const LogMessageData&) = delete; + + // `LogEntry` sent to `LogSink`s; contains metadata. + absl::LogEntry entry; + + // true => this was first fatal msg + bool first_fatal; + // true => all failures should be quiet + bool fail_quietly; + // true => PLOG was requested + bool is_perror; + + // Extra `LogSink`s to log to, in addition to `global_sinks`. + absl::InlinedVector<absl::LogSink*, 16> extra_sinks; + // If true, log to `extra_sinks` but not to `global_sinks` or hardcoded + // 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; + + void FinalizeEncodingAndFormat(); +}; + +LogMessage::LogMessageData::LogMessageData(const char* file, int line, + absl::LogSeverity severity, + absl::Time timestamp) + : extra_sinks_only(false), + manipulated(nullptr), + // This `absl::MakeSpan` silences spurious -Wuninitialized from GCC: + encoded_remaining(absl::MakeSpan(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; + entry.prefix_ = absl::ShouldPrependLogPrefix(); + entry.severity_ = absl::NormalizeLogSeverity(severity); + entry.verbose_level_ = absl::LogEntry::kNoVerbosityLevel; + entry.timestamp_ = timestamp; + 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())) { + data_->first_fatal = false; + data_->is_perror = false; + data_->fail_quietly = false; + + // 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. + LogBacktraceIfNeeded(); +} + +LogMessage::~LogMessage() { +#ifdef ABSL_MIN_LOG_LEVEL + if (data_->entry.log_severity() < + static_cast<absl::LogSeverity>(ABSL_MIN_LOG_LEVEL) && + data_->entry.log_severity() < absl::LogSeverity::kFatal) { + return; + } +#endif + Flush(); +} + +LogMessage& LogMessage::AtLocation(absl::string_view file, int line) { + data_->entry.full_filename_ = file; + data_->entry.base_filename_ = Basename(file); + data_->entry.line_ = line; + LogBacktraceIfNeeded(); + return *this; +} + +LogMessage& LogMessage::NoPrefix() { + data_->entry.prefix_ = false; + return *this; +} + +LogMessage& LogMessage::WithVerbosity(int verbose_level) { + if (verbose_level == absl::LogEntry::kNoVerbosityLevel) { + data_->entry.verbose_level_ = absl::LogEntry::kNoVerbosityLevel; + } else { + data_->entry.verbose_level_ = std::max(0, verbose_level); + } + return *this; +} + +LogMessage& LogMessage::WithTimestamp(absl::Time timestamp) { + data_->entry.timestamp_ = timestamp; + return *this; +} + +LogMessage& LogMessage::WithThreadID(absl::LogEntry::tid_t tid) { + data_->entry.tid_ = tid; + return *this; +} + +LogMessage& LogMessage::WithMetadataFrom(const absl::LogEntry& entry) { + data_->entry.full_filename_ = entry.full_filename_; + data_->entry.base_filename_ = entry.base_filename_; + data_->entry.line_ = entry.line_; + data_->entry.prefix_ = entry.prefix_; + data_->entry.severity_ = entry.severity_; + data_->entry.verbose_level_ = entry.verbose_level_; + data_->entry.timestamp_ = entry.timestamp_; + data_->entry.tid_ = entry.tid_; + return *this; +} + +LogMessage& LogMessage::WithPerror() { + data_->is_perror = true; + return *this; +} + +LogMessage& LogMessage::ToSinkAlso(absl::LogSink* sink) { + ABSL_INTERNAL_CHECK(sink, "null LogSink*"); + data_->extra_sinks.push_back(sink); + return *this; +} + +LogMessage& LogMessage::ToSinkOnly(absl::LogSink* sink) { + ABSL_INTERNAL_CHECK(sink, "null LogSink*"); + data_->extra_sinks.clear(); + data_->extra_sinks.push_back(sink); + data_->extra_sinks_only = true; + return *this; +} + +#ifdef __ELF__ +extern "C" void __gcov_dump() ABSL_ATTRIBUTE_WEAK; +extern "C" void __gcov_flush() ABSL_ATTRIBUTE_WEAK; +#endif + +void LogMessage::FailWithoutStackTrace() { + // Now suppress repeated trace logging: + log_internal::SetSuppressSigabortTrace(true); +#if defined _DEBUG && defined COMPILER_MSVC + // When debugging on windows, avoid the obnoxious dialog. + __debugbreak(); +#endif + +#ifdef __ELF__ + // For b/8737634, flush coverage if we are in coverage mode. + if (&__gcov_dump != nullptr) { + __gcov_dump(); + } else if (&__gcov_flush != nullptr) { + __gcov_flush(); + } +#endif + + abort(); +} + +void LogMessage::FailQuietly() { + // _exit. Calling abort() would trigger all sorts of death signal handlers + // and a detailed stack trace. Calling exit() would trigger the onexit + // handlers, including the heap-leak checker, which is guaranteed to fail in + // this case: we probably just new'ed the std::string that we logged. + // Anyway, if you're calling Fail or FailQuietly, you're trying to bail out + // of the program quickly, and it doesn't make much sense for FailQuietly to + // offer different guarantees about exit behavior than Fail does. (And as a + // consequence for QCHECK and CHECK to offer different exit behaviors) + _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); +template LogMessage& LogMessage::operator<<(const short& v); // NOLINT +template LogMessage& LogMessage::operator<<(const unsigned short& v); // NOLINT +template LogMessage& LogMessage::operator<<(const int& v); +template LogMessage& LogMessage::operator<<(const unsigned int& v); +template LogMessage& LogMessage::operator<<(const long& v); // NOLINT +template LogMessage& LogMessage::operator<<(const unsigned long& v); // NOLINT +template LogMessage& LogMessage::operator<<(const long long& v); // NOLINT +template LogMessage& LogMessage::operator<<( + const unsigned long long& v); // NOLINT +template LogMessage& LogMessage::operator<<(void* const& v); +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); + +void LogMessage::Flush() { + if (data_->entry.log_severity() < absl::MinLogLevel()) + return; + + if (data_->is_perror) { + InternalStream() << ": " << absl::base_internal::StrError(errno_saver_()) + << " [" << errno_saver_() << "]"; + } + + // Have we already seen a fatal message? + 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. + bool expected_seen_fatal = false; + if (seen_fatal.compare_exchange_strong(expected_seen_fatal, true, + std::memory_order_relaxed)) { + data_->first_fatal = true; + } + } + + 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(); +} + +void LogMessage::PrepareToDie() { + // If we log a FATAL message, flush all the log destinations, then toss + // a signal for others to catch. We leave the logs in a state that + // someone else can use them (as long as they flush afterwards) + if (data_->first_fatal) { + // Notify observers about the upcoming fatal error. + ABSL_INTERNAL_C_SYMBOL(AbslInternalOnFatalLogMessage)(data_->entry); + } + + if (!data_->fail_quietly) { + // Log the message first before we start collecting stack trace. + log_internal::LogToSinks(data_->entry, absl::MakeSpan(data_->extra_sinks), + data_->extra_sinks_only); + + // `DumpStackTrace` generates an empty string under MSVC. + // Adding the constant prefix here simplifies testing. + data_->entry.stacktrace_ = "*** Check failure stack trace: ***\n"; + debugging_internal::DumpStackTrace( + 0, log_internal::MaxFramesInLogStackTrace(), + log_internal::ShouldSymbolizeLogStackTrace(), WriteToString, + &data_->entry.stacktrace_); + } +} + +void LogMessage::Die() { + absl::FlushLogSinks(); + + if (data_->fail_quietly) { + FailQuietly(); + } else { + FailWithoutStackTrace(); + } +} + +void LogMessage::SendToLog() { + if (IsFatal()) PrepareToDie(); + // Also log to all registered sinks, even if OnlyLogToStderr() is set. + log_internal::LogToSinks(data_->entry, absl::MakeSpan(data_->extra_sinks), + data_->extra_sinks_only); + if (IsFatal()) Die(); +} + +void LogMessage::LogBacktraceIfNeeded() { + if (!absl::log_internal::IsInitialized()) return; + + if (!absl::log_internal::ShouldLogBacktraceAt(data_->entry.source_basename(), + data_->entry.source_line())) + return; + OstreamView view(*data_); + view.stream() << " (stacktrace:\n"; + debugging_internal::DumpStackTrace( + 1, log_internal::MaxFramesInLogStackTrace(), + 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) + : LogMessage(file, line, absl::LogSeverity::kFatal) {} + +LogMessageFatal::LogMessageFatal(const char* file, int line, + absl::string_view failure_msg) + : LogMessage(file, line, absl::LogSeverity::kFatal) { + *this << "Check failed: " << failure_msg << " "; +} + +// ABSL_ATTRIBUTE_NORETURN doesn't seem to work on destructors with msvc, so +// disable msvc's warning about the d'tor never returning. +#if defined(_MSC_VER) && !defined(__clang__) +#pragma warning(push) +#pragma warning(disable : 4722) +#endif +LogMessageFatal::~LogMessageFatal() { + Flush(); + FailWithoutStackTrace(); +} +#if defined(_MSC_VER) && !defined(__clang__) +#pragma warning(pop) +#endif + +LogMessageQuietlyFatal::LogMessageQuietlyFatal(const char* file, int line) + : LogMessage(file, line, absl::LogSeverity::kFatal) { + SetFailQuietly(); +} + +LogMessageQuietlyFatal::LogMessageQuietlyFatal(const char* file, int line, + absl::string_view failure_msg) + : LogMessage(file, line, absl::LogSeverity::kFatal) { + SetFailQuietly(); + *this << "Check failed: " << failure_msg << " "; +} + +// ABSL_ATTRIBUTE_NORETURN doesn't seem to work on destructors with msvc, so +// disable msvc's warning about the d'tor never returning. +#if defined(_MSC_VER) && !defined(__clang__) +#pragma warning(push) +#pragma warning(disable : 4722) +#endif +LogMessageQuietlyFatal::~LogMessageQuietlyFatal() { + Flush(); + FailQuietly(); +} +#if defined(_MSC_VER) && !defined(__clang__) +#pragma warning(pop) +#endif + +} // namespace log_internal + +ABSL_NAMESPACE_END +} // namespace absl |