533055 - IPDL: Add an RPCChannel::DumpStack() method to help with debugging

Status: RESOLVED FIXED

(Core :: IPC, enhancement)

Description

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

Apparently the MSVC debugger isn't able to navigate up the stack through plugins compiled in a certain way (~= -fomit-frame-pointer?).  This makes debugging RPC errors harder, because although the RPC stack was designed to directly map to the C++ stack, that's of no use when much of the C++ stack is chomped.

This should be moderately easy.  The best solution would be adding a virtual |PrintDebugInfo()| method to Message, but we can't do that without changing a lot of code that has direct references to Message's.  So I think an acceptable intermediate solution is to add a |const char* const debug_desc_| field to Message that's set by IPDL-generated code to the literal name of the message, like "CallFooCtor".  This should be cheap enough to leave on in opt builds.  Then RPCChannel just needs to keep around enough breadcrumbs to allow it to print both in-calls and out-calls (currently it only tracks out-calls).  It would probably be nice to print deferred messages in the stack as well.  Something like

  ---------
  [2] in async PStream::Notify(actorID=3)
  ---------
  [1] out rpc PScriptableObject::GetProperty(actorId=-2)
  ---------
  [0] in rpc PScriptableObject::Invoke(actorId=-2)
      (deferred out rpc PScriptableObject::SetProperty(actorId=4))
  ---------

ought to do the trick.  We could log more information in debug builds.

Comment 1

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

I implemented the following interface and output format

(gdb) p this->mChannel.DumpRPCStack(stdout, "")
RPCChannel 'backtrace':
[(0) in rpc PTestSyncWakeup::Msg_StackFrame(actor=2147483647) ]
[(1) out rpc PTestSyncWakeup::Msg_StackFrame(actor=2147483647) ]
[(2) in sync PTestSyncWakeup::Msg_Sync2(actor=2147483647) ]
$1 = void
(gdb) pvector this->mChannel.mCxxStackFrames
elem[0]: $3 = {
  mDirection = mozilla::ipc::RPCChannel::IN_MESSAGE, 
  mMsg = 0x7fffffffe260
}
elem[1]: $4 = {
  mDirection = mozilla::ipc::RPCChannel::OUT_MESSAGE, 
  mMsg = 0x7fffe0002900
}
elem[2]: $5 = {
  mDirection = mozilla::ipc::RPCChannel::IN_MESSAGE, 
  mMsg = 0x7fffffffdf00
}
Vector size = 3
Vector capacity = 4
Element type = mozilla::ipc::RPCChannel::RPCFrame *
(gdb) p this->mChannel.DebugAbort("", 0, "", "test", "test", false)
###!!! [RPCChannel][Parent][:0] Assertion () failed.  test (triggered by test)
  RPCChannel 'backtrace':
  [(0) in rpc PTestSyncWakeup::Msg_StackFrame(actor=2147483647) ]
  [(1) out sync PTestSyncWakeup::Msg_StackFrame(actor=2147483647) ]
  [(2) in sync PTestSyncWakeup::Msg_Sync2(actor=2147483647) ]
  remote RPC stack guess: 1
  deferred stack size: 0
  out-of-turn RPC replies stack size: 0
  Pending queue size: 0, front to back:

(The "actor=2147483647" stuff just means "toplevel".)

Comment 2

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

Attachment: Part 1: Add a "name" field to IPC::Message

Comment 3

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

Attachment: Part 2: Set Message names in IPDL-generated code

Comment 4

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

Attachment: Part 3: Track |Message|s being processed on the C++ stack and offer a DumpRPCStack() method to print them

I went ahead and left this code on in debug and opt.  It should be quite cheap, and is easy enough to disable anyway.

Comment 5

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Comment on attachment 429945 [details] [diff] [review]
Part 3: Track |Message|s being processed on the C++ stack and offer a DumpRPCStack() method to print them

>+    mCxxStackFrames()

You can just remove that can't you?

>+RPCChannel::DumpRPCStack(FILE* outfile, const char* const pfx)
>+{
>+    fprintf(outfile, "%sRPCChannel 'backtrace':\n", pfx);

It's kinda tough to tell msvc to use stdout manually when you break in the debugger. You've currently got the default set to stdout in the header, but I don't think that helps. Let's make the default be null and then set to stdout within the function.

Also, calling this off the worker thread could be trouble... Maybe warn or something?

>+        void Describe(int32* id,
>+                      const char** dir, const char** sems, const char** name)

Nit: Weird wrapping?

>+        CxxStackFrame(RPCChannel& that,
>+                      Direction direction, const Message* msg) : mThat(that) {

And again.

Comment 6

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

Attachment: Part 3: Track |Message|s being processed on the C++ stack and offer a DumpRPCStack() method to print them, v2

Updated per comments, and fixed the use-after-free bug that was leading to corrupted "RPC stack frames".  Just looking for an interdiff re-affirmation r?.

Comment 7

[Chris Jones [:cjones] inactive; ni?/f?/r? if you need me]

http://hg.mozilla.org/mozilla-central/rev/6f14a461968d
http://hg.mozilla.org/mozilla-central/rev/2cdf465ee181
http://hg.mozilla.org/mozilla-central/rev/5e378936ee76

Comment 8

[Benjamin Smedberg]

http://hg.mozilla.org/projects/firefox-lorentz/rev/c698189d82e0
http://hg.mozilla.org/projects/firefox-lorentz/rev/1982ec4753cc
http://hg.mozilla.org/projects/firefox-lorentz/rev/bb9a5a68b11a

Comment 9

[Mike Beltzner [:beltzner, not reading bugmail]]

Blanket approval for Lorentz merge to mozilla-1.9.2
a=beltzner for 1.9.2.4 - please make sure to mark status1.9.2:.4-fixed

Comment 10

[Benjamin Smedberg]

Merged into 1.9.2 at http://hg.mozilla.org/releases/mozilla-1.9.2/rev/84ba4d805430