Skip to content

Commit

Permalink
Log crash keys and other info when DumpWithoutCrashing is called.
Browse files Browse the repository at this point in the history 
This CL should slightly improve development experience when debugging
scenarios where a DumpWithoutCrashing is called when running a test, or
when manually trying to repro a bug with a developer build of Chromium.
This CL logs the same information as LOG(FATAL) would (stack trace,
task trace, crash keys).

This CL has been opportunistically put together when working on
https://crbug.com/1038996, but it should be useful in general.
This CL does *not* fix https://crbug.com/1038996.

Example of how test output might look like when it
(accidentally/unexpectedly in this case) triggers a renderer kill:

    [838194:838194:0826/140420.024770:ERROR:bad_message.cc(20)] Terminating extension renderer for bad IPC message, reason 21
    [838194:838194:0826/140420.024971:ERROR:process_posix.cc(337)] Unable to terminate process 838300: Resource temporarily unavailable (11)
    [838194:838194:0826/140420.158002:ERROR:dump_without_crashing.cc(74)] DumpWithoutCrashing:
    #0 0x7f678a4593e2 base::debug::CollectStackTrace()
    #1 0x7f678a34d5d3 base::debug::StackTrace::StackTrace()
    #2 0x7f678a36b533 logging::LogMessage::AppendCrashInfoForDevBuilds()
    #3 0x7f678a34cdae (anonymous namespace)::MaybeLogThatDumpWithoutCrashingHappened()
    #4 0x7f678a34cf2b base::debug::DumpWithoutCrashing()
    #5 0x7f6782feddc6 content::RenderProcessHostImpl::ShutdownForBadMessage()
    #6 0x5645447dc5c4 extensions::bad_message::ReceivedBadMessage()
    #7 0x5645448fd588 extensions::MessagingAPIMessageFilter::OnOpenChannelToExtension()
    #8 0x5645448fcfa7 IPC::MessageT<>::Dispatch<>()
    #9 0x5645448fccc0 extensions::MessagingAPIMessageFilter::OnMessageReceived()
    #10 0x7f678254ccd5 content::BrowserMessageFilter::Internal::DispatchMessage()
    ...
    Task trace:
    #0 0x7f678254ca73 content::BrowserMessageFilter::Internal::OnMessageReceived()
    #1 0x7f6789a8adce mojo::SimpleWatcher::Context::Notify()
    Crash keys:
      "RPH.BadMessageKill-isolation_mode" = "spp "
      "killed_process_origin_lock" = "{ chrome-extension://mbbkmcnhalmicnfjpiigcennjnmlcdja/ }"
      "extension_bad_message_reason" = "21"
      "ExternalConnectionInfo-source_url" = "chrome-extension://mbbkmcnhalmicnfjpiigcennjnmlcdja/background.js"
      "ExternalConnectionInfo-source_origin" = "nullptr"
      "MessagingSource-extension_id" = "mbbkmcnhalmicnfjpiigcennjnmlcdja"
      "MessagingSource-type" = "Extension"
      "ExternalConnectionInfo-target_id" = "mbbkmcnhalmicnfjpiigcennjnmlcdja"
      "ui_scheduler_async_stack" = "0x7F678254CA73 0x7F6789A8ADCE"
      "io_scheduler_async_stack" = "0x7F6789A8ADCE 0x0"

Bug: 1038996
Change-Id: I2172212a42b43f9272ecc86904aeb2ddb3c3b936
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/3857528
Reviewed-by: Daniel Cheng <dcheng@chromium.org>
Commit-Queue: Łukasz Anforowicz <lukasza@chromium.org>
Cr-Commit-Position: refs/heads/main@{#1040542}
  • Loading branch information
@anforowicz
anforowicz authored and Chromium LUCI CQ committed Aug 29, 2022
1 parent 69b62b8 commit 722256f
Show file tree
Hide file tree
Showing 3 changed files with 63 additions and 20 deletions.
18 changes: 18 additions & 0 deletions base/debug/dump_without_crashing.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@
#include "base/debug/dump_without_crashing.h"

#include "base/check.h"
#include "base/logging.h"
#include "base/metrics/histogram_functions.h"
#include "base/no_destructor.h"
#include "base/synchronization/lock.h"
Expand Down Expand Up @@ -58,6 +59,20 @@ bool ShouldDumpWithoutCrashWithLocationAndUniqueId(
time_between_dumps);
}

void MaybeLogThatDumpWithoutCrashingHappened() {
#if !defined(OFFICIAL_BUILD)
// Exit early if logging of error messages is disabled. This is not strictly
// required (since `LOG(ERROR)` below would discard the message), but avoids
// the somewhat unnecessary and expensive call to AppendCrashInfoForDevBuilds.
if (logging::LOG_ERROR < logging::GetMinLogLevel())
return;

std::ostringstream string_stream;
logging::LogMessage::AppendCrashInfoForDevBuilds(string_stream);
LOG(ERROR) << "DumpWithoutCrashing: " << string_stream.str();
#endif
}

} // namespace

namespace base {
Expand All @@ -66,6 +81,7 @@ namespace debug {

bool DumpWithoutCrashingUnthrottled() {
TRACE_EVENT0("base", "DumpWithoutCrashingUnthrottled");
MaybeLogThatDumpWithoutCrashingHappened();
if (dump_without_crashing_function_) {
(*dump_without_crashing_function_)();
return true;
Expand All @@ -76,6 +92,7 @@ bool DumpWithoutCrashingUnthrottled() {
bool DumpWithoutCrashing(const base::Location& location,
base::TimeDelta time_between_dumps) {
TRACE_EVENT0("base", "DumpWithoutCrashing");
MaybeLogThatDumpWithoutCrashingHappened();
if (dump_without_crashing_function_ &&
ShouldDumpWithoutCrashWithLocation(location, time_between_dumps)) {
(*dump_without_crashing_function_)();
Expand All @@ -92,6 +109,7 @@ bool DumpWithoutCrashingWithUniqueId(size_t unique_identifier,
const base::Location& location,
base::TimeDelta time_between_dumps) {
TRACE_EVENT0("base", "DumpWithoutCrashingWithUniqueId");
MaybeLogThatDumpWithoutCrashingHappened();
if (dump_without_crashing_function_ &&
ShouldDumpWithoutCrashWithLocationAndUniqueId(unique_identifier, location,
time_between_dumps)) {
Expand Down
61 changes: 41 additions & 20 deletions base/logging.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -699,32 +699,53 @@ LogMessage::LogMessage(const char* file, int line, const char* condition)
stream_ << "Check failed: " << condition << ". ";
}

#if !defined(OFFICIAL_BUILD)
// static
void LogMessage::AppendCrashInfoForDevBuilds(std::ostream& out) {
// `!BUILDFLAG(IS_NACL)` because `base::debug::OutputCrashKeysToStream` and
// `base::debug::StackTrace` are not available in NaCl (i.e. `//base/BUILD.gn`
// removes their .cc files `if (is_nacl)`; see also r319987).
//
// Unclear why _exactly_ `!BUILDFLAG(IS_AIX)` was added in r467484, nor why
// `!defined(__UCLIBC__)` was added in r343626.
#if !BUILDFLAG(IS_NACL) && !defined(__UCLIBC__) && !BUILDFLAG(IS_AIX)
// Include a newline to separate from the main log message.
//
// Using "\n" instead of `std::endl` because the latter flushes, and the LLVM
// style guide (yes, I know this is not LLVM but) recommends the former
// instead of the latter for that reason.
out << "\n";

// Include a stack trace.
base::debug::StackTrace stack_trace;
stack_trace.OutputToStream(&out);
base::debug::TaskTrace task_trace;
if (!task_trace.empty())
task_trace.OutputToStream(&out);

// Include the IPC context, if any.
// TODO(chrisha): Integrate with symbolization once those tools exist!
const auto* task = base::TaskAnnotator::CurrentTaskForThread();
if (task && task->ipc_hash) {
out << "IPC message handler context: "
<< base::StringPrintf("0x%08X", task->ipc_hash) << "\n";
}

// Include the crash keys, if any.
base::debug::OutputCrashKeysToStream(out);
#endif
}
#endif

LogMessage::~LogMessage() {
size_t stack_start = stream_.str().length();
#if !defined(OFFICIAL_BUILD) && !BUILDFLAG(IS_NACL) && !defined(__UCLIBC__) && \
!BUILDFLAG(IS_AIX)
#if !defined(OFFICIAL_BUILD)
if (severity_ == LOGGING_FATAL && !base::debug::BeingDebugged()) {
// Include a stack trace on a fatal, unless a debugger is attached.
base::debug::StackTrace stack_trace;
stream_ << std::endl; // Newline to separate from log message.
stack_trace.OutputToStream(&stream_);
base::debug::TaskTrace task_trace;
if (!task_trace.empty())
task_trace.OutputToStream(&stream_);

// Include the IPC context, if any.
// TODO(chrisha): Integrate with symbolization once those tools exist!
const auto* task = base::TaskAnnotator::CurrentTaskForThread();
if (task && task->ipc_hash) {
stream_ << "IPC message handler context: "
<< base::StringPrintf("0x%08X", task->ipc_hash) << std::endl;
}

// Include the crash keys, if any.
base::debug::OutputCrashKeysToStream(stream_);
AppendCrashInfoForDevBuilds(stream_);
}
#endif
stream_ << std::endl;
stream_ << "\n";
std::string str_newline(stream_.str());
TRACE_LOG_MESSAGE(
file_, base::StringPiece(str_newline).substr(message_start_), line_);
Expand Down
4 changes: 4 additions & 0 deletions base/logging.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -654,6 +654,10 @@ class BASE_EXPORT LogMessage {
// Gets file:line: message in a format suitable for crash reporting.
std::string BuildCrashString() const;

#if !defined(OFFICIAL_BUILD)
static void AppendCrashInfoForDevBuilds(std::ostream& out);
#endif

private:
void Init(const char* file, int line);

Expand Down

0 comments on commit 722256f

Please sign in to comment.