Code to collect issue 97285 debugging info for crash reports.

Code to collect issue 97285 debugging info for crash reports.

It is useful to record breakpad keys for debugging, which is not
applicable to multi-process bugs.  This adds infrastructure to allow
collection of information across processes.

BUG=97285, 141055
Originally committed: http://src.chromium.org/viewvc/chrome?view=rev&revision=155122
Reverted at 155250 due to release-manager suspicions about Windows issues, which now appear unrelated.

[Scott Hess - ex-Googler, 2012-09-04 22:22:56]

Late last week I spent a few hours in a waiting room, so I found myself
pondering how I'd _really_ want things to work.  Then I realized that it
wouldn't be all _that_ hard to implement.

This is really kind of three CLs in one:
 - GetPluginChannelHost() fix (fails rather than crashing).
 - Infrastructure to collect debugging info.
 - Actual generating of debugging info.

I can break things apart if desired, but I suspect that the middle part is the
contentious one, so I'll not be preemptive about that.

I would guess that the code in plugin and renderer which registers forwarding
handlers could as easily be lifted up into chrome/.  I thought it was more
useful in content/, though.

[I notice that the DCHECK() for handlers breaks my NullLogging test.  I'm going
to convert those to DLOG_IF.]

[Bernhard Bauer, 2012-09-05 15:04:55]

Awesome!

https://chromiumcodereview.appspot.com/10908078/diff/1/chrome/app/chrome_main...
File chrome/app/chrome_main_delegate.cc (right):

https://chromiumcodereview.appspot.com/10908078/diff/1/chrome/app/chrome_main...
chrome/app/chrome_main_delegate.cc:410: msgs->assign(bug_messages.begin(),
bug_messages.end());
Could you just write `*msgs = g_messages.Get()[bug_id];`?

https://chromiumcodereview.appspot.com/10908078/diff/1/content/browser/plugin...
File content/browser/plugin_process_host.cc (right):

https://chromiumcodereview.appspot.com/10908078/diff/1/content/browser/plugin...
content/browser/plugin_process_host.cc:468: if
(!content::debug::GetMessages(bug_id, msgs))
Doesn't GetMessages() return false if the out vector is empty? Why do we need to
clear it then?

https://chromiumcodereview.appspot.com/10908078/diff/1/content/common/content...
File content/common/content_debug_logging.cc (right):

https://chromiumcodereview.appspot.com/10908078/diff/1/content/common/content...
content/common/content_debug_logging.cc:15: // thread-safe.crbug.com
Oops! Google Chrome could not find thread-safe.crbug.com

https://chromiumcodereview.appspot.com/10908078/diff/1/content/common/content...
content/common/content_debug_logging.cc:28: DCHECK(g_record_handler);
Are these the ones you want to replace with DLOG_IF? Then you could just put a
DLOG inside of the if statement (or turn it around and early-return if
|g_record_handler| is NULL).

https://chromiumcodereview.appspot.com/10908078/diff/1/content/common/content...
File content/common/content_debug_logging_unittest.cc (right):

https://chromiumcodereview.appspot.com/10908078/diff/1/content/common/content...
content/common/content_debug_logging_unittest.cc:35: static std::map<int,
std::vector<std::string> > messages;
Could you make this a pointer to avoid the static initializer?

[Scott Hess - ex-Googler, 2012-09-05 17:17:05]

OK, some cleanup done.

https://chromiumcodereview.appspot.com/10908078/diff/1/chrome/app/chrome_main...
File chrome/app/chrome_main_delegate.cc (right):

https://chromiumcodereview.appspot.com/10908078/diff/1/chrome/app/chrome_main...
chrome/app/chrome_main_delegate.cc:410: msgs->assign(bug_messages.begin(),
bug_messages.end());
On 2012/09/05 15:04:55, Bernhard Bauer wrote:
> Could you just write `*msgs = g_messages.Get()[bug_id];`?

Done.  Sometimes it's harder to see the things which don't look right for C.

https://chromiumcodereview.appspot.com/10908078/diff/1/content/browser/plugin...
File content/browser/plugin_process_host.cc (right):

https://chromiumcodereview.appspot.com/10908078/diff/1/content/browser/plugin...
content/browser/plugin_process_host.cc:468: if
(!content::debug::GetMessages(bug_id, msgs))
On 2012/09/05 15:04:55, Bernhard Bauer wrote:
> Doesn't GetMessages() return false if the out vector is empty? Why do we need
to
> clear it then?

GetMessages() returns false if there is no handler, or if the handler returns
false.  Maybe the way to go is to document the API as false implying *msgs is
empty.

The GetMessages() return value was meant to allow distinguishing between "nobody
provided results" and "results were provided, they were just empty".  The IPC
version encodes that distinction in empty results because I'm lazy.  But now
that it seems to work, maybe I should just go back and layer in an explicit bool
for that, rather than making stuff up.

https://chromiumcodereview.appspot.com/10908078/diff/1/content/common/content...
File content/common/content_debug_logging.cc (right):

https://chromiumcodereview.appspot.com/10908078/diff/1/content/common/content...
content/common/content_debug_logging.cc:15: // thread-safe.crbug.com
On 2012/09/05 15:04:55, Bernhard Bauer wrote:
> Oops! Google Chrome could not find http://thread-safe.crbug.com

I have no idea where this came from!

https://chromiumcodereview.appspot.com/10908078/diff/1/content/common/content...
content/common/content_debug_logging.cc:28: DCHECK(g_record_handler);
On 2012/09/05 15:04:55, Bernhard Bauer wrote:
> Are these the ones you want to replace with DLOG_IF? Then you could just put a
> DLOG inside of the if statement (or turn it around and early-return if
> |g_record_handler| is NULL).

Yeah, pretty much.

Except now I realize that having a DLOG() in here will muddy up test output,
since tests are unlikely to register handlers.  I'll just leave it out entirely,
and for now users (aka me) are on their own to verify that things actually work.

https://chromiumcodereview.appspot.com/10908078/diff/1/content/common/content...
File content/common/content_debug_logging_unittest.cc (right):

https://chromiumcodereview.appspot.com/10908078/diff/1/content/common/content...
content/common/content_debug_logging_unittest.cc:35: static std::map<int,
std::vector<std::string> > messages;
On 2012/09/05 15:04:55, Bernhard Bauer wrote:
> Could you make this a pointer to avoid the static initializer?

Hmm, and then the handler functions can just watch the pointer and be safer. 
OK.

[eroman, 2012-09-05 17:46:43]

This doesn't look too crazy, however what do you think about the alternative
implementations such as:

(a) Attach chrome_debug.log to crash reports. Now investigators would use the
already familiar LOG(ERROR) / LOG(WARNING) calls to log from multiple processes.
The log file would of course be larger than the in-memory ring buffer, but could
filter it before upload if too large.

(b) Use a shared memory section rather than IPCs for getting/setting the
messages. Could probably just allocate a range of memory for each bug, and have
consumer read/write directly into that. The advantage would be not doing extra
IPCs, which might have side-effects on the multi-process interaction being
debugged.

[piman, 2012-09-05 17:59:01]

On Wed, Sep 5, 2012 at 10:46 AM, <eroman@chromium.org> wrote:

> This doesn't look too crazy, however what do you think about the
> alternative
> implementations such as:
>
> (a) Attach chrome_debug.log to crash reports. Now investigators would use
> the
> already familiar LOG(ERROR) / LOG(WARNING) calls to log from multiple
> processes.
> The log file would of course be larger than the in-memory ring buffer, but
> could
> filter it before upload if too large.
>

I was thinking of something along these lines, but with a twist - use LOG()
with a special format or a different macro, that tags a given line to be
included in crash reports (and associated with a bug id). The logging code
would handle that and stash it for consumption by crash reporting.

>
> (b) Use a shared memory section rather than IPCs for getting/setting the
> messages. Could probably just allocate a range of memory for each bug, and
> have
> consumer read/write directly into that. The advantage would be not doing
> extra
> IPCs, which might have side-effects on the multi-process interaction being
> debugged.
>

TBH, I think that may be more work and more complexity than you want.
Managing access to a shared resource from multiple processes some of which
are untrusted is very tricky.

If we keep the IPC route, I think it'd be useful to handle it at the
ChildThread/ChildProcessHost level (similar to e.g. the tracing code), that
way the code would be reusable for all child processes without having to
add messages for each process interaction. WDYT?


>
>
https://chromiumcodereview.**appspot.com/10908078/<https://chromiumcodereview...
>

[Bernhard Bauer, 2012-09-05 18:11:53]

lgtm

[Scott Hess - ex-Googler, 2012-09-05 18:13:00]

One suggestion, before we bikeshed: I'd like to flag discussion as
"Here's something that would be nice to move towards in the longer
term" versus "Here's something that I think should block".

On Wed, Sep 5, 2012 at 10:58 AM, Antoine Labour <piman@chromium.org> wrote:
> On Wed, Sep 5, 2012 at 10:46 AM, <eroman@chromium.org> wrote:
>> This doesn't look too crazy, however what do you think about the
>> alternative
>> implementations such as:
>>
>> (a) Attach chrome_debug.log to crash reports. Now investigators would use
>> the
>> already familiar LOG(ERROR) / LOG(WARNING) calls to log from multiple
>> processes.
>> The log file would of course be larger than the in-memory ring buffer, but
>> could
>> filter it before upload if too large.
>
> I was thinking of something along these lines, but with a twist - use LOG()
> with a special format or a different macro, that tags a given line to be
> included in crash reports (and associated with a bug id). The logging code
> would handle that and stash it for consumption by crash reporting.

My main concern about capturing the existing LOG() infrastructure is
that sometimes people log pretty indiscriminately.  In this code my
goal is to debug a specific bug, and finding that someone else's
useless LOG() vomit was blowing my info out of the window would piss
me off to no end.  We could layer a bunch of special-case tags and
stuff overhead, but I don't think something purpose-built is all that
bad.

Long-term I think it would be nice to collect LOG() output in a ring
buffer of some sort, and attach it as a file to crash reports.  I
think mento is planning something like that for the all-signing
all-dancing OSX breakpad replacement.

>> (b) Use a shared memory section rather than IPCs for getting/setting the
>> messages. Could probably just allocate a range of memory for each bug, and
>> have
>> consumer read/write directly into that. The advantage would be not doing
>> extra
>> IPCs, which might have side-effects on the multi-process interaction being
>> debugged.
>
> TBH, I think that may be more work and more complexity than you want.
> Managing access to a shared resource from multiple processes some of which
> are untrusted is very tricky.

I agree - also, part of the reason I used IPCs is because handling of
IPCs is well understood within Chrome.  There's little chance that
encoding/decoding or synchronization will be a problem, so there's not
much likelihood that this debug code will cause a complete melt-down
such that Chrome no longer works.  While I agree that it could suffer
from heisenbug problems like any other printf-style debugging, I think
that realistically in such cases the browser is dispatching about a
billion IPCs per second, so it's unlikely that simply dispatching
these IPCs will cause additional problems.  It's more likely that
constructing the information to log would cause problems.

> If we keep the IPC route, I think it'd be useful to handle it at the
> ChildThread/ChildProcessHost level (similar to e.g. the tracing code), that
> way the code would be reusable for all child processes without having to add
> messages for each process interaction. WDYT?

Hmm hmm hmm, that seems like a good idea.  It's in the current IPC
flow mainly because it hadn't occurred to me that there was a lower
substrate to put it in, but I see it now.  Is that something to
resolve in the short term, or longer term?

>> https://chromiumcodereview.appspot.com/10908078/

[eroman, 2012-09-05 18:15:32]

@shess: my comments do not block this codereview, was just thinking out loud.
moving to cc list rather than reviewers :)

[Scott Hess - ex-Googler, 2012-09-05 18:32:09]

On 2012/09/05 18:13:00, shess wrote:
> On Wed, Sep 5, 2012 at 10:58 AM, Antoine Labour <mailto:piman@chromium.org>
wrote:
> > If we keep the IPC route, I think it'd be useful to handle it at the
> > ChildThread/ChildProcessHost level (similar to e.g. the tracing code), that
> > way the code would be reusable for all child processes without having to add
> > messages for each process interaction. WDYT?
> 
> Hmm hmm hmm, that seems like a good idea.  It's in the current IPC
> flow mainly because it hadn't occurred to me that there was a lower
> substrate to put it in, but I see it now.  Is that something to
> resolve in the short term, or longer term?

Looking at this more closely, I realize that my forwarding code could
potentially call Send() from an inappropriate thread.  As things stand, I think
it works because all of the callers are already in the child thread for their
process.  The RecordMsg() handler could obviously be written to post a task to
the right thread, but the GetMessages() handler can't, really.  I'm comfortable
with GetMessages() being forward by a sync message, as it's (currently) only
used when already dying in code with lots of sync messages.  *pondering*.

[Scott Hess - ex-Googler, 2012-09-05 19:46:30]

On 2012/09/05 19:05:01, piman wrote:

Was that "This message intentionally left blank"?

[piman, 2012-09-05 20:57:39]

On Wed, Sep 5, 2012 at 12:46 PM, <shess@chromium.org> wrote:

> On 2012/09/05 19:05:01, piman wrote:
>
> Was that "This message intentionally left blank"?
>

It's a "rietveld ate my comments" issue.
All I was saying is bikeshedding on the names. GetMessages and RecordMsg
are super confusing in the classes that deal with IPC - i.e. confusion
between IPC:Message and the logging message. Do you think we can rename
into something like GetCrashReportMessages or something?


>
>
https://chromiumcodereview.**appspot.com/10908078/<https://chromiumcodereview...
>

[Scott Hess - ex-Googler, 2012-09-05 23:37:27]

On 2012/09/05 20:57:39, piman wrote:
> All I was saying is bikeshedding on the names. GetMessages and RecordMsg
> are super confusing in the classes that deal with IPC - i.e. confusion
> between IPC:Message and the logging message. Do you think we can rename
> into something like GetCrashReportMessages or something?

I was thinking the same.  And Rietveld ate my comments.  Which were basically
"Bah, bits are free, I'll just put ContentDebug in there to reflect
content::debug::".  If it works well for debugging, next step can refactor
towards something better in ChildProcessHost.  If it works horribly, next step
can be revert.

In experimenting with ChildProcessHost, I find that RenderProcessHostImpl is not
a subclass of ChildProcessHost.  ChildThread can register handlers and forward
for all sub-processes, but the browser will either need duplicated forwarding
code, or a ContentDebugLoggingFilter for each host.

[piman, 2012-09-05 23:40:42]

lgtm

[commit-bot: I haz the power, 2012-09-06 02:07:02]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/shess@chromium.org/10908078/14010

[Scott Hess - ex-Googler, 2012-09-06 02:09:56]

On 2012/09/06 02:07:02, I haz the power (commit-bot) wrote:
> CQ is trying da patch. Follow status at
> https://chromium-status.appspot.com/cq/shess%40chromium.org/10908078/14010

Man, I hope this makes the canary cut!

[commit-bot: I haz the power, 2012-09-06 04:28:19]

Change committed as 155122

[Scott Hess - ex-Googler, 2012-09-06 20:31:51]

Karen is on me about whether this change could be related to increased renderer
crash rates on Win Canary.  I can't see how.  The bit about forwarding messages
obviously could be related, but since the messages are only sent in code which
is if-def'ed to OSX, that code is never called.  Is it possible I'm not reading
something right?

I'm not seeing anything on the crash server which is helpful at all.

[jam, 2012-09-07 17:10:22]

how long is this change planned on being in the tree for? it wasn't properly
reviewed (see content/public/OWNERS)

[Scott Hess - ex-Googler, 2012-09-07 17:57:56]

On 2012/09/07 17:10:22, John Abd-El-Malek wrote:
> how long is this change planned on being in the tree for? it wasn't properly
> reviewed (see content/public/OWNERS)

It's been reverted.  I'll check out content/public/OWNERS before relanding. 
There is part which I think would be valuable to leave long-term, and part for
the specific bug which would only be short-term (and is unlikely to be what
you'd care about).

[Scott Hess - ex-Googler, 2012-09-07 18:28:23]

John, would you prefer me to re-open this CL, or initiate a new one
refering to this one?

Thanks,
scott


On Fri, Sep 7, 2012 at 10:57 AM,  <shess@chromium.org> wrote:
> On 2012/09/07 17:10:22, John Abd-El-Malek wrote:
>> how long is this change planned on being in the tree for? it wasn't
>> properly
>> reviewed (see content/public/OWNERS)
>
> It's been reverted.  I'll check out content/public/OWNERS before relanding.
> There is part which I think would be valuable to leave long-term, and part
> for
> the specific bug which would only be short-term (and is unlikely to be what
> you'd care about).
>
> https://chromiumcodereview.appspot.com/10908078/

[jam, 2012-09-07 18:28:53]

up to you

On Fri, Sep 7, 2012 at 11:28 AM, Scott Hess <shess@chromium.org> wrote:

> John, would you prefer me to re-open this CL, or initiate a new one
> refering to this one?
>
> Thanks,
> scott
>
>
> On Fri, Sep 7, 2012 at 10:57 AM,  <shess@chromium.org> wrote:
> > On 2012/09/07 17:10:22, John Abd-El-Malek wrote:
> >> how long is this change planned on being in the tree for? it wasn't
> >> properly
> >> reviewed (see content/public/OWNERS)
> >
> > It's been reverted.  I'll check out content/public/OWNERS before
> relanding.
> > There is part which I think would be valuable to leave long-term, and
> part
> > for
> > the specific bug which would only be short-term (and is unlikely to be
> what
> > you'd care about).
> >
> > https://chromiumcodereview.appspot.com/10908078/
>

[Scott Hess - ex-Googler, 2012-09-07 21:29:05]

John,

This is a bit like TRACE_* or LOG(), with the intent being to allow processes to
record messages against an id which can later be posted along with crashdumps
(or in the error output, whatever).  Normally, this could be done more directly
using breakpad keys or something, but that doesn't work for cross-process
interactions.  The interface in content/public/common provides the ability to
register handlers for these messages (which embedders would need to do to
facilitate it), plus the interface for recording messages.

The reason I added public/common/content_debug_logging.h was because
chrome/app/chrome_main_delegate.cc registers to be the root capture for this.  I
actually think it wouldn't be terrible to move it into base/, eventually, but
for now I only need to debug stuff in content/, and all of the cross-process
messaging has to be in content/ already, so I'd rather prove it out before
pushing it to base/.

My main concern is to make progress on the linked bugs in the short term.  But
if I had had something like this before, I think I'd have made better progress
on the bugs a long time ago, so I do think this (or something like it) would be
a reasonable cross-platform addition.

[BTW - I see that the header has an incorrect include guard.]

Thanks,
scott

[eroman, 2013-06-04 20:50:26]

Can this issue be closed? (shows up in my incoming queue)